ロギング

クイックロギング入門

Djangoはロギングのために、Pythonビルトインの logging モジュールを使用しています。このモジュールの使い方はPythonのドキュメントに記述されています。しかし、もしあなたがPythonのロギングフレームワークを使ったことがない場合(もしくはある場合も)、これは素早い入門になるでしょう。

登場人物

Pythonのロギングは4つの部分で構成されます。

• ロガー
• ハンドラ
• フィルタ
• フォーマッタ

ロガー

ロガーはロギングシステムのエントリーポイントです。各ロガーは処理が記述されたメッセージの名前付けされたバケツです。

ロガーには ログレベル が設定されています。このログレベルはハンドリングされたログメッセージの深刻さを表しています。Pythonは下記のログレベルを定義しています。

• DEBUG: デバッグのための低レベルシステム情報
• INFO: 一般的なシステム情報
• WARNING: 重要度の小さい問題が発生したことを示す情報
• ERROR: 大きな問題が発生したことを示す情報
• CRITICAL: 重大な問題が発生したことを示す情報

ロガーに記載された各メッセージは ログレコード です。各ログレコードは、特定のメッセージの重要性を表す ログレベル を持ちます。ログレコードには、記録されたイベントを説明するメタデータを含むことができます。これには、スタックトレースやエラーコードと言った詳細を含めることができます。

ロガーにメッセージが渡されたとき、メッセージのログレベルはロガーのログレベルと比較されます。メッセージのログレベルがロガー自体のログレベルと同等以上の場合、メッセージは次の処理に進みます。それ以外の場合、メッセージは無視されます。

ロガーによってメッセージの処理が必要だと判断された場合、メッセージは ハンドラ に渡されます。

ハンドラ

ハンドラは、ロガー上で書くメッセージに何をするかを決定するための原動力です。ここで、メッセージを表示する、ファイルに書き込む、ネットワークソケットに送信する、といった特定のロギング動作を記述します。

ロガーと同様に、ハンドラもログレベルを持ちます。ログレコードのログレベルがハンドラのレベルに満たない場合、ハンドラはメッセージを無視します。

ロガーには複数のハンドラを設定でき、また各ハンドラは異なるログレベルを持つことができます。この方法により、メッセージの重要性に応じて通知方法を変えることができます。たとえば、ERROR と CRITICAL メッセージを呼び出しサービスに転送するハンドラを設定する一方で、後で分析するために (ERROR や``CRITICAL`` も含む) すべてのメッセージをファイルに記録する 2 つめのハンドラをセットすることができます。

フィルタ

フィルターは、どのログレコードがロガーからハンドラへ渡されるかについて、追加的なコントロールを提供します。

デフォルトでは、ログレベル要件を満たしたすべてのログメッセージが処理されます。しかし、フィルタを使用することで、ロギングのプロセスに追加的な要件を設定できます。たとえば、特定のソースからの ERROR のみを処理するようにフィルタを設定することができます。

フィルタは、処理前にログレコードを修正するためにも使えます。たとえば、特定の条件を満たした場合に ERROR ログレコードを WARNING レコードに格下げさせるようなフィルタを設定できます。

フィルタは、ロガーもしくはハンドラに対して設定できます; 複数のフィルタを使って複数のフィルタ動作を連鎖させることも可能です。

フォーマッタ

最終的には、ログレコードはテキストとして表現される必要があります。フォーマッタはこのテキストの書式を定義します。フォーマッタは、通常は Python の文字列フォーマットで、LogRecord 属性 を含みます; しかし、特定の書式設定を行うような独自のフォーマッタを記述することもできます。

ロギングを使用する

ロガー、ハンドラ、フィルタ、フォーマッタを設定し終えたら、コード内にロギングの呼び出しを設置する必要があります。ロギングのフレームワークの使用は非常にシンプルです。例をご覧ください:

# import the logging library
import logging

# Get an instance of a logger
logger = logging.getLogger(__name__)

def my_view(request, arg1, arg):
    ...
    if bad_mojo:
        # Log an error message
        logger.error('Something went wrong!')

そう、これだけです! bad_mojo の状態がアクティブなときは、毎回エラーログが記述されます。

ロガーに名前をつける

The call to logging.getLogger() obtains (creating, if necessary) an instance of a logger. The logger instance is identified by a name. This name is used to identify the logger for configuration purposes.

慣習として、logger の名前は通常 __name__ とし、logger が含まれている Python モジュールの名前となるようにします。これにより、ロギングの呼び出しをモジュールごとにフィルタ・ハンドリングできるようになります。しかし、ロギングメッセージを他の方法で組織したい場合は、ドット区切りの名前を logger に与えることもできます。

# Get an instance of a specific named logger
logger = logging.getLogger('project.interesting.stuff')

The dotted paths of logger names define a hierarchy. The project.interesting logger is considered to be a parent of the project.interesting.stuff logger; the project logger is a parent of the project.interesting logger.

Why is the hierarchy important? Well, because loggers can be set to propagate their logging calls to their parents. In this way, you can define a single set of handlers at the root of a logger tree, and capture all logging calls in the subtree of loggers. A logging handler defined in the project namespace will catch all logging messages issued on the project.interesting and project.interesting.stuff loggers.

This propagation can be controlled on a per-logger basis. If you don't want a particular logger to propagate to its parents, you can turn off this behavior.

ロギング呼び出しを作成する

ロガーのインスタンスは、デフォルトの各ログレベルに対する入力方法を含んでいます:

• logger.debug()
• logger.info()
• logger.warning()
• logger.error()
• logger.critical()

さらに 2 つのロギング呼び出しが可能です:

• logger.log(): 手動で、特定のログレベルでロギングメッセージを吐き出します。
• logger.exception(): Creates an ERROR level logging message wrapping the current exception stack frame.

ロギングを設定する

もちろん、コード内にロギング呼び出しを設置するだけでは不十分です。ロガー、ハンドラ、フィルタおよびフォーマッタが、役立つ形でロギング出力をするように設定する必要があります。

Python のロギングライブラリは、実用的なインターフェースから設定ファイルまで、ロギング設定のテクニックを提供しています。デフォルトでは、Django は dictConfig フォーマット を使用します。

ロギングを設定するために、設定値のディクショナリを定義するため、LOGGING を使います。この設定で、あなた自身のロギングを構成するロガー、ハンドラ、フィルタ、フォーマッタを定義します。また、これらの構成要素が持つべきログレベルや他の属性も定義します。

デフォルトでは、LOGGING 設定は、以下のスキームを使って Django のデフォルトロギング設定 に統合されています。

LOGGING dictConfig 内の disable_existing_loggers キーが True (デフォルトです) にセットされている場合、デフォルト設定のすべてのロガーが無効化されます。無効化は、削除とは違います; ロガーは存在はしており、記録されたものを黙って破棄します。親ロガーに伝達もしません。'disable_existing_loggers': True は、とても慎重に扱う必要があります; あなたの期待しない動作かもしれません。代わりに disable_existing_loggers を False にセットして、デフォルトロガー設定の必要な部分を再定義できます; もしくは、LOGGING_CONFIG を None にセットして ロギング設定を自分で行うこともできます。

ロギングは、一般的な Django の setup() 関数の一部として設定されます。したがって、ロガーが常にプロジェクトコード内で使用準備ができていることが保証されています。

例

dictConfig フォーマット に関する完全なドキュメントが、ロギング設定ディクショナリの最高の教材です。とはいえ、どんなことが可能なのか知ってもらうため、以下にいくつかの例を示します。

最初は、 django ロガーからローカルファイルにすべてのロギングを書き込むシンプルな設定です:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'file': {
            'level': 'DEBUG',
            'class': 'logging.FileHandler',
            'filename': '/path/to/django/debug.log',
        },
    },
    'loggers': {
        'django': {
            'handlers': ['file'],
            'level': 'DEBUG',
            'propagate': True,
        },
    },
}

この例を使用するときは、'filename' のパスを Django アプリケーションを実行しているユーザーが書き込み可能な場所に変更してください。

次は、Django のロギングをコンソールに表示する構成の例です。ローカル開発で有用でしょう。

デフォルトでは、この設定は INFO および上位のレベルのメッセージのみをコンソールに送信します (Django のデフォルトのロギング設定と同じですが、デフォルト設定は DEBUG=True のときのみ動作する点が異なります)。 Django はそんなに多くのメッセージを記録するわけではありません。この設定では、環境変数 DJANGO_LOG_LEVEL=DEBUG をセットすることで、Django のデバッグロギングのすべてを見ることもできますが、すべてのデータベースクエリを含んでいるため非常に冗長です:

import os

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'level': os.getenv('DJANGO_LOG_LEVEL', 'INFO'),
        },
    },
}

最後に、なかなか複雑なロギングセットアップの例をご覧ください:

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']
        }
    }
}

このロギング設定は、以下のことを行います:

• Identifies the configuration as being in 'dictConfig version 1' format. At present, this is the only dictConfig format version.

• 2 つのフォーマッタを定義します:

  • simple は、ログレベルの名称 (DEBUG など) とログメッセージを出力します。

    この format 文字列は標準の Python 文字列フォーマットで、各ログ行で出力される詳細を定義します。出力可能な詳細の全リストは Formatter Objects に記載されています。

  • verbose は、ログレベルの名称とログメッセージに加えて、時刻、プロセス、スレッド、ログメッセージを生成したモジュールを出力します。

• 2 つのフィルタを定義します:

  • project.logging.SpecialFilter, using the alias special. If this filter required additional arguments, they can be provided as additional keys in the filter configuration dictionary. In this case, the argument foo will be given a value of bar when instantiating SpecialFilter.
  • django.utils.log.RequireDebugTrue は、DEBUG が True のときにレコードの処理を進めます。

• 2 つのハンドラを定義します:

  • console は、すべての INFO 以上のメッセージを sys.stderr に表示 (print) する StreamHandler クラスです。このハンドラは simple 出力フォーマットを使用します。
  • mail_admins` は、すべての ``ERROR 以上のメッセージを ADMINS に E メール送信する AdminEmailHandler です。このハンドラは special フィルタを使用します。

• 3 つのロガーを設定します:

  • django は、すべてのメッセージを console ハンドラに渡します。
  • django.request は、すべての ERROR メッセージを mail_admins ハンドラに渡します。加えて、このロガーはメッセージを親に 伝えない よう設定されています。これは、django.request 内に記述されたログメッセージは django ロガーで処理されないことを意味します。
  • myproject.custom は INFO もしくはそれ以上のすべてのメッセージを渡し、special フィルタを 2 つのハンドラに引き渡します -- console と mail_admins です。これは、INFO 以上のレベルのメッセージがコンソールで表示され、さらに ERROR と CRITICAL のメッセージは E メールでも出力されることを意味します。

カスタムのロギング設定

ロガーの設定に Python の dictConfig フォーマットを使用したくない場合は、あなた自身の設定スキームを定義することができます。

The LOGGING_CONFIG setting defines the callable that will be used to configure Django's loggers. By default, it points at Python's logging.config.dictConfig() function. However, if you want to use a different configuration process, you can use any other callable that takes a single argument. The contents of LOGGING will be provided as the value of that argument when logging is configured.

ロギング設定を無効化する

If you don't want to configure logging at all (or you want to manually configure logging using your own approach), you can set LOGGING_CONFIG to None. This will disable the configuration process for Django's default logging. Here's an example that disables Django's logging configuration and then manually configures logging:

settings.py

LOGGING_CONFIG = None

import logging.config
logging.config.dictConfig(...)

Setting LOGGING_CONFIG to None only means that the automatic configuration process is disabled, not logging itself. If you disable the configuration process, Django will still make logging calls, falling back to whatever default logging behavior is defined.

Django's logging extensions

Django provides a number of utilities to handle the unique requirements of logging in Web server environment.

ロガー

Django provides several built-in loggers.

django

The catch-all logger for messages in the django hierarchy. No messages are posted using this name but instead using one of the loggers below.

django.request

Log messages related to the handling of requests. 5XX responses are raised as ERROR messages; 4XX responses are raised as WARNING messages. Requests that are logged to the django.security logger aren't logged to django.request.

Messages to this logger have the following extra context:

• status_code: The HTTP response code associated with the request.
• request: The request object that generated the logging message.

django.server

Log messages related to the handling of requests received by the server invoked by the runserver command. HTTP 5XX responses are logged as ERROR messages, 4XX responses are logged as WARNING messages, and everything else is logged as INFO.

Messages to this logger have the following extra context:

• status_code: The HTTP response code associated with the request.
• request: The request object that generated the logging message.

django.template

Log messages related to the rendering of templates.

• Missing context variables are logged as DEBUG messages.

django.db.backends

Messages relating to the interaction of code with the database. For example, every application-level SQL statement executed by a request is logged at the DEBUG level to this logger.

Messages to this logger have the following extra context:

• duration: The time taken to execute the SQL statement.
• sql: The SQL statement that was executed.
• params: The parameters that were used in the SQL call.

For performance reasons, SQL logging is only enabled when settings.DEBUG is set to True, regardless of the logging level or handlers that are installed.

This logging does not include framework-level initialization (e.g. SET TIMEZONE) or transaction management queries (e.g. BEGIN, COMMIT, and ROLLBACK). Turn on query logging in your database if you wish to view all database queries.

django.security.*

The security loggers will receive messages on any occurrence of SuspiciousOperation and other security-related errors. There is a sub-logger for each subtype of security error, including all SuspiciousOperations. The level of the log event depends on where the exception is handled. Most occurrences are logged as a warning, while any SuspiciousOperation that reaches the WSGI handler will be logged as an error. For example, when an HTTP Host header is included in a request from a client that does not match ALLOWED_HOSTS, Django will return a 400 response, and an error message will be logged to the django.security.DisallowedHost logger.

These log events will reach the django logger by default, which mails error events to admins when DEBUG=False. Requests resulting in a 400 response due to a SuspiciousOperation will not be logged to the django.request logger, but only to the django.security logger.

To silence a particular type of SuspiciousOperation, you can override that specific logger following this example:

'handlers': {
    'null': {
        'class': 'logging.NullHandler',
    },
},
'loggers': {
    'django.security.DisallowedHost': {
        'handlers': ['null'],
        'propagate': False,
    },
},

Other django.security loggers not based on SuspiciousOperation are:

• django.security.csrf: For CSRF failures.

django.db.backends.schema

Logs the SQL queries that are executed during schema changes to the database by the migrations framework. Note that it won't log the queries executed by RunPython. Messages to this logger have params and sql in their extra context (but unlike django.db.backends, not duration). The values have the same meaning as explained in django.db.backends.

ハンドラ

Django provides one log handler in addition to those provided by the Python logging module.

class AdminEmailHandler(include_html=False, email_backend=None)[ソース]

This handler sends an email to the site ADMINS for each log message it receives.

If the log record contains a request attribute, the full details of the request will be included in the email. The email subject will include the phrase "internal IP" if the client's IP address is in the INTERNAL_IPS setting; if not, it will include "EXTERNAL IP".

If the log record contains stack trace information, that stack trace will be included in the email.

The include_html argument of AdminEmailHandler is used to control whether the traceback email includes an HTML attachment containing the full content of the debug Web page that would have been produced if DEBUG were True. To set this value in your configuration, include it in the handler definition for django.utils.log.AdminEmailHandler, like this:

'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'class': 'django.utils.log.AdminEmailHandler',
        'include_html': True,
    }
},

Note that this HTML version of the email contains a full traceback, with names and values of local variables at each level of the stack, plus the values of your Django settings. This information is potentially very sensitive, and you may not want to send it over email. Consider using something such as Sentry to get the best of both worlds -- the rich information of full tracebacks plus the security of not sending the information over email. You may also explicitly designate certain sensitive information to be filtered out of error reports -- learn more on Filtering error reports.

By setting the email_backend argument of AdminEmailHandler, the email backend that is being used by the handler can be overridden, like this:

'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'class': 'django.utils.log.AdminEmailHandler',
        'email_backend': 'django.core.mail.backends.filebased.EmailBackend',
    }
},

By default, an instance of the email backend specified in EMAIL_BACKEND will be used.

send_mail(subject, message, *args, **kwargs)[ソース]

Sends emails to admin users. To customize this behavior, you can subclass the AdminEmailHandler class and override this method.

フィルタ

Django provides some log filters in addition to those provided by the Python logging module.

class CallbackFilter(callback)[ソース]

This filter accepts a callback function (which should accept a single argument, the record to be logged), and calls it for each record that passes through the filter. Handling of that record will not proceed if the callback returns False.

For instance, to filter out UnreadablePostError (raised when a user cancels an upload) from the admin emails, you would create a filter function:

from django.http import UnreadablePostError

def skip_unreadable_post(record):
    if record.exc_info:
        exc_type, exc_value = record.exc_info[:2]
        if isinstance(exc_value, UnreadablePostError):
            return False
    return True

and then add it to your logging config:

'filters': {
    'skip_unreadable_posts': {
        '()': 'django.utils.log.CallbackFilter',
        'callback': skip_unreadable_post,
    }
},
'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'filters': ['skip_unreadable_posts'],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},

class RequireDebugFalse[ソース]

This filter will only pass on records when settings.DEBUG is False.

This filter is used as follows in the default LOGGING configuration to ensure that the AdminEmailHandler only sends error emails to admins when DEBUG is False:

'filters': {
    'require_debug_false': {
        '()': 'django.utils.log.RequireDebugFalse',
    }
},
'handlers': {
    'mail_admins': {
        'level': 'ERROR',
        'filters': ['require_debug_false'],
        'class': 'django.utils.log.AdminEmailHandler'
    }
},

class RequireDebugTrue[ソース]

This filter is similar to RequireDebugFalse, except that records are passed only when DEBUG is True.

Django のデフォルトのロギング設定

デフォルトでは、Django は以下のロギングを設定してあります:

DEBUG が True のとき:

• django ロガーは、django ヒエラルキー (django.server を除く) において、INFO レベル以上のメッセージをコンソールに送信します。

DEBUG が False のとき:

• django ロガーは、django ヒエラルキー (django.server を除く) において、ERROR ないし CRITICAL レベルを AdminEmailHandler に送信します。

DEBUG の値にかかわらず:

• django.server ロガーは INFO レベル以上のメッセージをコンソールに送信します。

All loggers except django.server propagate logging to their parents, up to the root django logger. The console and mail_admins handlers are attached to the root logger to provide the behavior described above.

このデフォルト設定を補完ないし置き換える方法を学びたいときは、ロギングを設定する を参照してください。