loggingとは(django-structlog)

どうも、おのでらです。
今回の記事は
「loggingとは？」
「djangoでlogを出力する方法」
についてです。

自分が案件でloggingの実装を始めたときの過去の自分への備忘録としてまとめました。
この記事を読んで貰えれば
loggingについて、だいたいのイメージができると思います。

1. そもそもログはなんで必要？

ログを記録する理由は
不具合の修正を迅速に行うためです。

次のようなログが記録されたとします。

timestamp='2019-04-13T19:39:31.089925Z' level='info' event='an_error_occurred' logger='my_awesome_project.my_awesome_module' request_id='3a8f801c-072b-4805-8f38-e1337f363ed4' user_id=1 ip='0.0.0.0' bar='Buz' 

このlogからは
・エラーが起きた時間
・エラーの内容
・エラーが起きた場所
・エラーを起こしたユーザー
の情報を取得できます。

もしも、logなしで不具合を調査が出た場合、
調査だけで莫大な時間がかかってしまいます。

2. django-structlogとは

djangoでログをとるには
python標準のloggerがあります。

対して、django-structlogはdjangoに特化したloggerです。
django-structlogは、簡単な設定で多くのログ情報を出力してくれます。

loggerとdjango-structlog2つのログ出力を比較しましょう。

loggerの場合

入力

import logging
logger = logging.get_logger(__name__)
logger.info("An error occurred")

出力

An error occurred

django-structlogの場合

入力

>>> import structlog
>>> logger = structlog.get_logger(__name__)
>>> logger.info("an_error_occurred", bar="Buz")

出力

timestamp='2019-04-13T19:39:31.089925Z' level='info' event='an_error_occurred' logger='my_awesome_project.my_awesome_module' request_id='3a8f801c-072b-4805-8f38-e1337f363ed4' user_id=1 ip='0.0.0.0' bar='Buz'

django-structlogがデフォルトで
多くの情報を出力してくれることがわかりました。

3. LogLevelについて

Logにはそれぞれ重要度を表すLogLevelがあります。

・CRITICAL
・ERROR
・WARNING
・INFO
・DEBUG
などがLogLevelになります。
上に行くにつれ重要度が高いです。

500などのサーバーエラー→CRITICAL、
40~系のクライアントエラー→ERROR
などの使い分けができます。

4. 導入方法

https://django-structlog.readthedocs.io/en/latest/getting_started.html
公式ドキュメントより

まずはstructlogのインストール。

pip install django-structlog

次にsettings.pyのMIDDLEWAREの欄に下のように追加します。

MIDDLEWARE = [
    # ...
    'django_structlog.middlewares.RequestMiddleware',
]

そして次はstructlogの設定です。settings.pyから

import structlog

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "json_formatter": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.JSONRenderer(),
        },
        "plain_console": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.dev.ConsoleRenderer(),
        },
        "key_value": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.KeyValueRenderer(key_order=['timestamp', 'level', 'event', 'logger']),
        },
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "plain_console",
        },
        "json_file": {
            "class": "logging.handlers.WatchedFileHandler",
            "filename": "logs/json.log",
            "formatter": "json_formatter",
        },
        "flat_line_file": {
            "class": "logging.handlers.WatchedFileHandler",
            "filename": "logs/flat_line.log",
            "formatter": "key_value",
        },
    },
    "loggers": {
        "django_structlog": {
            "handlers": ["console", "flat_line_file", "json_file"],
            "level": "INFO",
        },
        # Make sure to replace the following logger's name for yours
        "django_structlog_demo_project": {
            "handlers": ["console", "flat_line_file", "json_file"],
            "level": "INFO",
        },
    }
}

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        structlog.stdlib.filter_by_level,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeDecoder(),
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
    cache_logger_on_first_use=True,
)

import structlog
logger = structlog.get_logger(__name__)

これでログが出力されます。

※公式ドキュメントの設定では
タイムスタンプの時刻が協定世界時のUTCなっています。

変更方法は

structlog.processors.TimeStamper(fmt="iso")

から

structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S", utc=False)

に変更することで日本標準時間に変更できます。

5. Loggingの定数について

Loggingの定数で重要なものは
・formatter
・handler
・logger
になります。

formatter

formatterはどんな情報をログ出力するかを決定します。

"formatters": {
        "json_formatter": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.JSONRenderer(),
        },
        "plain_console": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.dev.ConsoleRenderer(),
        },
        "key_value": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.KeyValueRenderer(key_order=['timestamp', 'level', 'event', 'logger']),
        },
    },

handlers

ログの出力先を設定します。（標準出力、ファイル、メール等）

"handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "plain_console",
        },
        "json_file": {
            "class": "logging.handlers.WatchedFileHandler",
            "filename": "logs/json.log",
            "formatter": "json_formatter",
        },
        "flat_line_file": {
            "class": "logging.handlers.WatchedFileHandler",
            "filename": "logs/flat_line.log",
            "formatter": "key_value",
        },
    },

・class
ログ出力に使用するクラスです。ファイルに出力するクラスを指定します。
例えば、'logging.StreamHandler'を指定するとコンソールにログが出力されます。
・filename
ログ出力するファイルのパスとファイル名を指定できます。
・formatter
定義したformatterのうちどれを使用するかを指定します。

※SMTPHandllerを用いてログをメール送信することもできるらしいです。
www.nullpo.io/2018/11/12/python-logging-mail/

logger

実際にdjangoアプリ内で使用するstructlogの設定になります。

"loggers": {
        "django_structlog": {
            "handlers": ["console", "flat_line_file", "json_file"],
            "level": "INFO",
        },
        "django_structlog_demo_project": {
            "handlers": ["console", "flat_line_file", "json_file"],
            "level": "INFO",
        },

・handlers
先に定義したhandlersのどれを使用するか指定します。
・level
設定したログレベル以下のログは出力されなくなります。