目次
Django · Logging · structlog 構造化ログ対応
運用フェーズに入った Django アプリで「障害発生時に何が起きたか追えない」「アクセスログから不正検知ができない」という事態を避けるには、適切なログ出力設計が不可欠です。本記事では、Python 標準の logging を使ったカスタムコマンドのログ出力から、settings.py の LOGGING 辞書設定、さらに DjangoCongressJP 2019 で紹介された django-structlog による構造化ログ(JSON / key-value)、リクエスト ID・ユーザー ID 付きアクセスログ自動記録までを完全カバーします。
user@sinyblog:~/article ❯ 01_section_1.mdカスタムコマンド内で任意にログを吐き出したい場合
Djangoのカスタムコマンドを利用してバッチ処理等を実行する場合、処理結果をログに残したいケースが多いと思います。
そんな時は、pythonのロギング機能(logging)を利用するやり方があります。
pythonのloggingを使った一番簡単なロギングのコード例です。
python
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」が生成されファイルには以下のようなログが記録されます。
python
INFO:root:ログに書き込みたい文字列
INFO:root:ログに書き込みたい文字列2
とりあえずログは記録されましたが、実運用を考えるとファイル名に日付や時刻を付与したり、ログにも時刻と一緒にログ内容を記録したいと考えるのが普通だと思います。
そこで少しコードをカスタマイズします。
python
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')
ログには以下のような内容が記録されます。
default
05/19/2019 04:14:20 AM ログに書き込みたい文字列
05/19/2019 04:14:22 AM ログに書き込みたい文字列2
以下のコードでdatetimeを利用して現在時刻datetime.now()を取得し、strftimeで取得したdatetime型データを指定したフォーマット形式の文字列に変換します。
python
date_name = datetime.now().strftime("%Y%m%d-%H%M%S")
これで「'20190519-121111'」といった時刻の文字列が生成されます。
次に、logging.basicConfigを使ってログ出力の設定を行います。
python
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' ※日付/時刻フォーマットを指定する。
ログファイルに指定したフォルダが存在しないとエラーになるので、予めログフォルダは作成しておきましょう。
user@sinyblog:~/article ❯ 02_django_structlog.mddjango-structlogを利用する
次に、django-structlogというモジュールを使ったロギング方法について簡単に説明します。
「そもそもdjango-structlogとはなにか？」ですが、pypi.orgのサイトには以下の説明があります。
Django-structlogはstructlogを使ったDjangoプロジェクトのための構造化ロギング統合です
ログを記録すると、各ログにまとまったメタデータが追加され、イベントやインシデントの追跡が容易になります。
簡単に言うと、細かい設定をしなくてもDjangoアプリに対して発生するイベントに対してさまざまなメタデータを自動的に付与したロギング機能を提供してくれるモジュールのようです。
動作確認した環境は以下の通りです。
Python 3.6.5
Django 2.2.1
では実際に使ってみます。
インストールはpipコマンド一発で導入できるので簡単です。
python
pip install django-structlog
2019/5/19時点でdjango-structlogの最新バージョンは1.2.3ですが、古いバージョンを指定してインストールすると以下のエラーが発生する場合があるので最新版を導入するようにしましょう。
ModuleNotFoundError: No module named 'structlog
シンプルな使い方は以下の通りです。
python
import structlog
logger = structlog.get_logger(__name__)
logger.info("エラーが発生しました。")
実行すると、以下の通り日時が付与されたログが表示されます。
default
2019-05-19 09:32.07 エラーが発生しました。ただ、これはコンソール上に表示されるだけです。
Django-structlogを使ってDjangoアプリに対して発生したアクセスログ等を自動的にログに記録するように設定します。
settings.pyに「'django_structlog.middlewares.RequestMiddleware'」を追加します。
python
MIDDLEWARE = [
# ...
'django_structlog.middlewares.RequestMiddleware',
]
同じくsettings.pyの末尾に以下のコードを追記しましょう。
※以下の設定はGitサイトdjango-structlogに記載されている設定例そのままで、ログの出力先だけを変更したコードです。
python
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内に以下のようなアクセスログが記録されます。
python
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形式で同じ内容のログが記録されています。
js
{"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のレコードだけを抽出することができます。
python
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から、
default
{"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の情報だけを抽出できます。
default
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でロギングを行う方法についての解説でした。
