Djangoでロギング(logging)を行う方法

2019年5月19日 2019年5月19日

siny

1 カスタムコマンド内で任意にログを吐き出したい場合
2 django-structlogを利用する

こんにちは。sinyです。

この記事では、Djangoにおけるロギング方法についていくつかの方法をまとめてみました。

DjangoCongressJP 2019でも紹介されたdjango-structlogという構造化ロギング機能についても簡単に解説します。

カスタムコマンド内で任意にログを吐き出したい場合

Djangoのカスタムコマンドを利用してバッチ処理等を実行する場合、処理結果をログに残したいケースが多いと思います。

そんな時は、pythonのロギング機能(logging)を利用するやり方があります。
pythonのloggingを使った一番簡単なロギングのコード例です。

import logging
logfile = r"C:\temp\test.log"
logging.basicConfig(filename=logfile,level=logging.DEBUG)
logging.info('ログに書き込みたい文字列')
logging.info('ログに書き込みたい文字列2')

まず最初にloggingモジュールをインポートします。
logfileには出力するログファイルのパスを設定しておきます。

次にlogging.basicConfigを使い最小限のログ出力の設定を行っています。

filename：ログのファイルパス
level：ルートロガーのレベルを指定されたレベルに設定（logging.DEBUG）
　　　※ロギングのレベルにはCRITICAL/ERROR/WARNING/INFO/DEBUG/NOTSETがあります。
　※その他にもいろいろ設定がありますが詳細はこちらを確認してみてください。

最後にlogging.infoでレベル INFO のメッセージをルートロガーで記録します。

上記コードを実行すると、「C:\temp\test.log」が生成されファイルには以下のようなログが記録されます。

INFO:root:ログに書き込みたい文字列
INFO:root:ログに書き込みたい文字列2

とりあえずログは記録されましたが、実運用を考えるとファイル名に日付や時刻を付与したり、ログにも時刻と一緒にログ内容を記録したいと考えるのが普通だと思います。

そこで少しコードをカスタマイズします。

import logging
from datetime import datetime
date_name = datetime.now().strftime("%Y%m%d-%H%M%S")
logdir = r"C:\temp\log"
file_name = logdir + "\\" + date_name + "_test.log"
logging.basicConfig(filename=file_name,level=logging.DEBUG,format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p')
logging.info('ログに書き込みたい文字列')
logging.info('ログに書き込みたい文字列2')

ログには以下のような内容が記録されます。

05/19/2019 04:14:20 AM ログに書き込みたい文字列 
05/19/2019 04:14:22 AM ログに書き込みたい文字列2

以下のコードでdatetimeを利用して現在時刻datetime.now()を取得し、strftimeで取得したdatetime型データを指定したフォーマット形式の文字列に変換します。

date_name = datetime.now().strftime("%Y%m%d-%H%M%S")

これで「'20190519-121111'」といった時刻の文字列が生成されます。

次に、logging.basicConfigを使ってログ出力の設定を行います。

logging.basicConfig(filename=file_name,level=logging.DEBUG,format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p')

logging.basicConfigにはいろいろとオプションがありますが、上記では以下のオプションを追加しています。

format='%(asctime)s %(message)s' ※指定された書式文字列をロギングで使う。
datefmt='%m/%d/%Y %I:%M:%S %p'　※日付/時刻フォーマットを指定する。

　ログファイルに指定したフォルダが存在しないとエラーになるので、予めログフォルダは作成しておきましょう。

django-structlogを利用する

次に、django-structlogというモジュールを使ったロギング方法について簡単に説明します。

「そもそもdjango-structlogとはなにか？」ですが、pypi.orgのサイトには以下の説明があります。

Django-structlogはstructlogを使ったDjangoプロジェクトのための構造化ロギング統合です

ログを記録すると、各ログにまとまったメタデータが追加され、イベントやインシデントの追跡が容易になります。

Project description

簡単に言うと、細かい設定をしなくてもDjangoアプリに対して発生するイベントに対してさまざまなメタデータを自動的に付与したロギング機能を提供してくれるモジュールのようです。

動作確認した環境は以下の通りです。

Python 3.6.5
Django 2.2.1

では実際に使ってみます。
インストールはpipコマンド一発で導入できるので簡単です。

pip install django-structlog

　2019/5/19時点でdjango-structlogの最新バージョンは1.2.3ですが、古いバージョンを指定してインストールすると以下のエラーが発生する場合があるので最新版を導入するようにしましょう。
ModuleNotFoundError: No module named 'structlog
参考Issue

シンプルな使い方は以下の通りです。

import structlog
logger = structlog.get_logger(__name__)
logger.info("エラーが発生しました。")

実行すると、以下の通り日時が付与されたログが表示されます。

2019-05-19 09:32.07 エラーが発生しました。

ただ、これはコンソール上に表示されるだけです。

Django-structlogを使ってDjangoアプリに対して発生したアクセスログ等を自動的にログに記録するように設定します。

settings.pyに「'django_structlog.middlewares.RequestMiddleware'」を追加します。

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

同じくsettings.pyの末尾に以下のコードを追記しましょう。
※以下の設定はGitサイトdjango-structlogに記載されている設定例そのままで、ログの出力先だけを変更したコードです。

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",#プロジェクトフォルダ直下のlogs/json.logを指定したことになる。
            "formatter": "json_formatter",
        },
        "flat_line_file": {
            "class": "logging.handlers.WatchedFileHandler",
            "filename": "logs/flat_line.log",#プロジェクトフォルダ直下のlogs/flat_line.logを指定したことになる。
            "formatter": "key_value",
        },
    },
    "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",
        },
    }
}

structlog.configure(
    processors=[
        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.processors.ExceptionPrettyPrinter(),
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    context_class=structlog.threadlocal.wrap_dict(dict),
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)

以下の部分で通常のテキストログと、Json形式のログの出力先を指定しています。

"filename": "logs/json.log",　
"filename": "logs/flat_line.log",

上記の場合は、<プロジェクトフォルダ>logsの下にログファイルが生成されます。

補足情報

上記のsettings.pyの設定後にpython manage.py shellを実行すると以下のエラーが発生するケースがあるみたいです。
SystemError: ConsoleRenderer with `colors=True` requires the colorama package installed.
上記エラーは「pip install colorama」でcoloramaというモジュールをインストールすると回避することができました。
※django-structlogはpython 3.7までサポートしていますが、coloramaは3.6までしかサポートしていないようなので注意してください。

この状態で、開発サーバを起動してDjangoアプリにアクセスすると、プロジェクトフォルダ直下のlogs\flat_line.log内に以下のようなアクセスログが記録されます。

timestamp='2019-05-19T02:13:32.807210Z' level='info' event='request_finished' logger='django_structlog.middlewares.request' request_id='9b66fdee-b968-4976-bcd7-25285195deaf' user_id=1 ip='127.0.0.1' code=200
timestamp='2019-05-19T02:13:36.202798Z' level='info' event='request_started' logger='django_structlog.middlewares.request' request_id='8eab04cd-a279-44b1-9cbf-c87be30af053' user_id=1 ip='127.0.0.1' request=<WSGIRequest: POST '/pdfmr/upload_test/'> user_agent='Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36'
timestamp='2019-05-19T02:13:36.327506Z' level='info' event='request_finished' logger='django_structlog.middlewares.request' request_id='8eab04cd-a279-44b1-9cbf-c87be30af053' user_id=1 ip='127.0.0.1' code=200
timestamp='2019-05-19T02:13:43.378222Z' level='info' event='request_started' logger='django_structlog.middlewares.request' request_id='1cf99591-dde7-406e-8e75-3717423f66dc' user_id=1 ip='127.0.0.1' request=<WSGIRequest: POST '/pdfmr/dell_file/'> user_agent='Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36'
timestamp='2019-05-19T02:13:43.392184Z' level='info' event='request_finished' logger='django_structlog.middlewares.request' request_id='1cf99591-dde7-406e-8e75-3717423f66dc' user_id=1 ip='127.0.0.1' code=200
timestamp='2019-05-19T02:13:44.263495Z' level='info' event='request_started' logger='django_structlog.middlewares.request' request_id='709b883e-6f10-4d48-b197-a44db5441ffb' user_id=1 ip='127.0.0.1' request=<WSGIRequest: GET '/pdfmr/upload_test/'> user_agent='Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36'
timestamp='2019-05-19T02:13:44.275238Z' level='info' event='request_finished' logger='django_structlog.middlewares.request' request_id='709b883e-6f10-4d48-b197-a44db5441ffb' user_id=1 ip='127.0.0.1' code=200

「何時にどのユーザIDがどのIP(端末）からどんな操作をしたか」といったことが自動的にログに残るのでアクセスログ解析に使えそうですね。

また、json.logの方を見るとJSON形式で同じ内容のログが記録されています。

{"request_id": "8eab04cd-a279-44b1-9cbf-c87be30af053", "user_id": 1, "ip": "127.0.0.1", "code": 200, "event": "request_finished", "timestamp": "2019-05-19T02:13:36.327506Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "1cf99591-dde7-406e-8e75-3717423f66dc", "user_id": 1, "ip": "127.0.0.1", "request": "<WSGIRequest: POST '/pdfmr/dell_file/'>", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36", "event": "request_started", "timestamp": "2019-05-19T02:13:43.378222Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "1cf99591-dde7-406e-8e75-3717423f66dc", "user_id": 1, "ip": "127.0.0.1", "code": 200, "event": "request_finished", "timestamp": "2019-05-19T02:13:43.392184Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "709b883e-6f10-4d48-b197-a44db5441ffb", "user_id": 1, "ip": "127.0.0.1", "request": "<WSGIRequest: GET '/pdfmr/upload_test/'>", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36", "event": "request_started", "timestamp": "2019-05-19T02:13:44.263495Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "709b883e-6f10-4d48-b197-a44db5441ffb", "user_id": 1, "ip": "127.0.0.1", "code": 200, "event": "request_finished", "timestamp": "2019-05-19T02:13:44.275238Z", "logger": "django_structlog.middlewares.request", "level": "info"}

このjson.logを使えば、ユーザアクセスのログ解析画面なども作れそうです。

例えば、以下のようにするとjson.logからユーザ名＝adminのレコードだけを抽出することができます。

import json
from django.conf import settings
json_log = settings.BASE_DIR + "\\" + "logs\json.log"
with open(json_log, mode = 'r', encoding = 'utf-8') as f:
    json_data = {i : json.loads(line) for i, line in enumerate(f)}



from django.contrib.auth.models import User
user_pk = User.objects.values_list('pk',flat=True).get(username="admin")
for i, _ in enumerate(json_data):
    if json_data[i]['user_id'] == user_pk:
        if 'user_agent' in json_data[i].keys():
            print(json_data[i]['ip'], json_data[i]['user_agent'])

上記コードを実行すると、以下のjson.logから、

{"request_id": "c2c81878-f81c-42b0-b804-4f8b76774aa8", "user_id": 1, "ip": "127.0.0.1", "request": "<WSGIRequest: GET '/pdfmr/upload_test/'>", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36", "event": "request_started", "timestamp": "2019-05-19T04:02:01.523345Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "c2c81878-f81c-42b0-b804-4f8b76774aa8", "user_id": 1, "ip": "127.0.0.1", "code": 200, "event": "request_finished", "timestamp": "2019-05-19T04:02:01.557251Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "4580d1cf-012d-4d98-a749-e193d6ea54ea", "user_id": 1, "ip": "127.0.0.1", "request": "<WSGIRequest: GET '/pdfmr/view_list/'>", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36", "event": "request_started", "timestamp": "2019-05-19T04:02:03.278351Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "4580d1cf-012d-4d98-a749-e193d6ea54ea", "user_id": 1, "ip": "127.0.0.1", "code": 200, "event": "request_finished", "timestamp": "2019-05-19T04:02:03.289349Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "06c935a6-0086-4fc5-bf87-50adb6ee29e9", "user_id": 1, "ip": "127.0.0.1", "request": "<WSGIRequest: GET '/pdfmr/upload_test/'>", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36", "event": "request_started", "timestamp": "2019-05-19T04:02:04.350004Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "06c935a6-0086-4fc5-bf87-50adb6ee29e9", "user_id": 1, "ip": "127.0.0.1", "code": 200, "event": "request_finished", "timestamp": "2019-05-19T04:02:04.361973Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "d74c52c7-c726-432e-af55-4e564adc4e6d", "user_id": 1, "ip": "127.0.0.1", "request": "<WSGIRequest: GET '/logout/'>", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36", "event": "request_started", "timestamp": "2019-05-19T04:02:05.205772Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "d74c52c7-c726-432e-af55-4e564adc4e6d", "user_id": 1, "ip": "127.0.0.1", "code": 302, "event": "request_finished", "timestamp": "2019-05-19T04:02:05.227713Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "48bb05b5-d248-40eb-9720-752522612fc2", "user_id": null, "ip": "127.0.0.1", "request": "<WSGIRequest: GET '/login/'>", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36", "event": "request_started", "timestamp": "2019-05-19T04:02:05.237688Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "48bb05b5-d248-40eb-9720-752522612fc2", "user_id": null, "ip": "127.0.0.1", "code": 200, "event": "request_finished", "timestamp": "2019-05-19T04:02:05.254593Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "4d77f995-9802-4988-8f13-f8d1108a6bf8", "user_id": null, "ip": "127.0.0.1", "request": "<WSGIRequest: POST '/login/'>", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36", "event": "request_started", "timestamp": "2019-05-19T04:02:07.894746Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "4d77f995-9802-4988-8f13-f8d1108a6bf8", "user_id": null, "ip": "127.0.0.1", "code": 302, "event": "request_finished", "timestamp": "2019-05-19T04:02:08.031457Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "9ce8a5ce-803b-409c-9815-e095d1aeac33", "user_id": 2, "ip": "127.0.0.1", "request": "<WSGIRequest: GET '/pdfmr/upload_test/'>", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36", "event": "request_started", "timestamp": "2019-05-19T04:02:08.057681Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "9ce8a5ce-803b-409c-9815-e095d1aeac33", "user_id": 2, "ip": "127.0.0.1", "code": 200, "event": "request_finished", "timestamp": "2019-05-19T04:02:08.070607Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "a0a92bb4-ccf1-4778-9951-51d7f2892788", "user_id": 2, "ip": "127.0.0.1", "request": "<WSGIRequest: GET '/pdfmr/view_list/'>", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36", "event": "request_started", "timestamp": "2019-05-19T04:02:09.991998Z", "logger": "django_structlog.middlewares.request", "level": "info"}
{"request_id": "a0a92bb4-ccf1-4778-9951-51d7f2892788", "user_id": 2, "ip": "127.0.0.1", "code": 200, "event": "request_finished", "timestamp": "2019-05-19T04:02:10.002956Z", "logger": "django_structlog.middlewares.request", "level": "info"}

ユーザ名がadminだけのIPとuser_agentの情報だけを抽出できます。

127.0.0.1 Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36
127.0.0.1 Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36
127.0.0.1 Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36
127.0.0.1 Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.157 Safari/537.36

以上、Djangoでロギングを行う方法についての解説でした。