2022-02-08 Updated: 2022-02-08

DjangoでRailsのようなログ出力設定をする

背景

Djangoでviewを実装し、ぽちぽち動かしているときに、どんなクエリが実行されているかを確認できるとうれしいと思いました。
Railsだとデフォルトでそのようになっているのですが、Djangoは設定が必要だったので設定してみました。

設定

設定内容は以下になります

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

設定内容を詳しくみていきます

設定の詳細

まず公式ドキュメントを確認します
ロギング | Django ドキュメント | Django
公式ドキュメントの内容に沿って確認していきます

LOGGING

公式ドキュメントには

n order to configure logging, you use LOGGING to define a dictionary of logging settings. These settings describe the loggers, handlers, filters and formatters that you want in your logging setup, and the log levels and other properties that you want those components to have.

と記載されており、LOGGINGというdictionaryの定数を定義することでロギングの設定ができることがわかります。

LOGGING内の要素

version

versionについて、公式ドキュメントには記載がありませんが、例に記載されているように記述しておきます。
試しにversionを削除したところ、

1
2
3

web_1  |   File "/usr/local/lib/python3.10/logging/config.py", line 498, in configure
web_1  |     raise ValueError("dictionary doesn't specify a version")
web_1  | ValueError: dictionary doesn't specify a version

というエラーが出てしまいました。なので、記述しておきます。

disable_existing_loggers

disable_existing_loggersについて、公式ドキュメントには以下のように記載されています。

LOGGING の disable_existing_loggers キーの値を True にすると、全てのデフォルトの設定が無効になります（キーが存在しない場合は dictConfig のデフォルトになります）。このため、 ’disable_existing_loggers’: True を使う場合は注意してください。 True を設定する必要は殆どないでしょう。 disable_existing_loggers を False に設定して、デフォルトのロガーの一部、または全てを定義しなおすこともできます。あるいは、 LOGGING_CONFIG を None に設定して、ロギングの設定を自分で行うことも出来ます。

基本的にはFalseで良さそうですね。

handlers

[公式ドキュメント](ロギング | Django ドキュメント | Django)に記載があります。

Handlerはloggerから指定されます。今回の例で言うと、console
という名のハンドラを定義し、ログレベルと、ログを処理するハンドラクラスを指定します。

上記で指定しているlogging.StreamHandlerについてはPythonの公式ドキュメントに記載がありました
logging.handlers — ロギングハンドラ — Python 3.10.0b2 ドキュメント

StreamHandler クラスの新たなインスタンスを返します。 stream が指定された場合、インスタンスはログ出力先として指定されたストリームを使います; そうでない場合、 sys.stderr が使われます。

docker-compose upで動作させている時は、実行しているコンソールが標準出力なので、そのコンソールにログが出力されると言うことですね

loggers

[公式ドキュメント](ロギング | Django ドキュメント | Django)に記載があります

キー（今回でいうところのdjango.db.backends）は、パッケージのパスを指定します。そのパッケージ内で出力されたログは、ロガーで指定したログレベルと比較して同等以上の場合にロガーを通じてハンドラに渡されます。

以上で設定はすべて見終わりました。

詳細なログ設定

公式ドキュメントにあった詳細なログ設定も記載しておきます。パッケージごとに細分化されています。

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'verbose': {
            'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}',
            'style': '{',
        },
        'simple': {
            'format': '{levelname} {message}',
            'style': '{',
        },
    },
    'filters': {
        'special': {
            '()': 'project.logging.SpecialFilter',
            'foo': 'bar',
        },
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'filters': ['require_debug_true'],
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
            'filters': ['special']
        }
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'propagate': True,
        },
        'django.request': {
            'handlers': ['mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'myproject.custom': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
            'filters': ['special']
        }
    }
}

フォーマッタは見やすくするために利用することもあるかもしれません。

動作確認

設定前と設定後でどのようにコンソールの出力が変わったか見てみます。

設定前

web_1  | Starting development server at http://0.0.0.0:8000/
web_1  | Quit the server with CONTROL-C.
web_1  | [08/Feb/2022 11:36:59] "GET /accounts/login/?next=/ HTTP/1.1" 200 1892
web_1  | [08/Feb/2022 11:37:05] "POST /accounts/login/?next=/ HTTP/1.1" 302 0
web_1  | [08/Feb/2022 11:37:05] "GET / HTTP/1.1" 200 1176

設定後

web_1  | Starting development server at http://0.0.0.0:8000/
web_1  | Quit the server with CONTROL-C.
web_1  | [08/Feb/2022 11:39:16] "GET /accounts/login/ HTTP/1.1" 200 1892
web_1  | (0.001)
web_1  |                 SELECT VERSION(),
web_1  |                        @@sql_mode,
web_1  |                        @@default_storage_engine,
web_1  |                        @@sql_auto_is_null,
web_1  |                        @@lower_case_table_names,
web_1  |                        CONVERT_TZ('2001-01-01 01:00:00', 'UTC', 'UTC') IS NOT NULL
web_1  |             ; args=None; alias=default
web_1  | (0.000) SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED; args=None; alias=default
web_1  | (0.001) SELECT `auth_user`.`id`, `auth_user`.`password`, `auth_user`.`last_login`, `auth_user`.`is_superuser`, `auth_user`.`username`, `auth_user`.`first_name`, `auth_user`.`last_name`, `auth_user`.`email`, `auth_user`.`is_staff`, `auth_user`.`is_active`, `auth_user`.`date_joined` FROM `auth_user` WHERE `auth_user`.`email` = 'test@example.com' LIMIT 21; args=('test@example.com',); alias=default
web_1  | (0.001) SELECT (1) AS `a` FROM `django_session` WHERE `django_session`.`session_key` = 'xxxxxxxxxxxxxxxxxxxxxxx' LIMIT 1; args=('xxxxxxxxxxxxxxxxxxxxxxx',); alias=default
web_1  | (0.000) INSERT INTO `django_session` (`session_key`, `session_data`, `expire_date`) VALUES ('xxxxxxxxxxxxxxxxxxxxxxx', 'yyyyyyyyyyyyyyyyyyyy', '2022-02-22 02:39:29.502823'); args=('xxxxxxxxxxxxxxxxxxxxxxx', 'yyyyyyyyyyyyyyyyyyyy', '2022-02-22 02:39:29.502823'); alias=default
web_1  | (0.004) UPDATE `auth_user` SET `last_login` = '2022-02-08 02:39:29.509067' WHERE `auth_user`.`id` = 1; args=('2022-02-08 02:39:29.509067', 1); alias=default
web_1  | (0.001) UPDATE `django_session` SET `session_data` = 'zzzzzzzzzzzzzzzzzzzzzzzz', `expire_date` = '2022-02-22 02:39:29.515114' WHERE `django_session`.`session_key` = 'xxxxxxxxxxxxxxxxxxxxxxx'; args=('zzzzzzzzzzzzzzzzzzzzzzzz', '2022-02-22 02:39:29.515114', 'xxxxxxxxxxxxxxxxxxxxxxx'); alias=default
web_1  | [08/Feb/2022 11:39:29] "POST /accounts/login/ HTTP/1.1" 302 0
web_1  | (0.001) SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED; args=None; alias=default
web_1  | (0.001) SELECT `django_session`.`session_key`, `django_session`.`session_data`, `django_session`.`expire_date` FROM `django_session` WHERE (`django_session`.`expire_date` > '2022-02-08 02:39:29.536012' AND `django_session`.`session_key` = 'xxxxxxxxxxxxxxxxxxxxxxx') LIMIT 21; args=('2022-02-08 02:39:29.536012', 'xxxxxxxxxxxxxxxxxxxxxxx'); alias=default
web_1  | (0.001) SELECT `auth_user`.`id`, `auth_user`.`password`, `auth_user`.`last_login`, `auth_user`.`is_superuser`, `auth_user`.`username`, `auth_user`.`first_name`, `auth_user`.`last_name`, `auth_user`.`email`, `auth_user`.`is_staff`, `auth_user`.`is_active`, `auth_user`.`date_joined` FROM `auth_user` WHERE `auth_user`.`id` = 1 LIMIT 21; args=(1,); alias=default
web_1  | [08/Feb/2022 11:39:29] "GET / HTTP/1.1" 200 1176

実行されているSQLがログに表示されるようになりました！

ログの種類によって色をわける

どうしてもRailsをベースに考えてしまい、ログの種類によって色が変わるのがいいと思って調べてみると、colorlogというパッケージが見つかりました。

Poetryでインストール後、LOGGINGを以下のように書き換えます。

LOGGING = {
  'version': 1,
  'disable_existing_loggers': False,
  'formatters': {
    'color': {
      '()': 'colorlog.ColoredFormatter',
      'format': '%(log_color)s%(levelname)-8s %(message)s',
      'log_colors': {
        'DEBUG':    'bold_black',
        'INFO':     'white',
        'WARNING':  'yellow',
        'ERROR':    'red',
        'CRITICAL': 'bold_red',
      },
    },
  },
  'handlers': {
    'console': {
      'level': 'DEBUG',
      'class': 'logging.StreamHandler',
      'formatter': 'color',
    }
  },
  'loggers': {
    'django.db.backends': {
      'level': 'DEBUG',
      'handlers': ['console'],
    },
  }
}

formattersで指定したlog_colorsは例に載っていたものをそのまま利用しました。ここをお好みで調整すると色が変わります。

まとめ

開発デバッグ作業を効率よく行うには情報を増やすことが必要です。LOGGINGの設定であれば、一度行ってしまえばそのままずっと使えるのでしっかりと理解して設定するのがよいと思いました。

参考図書

実践Django