DjangoでLOGGING設定をしているときに、IPythonの補完に不具合が出る場合の対処

Djangoに限ったことではないのですが、PythonのloggingでrootのハンドラをDEBUGにしていると、IPythonの補完を実行した際にparsoという依存ライブラリのログが出てしまい、カーソル位置がずれてしまうことあります。

例えば、Djangoで以下のように settings.py でロギングの設定をした場合。

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
        },
    },
    'root': {
        'handlers': ['console'],
        'level': 'DEBUG',
    }
}

Djangoの manage.py shell では、IPythonがインストールされていると、IPythonが起動します。この設定で補完機能を使おうとTabキーを押したとき、次のようにログが出力されてカーソル位置がずれます。

IPythonの補完時にログが出力される

parsoというモジュール(ipython → jedi → parsoの依存)がデバッグログを出力するのですが、これでは補完がまともに使えなくなってしまいます。

parsoのログをINFOレベルに設定することで、回避できます。(もしくは disable_existing_loggers やrootロガーの設定変更で回避することもできます)

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        'parso': {
            'handlers': ['console'],
            'level': 'INFO',
            'propagate': False,
        },
    },
    'root': {
        'handlers': ['console'],
        'level': 'DEBUG',
    }
}

参考

• Unexpected logging outputs after setting log level to debug. · Issue #10946 · ipython/ipython · GitHub

オープンソースカンファレンス2019 HokkaidoでDjangoの紹介をしました

6/1に札幌で開催された オープンソースカンファレンス2019 Hokkaido で、django-ja名義でDjangoフレームワークの紹介をしてきました。

資料はSpeakerDeckにアップロードしています。

Djangoフレームワークの紹介_OSC北海道2019 - Speaker Deck

日本のDjangoユーザーのコミュニティである django-ja では、Djangoフレームワークに関する雑談や、DjangoCongressJPの開催、Djangoフレームワークのドキュメントやリソースの翻訳を行っています。

Home | djangoproject.jp

DjangoのSubqueryとOuterRefを使ってサブクエリを組み立てる

DjangoのORMで、サブクエリを使う方法について。任意のSQLであればrawメソッドを使えばよいのですが、なるべくORMのAPIを使いたい。

DjangoのORMでは任意の位置にサブクエリを使えるわけではないですが、例えば「テーブル単位での問い合わせ結果にサブクエリで得た列を追加する」ぐらいのことは、annotateメソッドを使ってできます。

サブクエリ側で条件を指定した絞り込みを行う場合、SubqueryとOuterRefを組み合わせるとできます。

Query Expressions | Django documentation | Django

モデル

Categoryモデルを親に持つ、Itemモデル、という関係性のデータです。

from django.db import models
from django.utils import timezone


class Category(models.Model):
    parent = models.ForeignKey(
        'myapp.Category', null=True, blank=True,
        on_delete=models.CASCADE)
    name = models.CharField(max_length=20)

    class Meta:
        db_table = 'category'
        ordering = ['id']

    def __str__(self):
        return self.name


class Item(models.Model):
    category = models.ForeignKey(
        'myapp.Category', null=True, blank=True,
        on_delete=models.SET_NULL)
    name = models.CharField(max_length=20)
    updated = models.DateTimeField(default=timezone.now)

    class Meta:
        db_table = 'item'
        ordering = ['id']

    def __str__(self):
        return self.name

Djangoのシェルで試したコード

CountなどのAggregate Expressionでうまくクエリを作れない場合、Subqueryを継承すると、自由にクエリを作れます。

サブクエリの結果をCountするCountQueryクラスを定義して使ってます。

from datetime import timedelta
from django.utils import timezone
from django.db.models import OuterRef, Subquery, IntegerField
import sqlparse
from myapp.models import Category, Item

class CountQuery(Subquery):
    """件数をカウントするサブクエリ
    """
    template = "(SELECT COUNT(*) FROM (%(subquery)s) _count)"
    output_field = IntegerField()

categories = Category.objects.annotate(
    updated_count=CountQuery(
        Item.objects.filter(
            category_id=OuterRef('pk'),
            updated__gt=timezone.now() - timedelta(days=1)  # 24時間以内に更新されたItemの件数を取得
        )
    )
)

print(sqlparse.format(str(categories.query), reindent=True))  # sqlparseでSQL文を整形

組み立てたSQLは、sqlparseで整形して表示してみてます。

SELECT "category"."id",
       "category"."parent_id",
       "category"."name",

  (SELECT COUNT(*)
   FROM
     (SELECT U0."id",
             U0."category_id",
             U0."name",
             U0."updated"
      FROM "item" U0
      WHERE (U0."category_id" = ("category"."id")
             AND U0."updated" > 2019-03-19 08:22:03.638946)
      ORDER BY U0."id" ASC) _count) AS "updated_count"
FROM "category"
ORDER BY "category"."id" ASC

理想はもう1段減らしたいのだけど、きれいに作る方法を見つけれてないです...

参考

Django 1.11 Annotating a Subquery Aggregate - Stack Overflow

Djangoのマイグレーションでスキーマ変更とデータ変更を分けたほうがよいか

Djangoのマイグレーションは、1つのマイグレーションで複数のタスクを実行できます。

スキーマを変更する処理のあとに、データのマイグレーションを実行、といったようなものです。

意味のある変更をまとめるのは便利そうに思えるのですが、落とし穴があったりします。

例を挙げてみます。

コード

myapp/models.py (モデル)

from django.db import models


class Item(models.Model):
    col1 = models.CharField(max_length=30)
    col2 = models.CharField(max_length=30, blank=True, null=True)  # このカラムを追加するマイグレーション

myapp/migrations/0002_item_col2.py (マイグレーションコード)

from django.db import migrations, models


def migrate_data(apps, schema_editor):
    Item = apps.get_model('myapp', 'Item')
    db_alias = schema_editor.connection.alias
    Item.objects.all().update(col2=models.F('col1'))
    raise Exception("ここでエラー発生")


class Migration(migrations.Migration):

    dependencies = [
        ('myapp', '0001_initial'),
    ]

    operations = [
        migrations.AddField(
            model_name='item',
            name='col2',
            field=models.CharField(blank=True, max_length=30, null=True),
        ),
        migrations.RunPython(
            migrate_data,
            migrations.RunPython.noop
        )
    ]

実行例

このコードは意図的にマイグレーション中に例外を発生させていますが、実際にはマイグレーションコードが何らかの例外を発生させて落ちる状況を考えてください。

1回目の実行では、想定通りExceptionが発生して停止します。

Exception: ここでエラー発生

2回目の実行では、データベースにSQLite3を使っている場合は、1回目同様、Exceptionで落ちますが、MySQLを使っている場合はスキーマ変更のほうでエラーになります。

django.db.utils.OperationalError: (1060, "Duplicate column name 'col2'")

これは、SQLite3やPostgreSQLはスキーマ変更もトランザクション内で実行し、ロールバックできるので、何度実行しても同じになりますが、MySQLやOracleはスキーマ変更はトランザクションの対象外だからです。

MySQLの場合はスキーマ変更をして、データ更新に失敗した場合、スキーマ変更はロールバックされません。

この例だとカラムが残ったままま、マイグレーション失敗、という扱いになります。リカバリには手動でカラムを削除してやりなおす必要があります。

結論

スキーマ変更とデータ変更のマイグレーションは、同じクラスにまとめずに分けておいたほうが、失敗時のリカバリが楽です。

参考

• Migration Operations | Django documentation | Django
• Transactional DDL in PostgreSQL: A Competitive Analysis - PostgreSQL wiki

GoogleAppEngine上で動作しているDjangoアプリをStackdriver Debuggerでデバッグする

AppEngineで動かしてるDjangoアプリをStackdriver Debuggerでデバッグする手順について。

Python 用 Stackdriver Debugger の設定  |  Stackdriver Debugger のドキュメント  |  Google Cloud

ドキュメントには、Django 1.Xの話しかなく、手順も良くなかったのでメモを残します(フィードバックはしておきました)。

Python 3.7、Django 2.1.4、AppEngineはStandard、Flexible両方で試しました。

requirements.txtへの追記

インストールするライブラリは、ドキュメント通り google-python-cloud-debugger で大丈夫でした。

requirements.txt に google-python-cloud-debugger をインストールするように追記しておきます。

google-python-cloud-debugger

Djangoの設定

DjangoアプリをAppEngineで動かす場合、エントリポイントは wsgi.py になります(gunicorn等でwsgi.pyを読み込ませてる場合)。

mysite という名前でプロジェクトを作った場合、 mysite/wsgi.py にStackdriver Debuggerを有効にするコードを追記します。

import os
from django.core.wsgi import get_wsgi_application

os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'mysite.settings')
application = get_wsgi_application()
# Enable Stackdriver Debugger(以下が追記部分)
try:
    import googleclouddebugger
    googleclouddebugger.enable()
except ImportError:
    pass

デバッグしてみる

変更したものをAppEngineにデプロイ後、GCPのコンソールからStackdriverデバッグの画面を開いてみます。

ソースコードが表示されない場合は、デプロイ時のコマンドを gcloud beta app deploy (betaコマンド)にしてみると改善するかもしれません。

ソースコードが表示されたら、デバッグしたい行にスナップショットのポイントや条件、式を指定し、実際にブラウザでアプリケーションを操作します。

指定したスナップショットのポイントを通過すると、デバッグの画面で、変数やコールスタックなどを確認できます。

本番環境を気軽にデバッグできるので便利ですね。

GoogleAppEngine上でDjangoフレームワークのログをStackdriver Loggingに流す

PythonのloggingモジュールからStackdriverにログを流す手順はドキュメントに書かれている。

Setting Up Stackdriver Logging for Python  |  Stackdriver Logging  |  Google Cloud

Djangoフレームワークを使っている場合は、Djangoのロギング設定を考慮する必要がある。

ちゃんと設定しておくと、logging.infoやlogging.errorで出力したレベルの情報をStackdriver上でも付与された状態でログを見れる。

Python 3.7、Django 2.1.4、google-cloud-logging 1.9.1で試した。

Djangoの設定

あらかじめ、対象のプロジェクトでStackdriver LoggingのAPIを有効にしておく。

また、クライアントライブラリ( google-cloud-logging ) をインストールしておく。

Djangoの settings.py に追記する想定。

from google.cloud import logging as google_cloud_logging

log_client = google_cloud_logging.Client()

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'stackdriver_logging': {
            'class': 'google.cloud.logging.handlers.AppEngineHandler',
            'client': log_client,
        },
    },
    'loggers': {
        'django': {
            'handlers': ['stackdriver_logging'],
            'level': 'INFO',
            'propagate': True,
        },
        'django.request': {
            'handlers': ['stackdriver_logging'],
            'level': 'ERROR',
        },
    },
    'root': {
        'handlers': ['stackdriver_logging'],
        'level': 'INFO',
    }
}

• AppEngineのデフォルトのサービスアカウントで書き込みは可能なので認証の設定は不要
• ドキュメントにある setup_logging() は、呼ばないでおく(Django側でロギングのセットアップが走るので不要)
• rootロガーの設定は好み
• AppEngineを使っている場合のハンドラは、 google.cloud.logging.handlers.AppEngineHandler を使っておくとFlexible/Standardどちらでも都合が良いらしい
• gunicornのログも流そうとすると、いろいろややこしいのでDjangoのみにしてある

参考

• Writing log entries — google-cloud cf545e7 documentation
• Setting up StackDriver logging for Django on GCP – Google Cloud Platform - Community – Medium
• google-cloud-logging · PyPI

今年の振り返りとか

これは pyspa Advent Calendar 2018 の4日目の記事です。

https://adventar.org/calendars/3018

毎年のことですが振り返りです。

畑

今年は気温が高かったせいか、夏野菜の苗は11月終わりぐらいまで枯れてなかった。すごい。

• ほうれん草
  • 春手前の気温が上がりきる前に種を蒔いて育てたらうまく行った。

• ミニ大根
  • これもほうれん草と同時期で栽培、気温が上がると花が咲いたり虫に食われまくったが、最初に収穫したものはいい感じ

• ナス
  • 種まきの時期を逃していたので、苗から。植えて放置でも大丈夫だった。
• ピーマン
  • 同じく種まきの時期を逃していたので、苗から。植えて放置でも大丈夫だった。
• きゅうり
  • 世話できなかったので今年の収穫は少なめ。
• パクチー
  • ベランダの鉢植えは日当たり足りなくて全然だめでしたが、畑に地植えしたものは大きく育ちました。

• バジル
  • 畑に地植えしたら元気になった、のはいいのだけど、葉に土が付きやすいのがイマイチ。マルチで砂や土が舞うのを軽減させたほうがいいかもしれない。
• スイカ
  • 去年食べたカットフルーツに入ってたスイカの種から。品種不明だけど、植えたら育って20cmクラスの実を収穫できた。

• さつまいも
  • いつもどおり苗から。忙しくて放置してたけど、しっかり育ってた。

仕事

去年の末ごろから手伝っている案件をずっとやっています。

お手伝い先では、やれることを引き受けてやっていますが、範囲が広くなってきました。

• アーキテクチャを決めること
  • システム全体をどう作っていくか、どう連携させるかとか考えて決める役割
• プロダクトに実装する機能と中長期的な開発スケジュール決め
  • 機能追加、画面追加とかで、どういうものを実装するのか大雑把に決める役割
    • 細かいところは実装者に概ね任せてしまっている(そこまでやるほど時間がない)
  • 方針を決めたり、指示を出したり。
  • チーム全体で何をいつごろ実装するか決める(このあたり任されてる)
• チームのタスク管理
  • 開発リーダー兼マネージャーという感じだったので、チームメンバーのレベルを見つつタスクを振ったり
  • 最近マネージャーやれる優秀な若者がチームに参加して、細かなタスク割当てはその人に委譲した。それまでは大変だった。
• コードレビュー
  • コードの品質が均一化するように。
  • あんまり細かい指摘はしない。
• 技術的な課題解決
  • 他のチームメンバーがつまづいている課題を助けたり、難易度の高い部分をやっています
• 採用
  • チームに参加する技術者の採用面接をやっている
• パートナー企業との打ち合わせ
  • 技術面での責任者として参加
• 雑多なヘルプ
  • 別部署向けにWordPressをインストールしたり、壊れたWordPressの環境を直したり
  • 壊れたECサイトを直したり

雇われCTOみたいな感じです。

来年はどうなってるかな。