Cloud RunでDjangoのプロジェクトを快適に実行するためのloggingについてまとめます.
- 実行環境
- Python logging
- logging.config.dictConfig
- DjangoのLOGGINGの設定
- Cloud Logging
- Cloud Run
- Cloud Trace
- まとめ
実行環境
Python 3.8.6 on macOS 10.15.7
Python logging
以下のウェブサイトに記載されていますが.自分なりにまとめます.
Logging HOWTO — Python 3.8.7 documentation
logging.Logger
, logging.Handler
, logging.Formatter
, logging.Filter
の4個のClassが登場します.
logging.Logger
ログを書き込むための入り口です.
import logging logging.basicConfig(level=logging.DEBUG) logging.debug("debug") logging.info("info") logging.warning("warning") logging.error("error")
これを実行すると,以下のように出力されます.
DEBUG:root:debug INFO:root:info WARNING:root:warning ERROR:root:error
print()
を使うと直感的でよいのですが,ソースコードからprint()
の挿入削除を繰り返すことになり面倒です.ログをレベルに分けておくと,出力するレベルを変更することで同様の操作ができて便利です.
以下のレベルをよく用います.
- DEBUG: 詳細な情報
- INFO: 想定通りの情報.例えば,webサーバーにリクエストがあり正常にレスポンスした.
- WARNING: 想定外の情報だがエラーではない.例えば,webサーバーにリクエストがあったがファイルが見つからなかった.
- ERROR: エラーが発生した.例えば,webサーバーにリクエストがあり,処理中に
ZeroDivisionError
が発生した.
上記の例では,level=logging.DEBUG
と設定しているので,ログが4個出力されています.level=logging.WARNING
に変更すると,以下のようにログが2個だけ出力されます.
WARNING:root:warning ERROR:root:error
logging.info()
はlogging.RootLogger
のinfo()
を呼ぶ関数で,logging.RootLogger()
はlogging.Logger
を継承しており,import logging
を実行するときに自動的に作成されます*1.
logging.Logger
は直接インスタンス化するのではなく,logging.getLogger(name)
を使ってインスタンス化します *2.例えば以下のように使います.
import logging logger = logging.getLogger(__name__) logger.debug("debug") logger.info("info") logger.warning("warning") logger.error("error")
warning error
logging.Handler
logging.Logger
によって書き込まれたログを扱う方法を決定します.標準出力に書き込んだり(logging.StreamHandler
),ファイルに書き込んだり(logging.FileHandler
),メールを送信したりと(logging.handlers.SMTPHandler
),多種多様な対応が可能です.
以下の例では,"test.log"にログを書き出すhandlerを使用します.
import logging logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) handler = logging.FileHandler("test.log", encoding="utf-8") handler.setLevel(logging.INFO) logger.addHandler(handler) logger.debug("debug") logger.info("info") logger.warning("warning") logger.error("error")
test.log
info warning error
具体的なハンドラの例は,以下に記載されています.
logging.handlers — Logging handlers — Python 3.8.7 documentation
logging.Formatter
ログのフォーマットを決定します.以下の例では,フォーマットを指定しているので,出力されるログには時刻などの情報が追加されます.
import logging logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) handler = logging.FileHandler("test.log", encoding="utf-8") handler.setLevel(logging.INFO) formatter = logging.Formatter( '%(asctime)s %(name)s %(levelname)s: %(message)s' ) handler.setFormatter(formatter) logger.addHandler(handler) logger.debug("debug") logger.info("info") logger.warning("warning") logger.error("error")
test.log
2021-01-23 17:27:42,686 __main__ INFO: info 2021-01-23 17:27:42,690 __main__ WARNING: warning 2021-01-23 17:27:42,690 __main__ ERROR: error
フォーマットの詳細は以下の表が参考になります.
logging — Logging facility for Python — Python 3.8.7 documentation
logging.Filter
ログの情報を変更したり,削除したりします.以下の例では,nameを変更するフィルターを使います.
import logging class SampleFilter(logging.Filter): def filter(self, record): record.name = "sample" return True logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) handler = logging.FileHandler("test.log", encoding="utf-8") handler.setLevel(logging.INFO) formatter = logging.Formatter( '%(asctime)s %(name)s %(levelname)s: %(message)s' ) handler.setFormatter(formatter) f = SampleFilter() logger.addFilter(f) logger.addHandler(handler) logger.debug("debug") logger.info("info") logger.warning("warning") logger.error("error")
2021-01-23 17:34:40,860 sample INFO: info 2021-01-23 17:34:40,860 sample WARNING: warning 2021-01-23 17:34:40,861 sample ERROR: error
"main"が"sample"に置換されています.
logging.config.dictConfig
loggingの設定をカスタマイズしていくと,上記のソースコードのように可読性が低下していきますので,logging.config.dictConfig(config)
を使用して辞書形式で一括設定すると便利です.
import logging from logging.config import dictConfig import json with open("config.json", "r", encoding="utf-8") as f: dictConfig(json.load(f)) logger = logging.getLogger(__name__) logger.debug("debug") logger.info("info") logger.warning("warning") logger.error("error")
config.json
{ "version": 1, "disable_existing_loggers": false, "formatters": { "file_formatter": { "format": "%(asctime)s %(name)s %(levelname)s: %(message)s" } }, "handlers": { "file_handler": { "class": "logging.FileHandler", "level": "INFO", "formatter": "file_formatter", "filename": "test.log", "mode": "a", "encoding": "utf-8" } }, "root": { "level": "INFO", "handlers": [ "file_handler" ] } }
2021-01-23 17:50:32,000 __main__ INFO: info 2021-01-23 17:50:32,001 __main__ WARNING: warning 2021-01-23 17:50:32,001 __main__ ERROR: error
DjangoのLOGGINGの設定
Djangoでは,今までやっていた設定ファイルの読み出しなど面倒な作業をsetup()
関数が一括で設定してくれます.しなければならないことはsettings.py
のLOGGING
に設定内容を記載するだけです.以下の設定でloggingが使えるようになります.
settings.py
LOGGING = { 'version': 1, 'disable_existing_loggers': False, 'formatters': { 'verbose': { 'format': '{asctime} {levelname} {module} {message}', 'style': '{', }, }, 'handlers': { 'console': { 'class': 'logging.StreamHandler', 'formatter': 'verbose' }, }, 'loggers': { 'django': { 'handlers': ['console'], 'level': 'INFO', } } }
banana/views.py
import logging from django.http import JsonResponse logger = logging.getLogger("django") def sample_banana(request): logger.debug("debug") logger.info("info") logger.warning("warning") logger.error("error") return JsonResponse({"banana": 1})
January 23, 2021 - 08:58:10 Django version 3.1.5, using settings 'sample.settings' Starting development server at http://0.0.0.0:8004/ Quit the server with CONTROL-C. 2021-01-23 08:58:43,230 INFO views info 2021-01-23 08:58:43,231 WARNING views warning 2021-01-23 08:58:43,231 ERROR views error 2021-01-23 08:58:43,235 INFO basehttp "GET /banana/sample HTTP/1.1" 200 13
DjangoはデフォルトでいくつかのLoggerを作成してくれます."django", "django.request", "django.server", などがあります.使い分ければ便利かもしれませんが,Loggerが存在しなければ一つ上の階層のLoggerが使われる仕様を利用して,上記のように"django" Loggerのみに上書きすれば,全てのログを一括して扱うことができます.
なお,"disable_existing_loggers"をTrue
にすればよさそうに見えますが,デフォルトで作成される"django.request"などのLoggerを無効にするだけなので,一部のログが出力されなくなります.
詳細は以下に記載されています.
Logging | Django documentation | Django
Cloud Logging
Google Cloud Platformで提供されているログ管理サービスです.「リアルタイムでのログの管理とスケーラブルな分析」と宣伝されており,面倒なログ管理をアウトソーシングすることができます.
認証の準備
"django-logger@test-project.iam.gserviceaccount.com" などという名前のサービスアカウントを作成し,"roles/logging.logWriter"を設定します.
json形式のcredentialをダウンロードし,GOOGLE_APPLICATION_CREDENTIALS
という名前の環境変数にパスを指定します.
Djangoをローカルで実行してログを送信
google-cloud-loggingという名前のCloud LoggingのClientを使います.
Python Client for Cloud Logging — google-cloud-logging documentation
requirements.txt
Django==3.1.5 google-cloud-logging==2.0.2
settings.py
import google.cloud.logging LOGGING = { 'version': 1, 'disable_existing_loggers': False, 'formatters': { 'verbose': { 'format': '{asctime} {levelname} {module} {message}', 'style': '{', }, }, 'handlers': { 'cloud_logging': { 'class': 'google.cloud.logging.handlers.CloudLoggingHandler', 'client': google.cloud.logging.Client(), 'formatter': 'verbose' }, 'console': { 'class': 'logging.StreamHandler', 'formatter': 'verbose' }, }, 'loggers': { 'django': { 'handlers': ['cloud_logging', 'console'], 'level': 'INFO' }, } }
これを実行し,リクエストを送信すると,Cloud Loggingにログが送信されます.
console handlerも追加しているので,標準出力にもログが表示されるようにしています.
2021-01-23 10:33:53,925 INFO views info 2021-01-23 10:33:53,926 WARNING views warning 2021-01-23 10:33:53,926 ERROR views error 2021-01-23 10:33:53,926 INFO basehttp "GET /banana/sample HTTP/1.1" 200 13
これらの設定で例外の情報もログに出力されるようになります.以下にように例外を意図的に発生させ,ログを確認しました.
views.py
def sample_banana(request): logger.debug("debug") logger.info("info") logger.warning("warning") logger.error("error") raise ValueError("invalid banana")
logging.Formatterの調整
Cloud Loggingでは,自動的にレベルや時刻が表示されるので,logging.Formatter
ではメッセージのみ表示するのがよさそうです.
LOGGING = { 'version': 1, 'disable_existing_loggers': False, 'formatters': { 'verbose': { 'format': '{message}', 'style': '{', }, }, 'handlers': { 'cloud_logging': { 'class': 'google.cloud.logging.handlers.CloudLoggingHandler', 'client': google.cloud.logging.Client(), 'formatter': 'verbose', }, 'console': { 'class': 'logging.StreamHandler', 'formatter': 'verbose' }, }, 'loggers': { 'django': { 'handlers': ['cloud_logging', 'console'], 'level': 'INFO' }, } }
views.py
def sample_banana(request): logger.debug("debug") logger.info("info") logger.warning("warning") logger.error("error") return JsonResponse({"banana": 1}) def error_banana(request): raise ValueError("Invalid banana.")
項目の重複がなくなり見やすくなりました.
Cloud Run
上記で作成したDjango プロジェクトをCloud Runで実行してみます."console" loggerが不要なので削除し,以下の設定にしました.
settings.py
LOGGING = { 'version': 1, 'disable_existing_loggers': False, 'handlers': { 'cloud_logging': { 'class': 'cloud_logging.CloudLoggingHandler', 'client': google.cloud.logging.Client() }, 'console': { 'class': 'logging.StreamHandler' }, }, 'loggers': { 'django': { 'handlers': ['cloud_logging'], 'level': 'INFO' }, } }
200ms毎に12個のログを出力するviewを作成します.
views.py
import logging import time from django.http import JsonResponse logger = logging.getLogger("django") def sample_banana(request): for i in range(12): logger.info(f"{i}") time.sleep(0.2) return JsonResponse({"banana": 1})
呼び出すと以下のようなログが生成されます.
また,Cloud Loggingのtrace context*3に対応するために,以下のようなCloudLoggingMiddleware
とCloudLoggingHandler
を新たに追加しました.
cloud_logging.py
import json import logging import os import re import threading from django.http import JsonResponse from google.cloud.logging_v2 import _helpers logger = logging.getLogger("django") re_trace_context = re.compile(r'^([0-9a-z]+)/([0-9]+)') th = threading.local() project_id = os.environ.get("PROJECT_ID") class CloudLoggingMiddleware(object): def __init__(self, get_response): self.get_response = get_response def __call__(self, request): meta = request.META trace_context = meta.get('HTTP_X_CLOUD_TRACE_CONTEXT', "") m = re_trace_context.match(trace_context) if m: th.trace = f"projects/{project_id}/traces/{m.group(1)}" th.span_id = m.group(2) labels = {} user = request.user labels["user_pk"] = f"{user.pk}" if user.is_authenticated else "guest" th.labels = labels # response = self.get_response(request) # th.__dict__.clear() return response class CloudLoggingHandler(logging.StreamHandler): def __init__(self, client, name="python", stream=None): super(CloudLoggingHandler, self).__init__(stream) self.logger = client.logger(name) def emit(self, record): self.logger.log_struct( { "message": super(CloudLoggingHandler, self).format(record), "python_logger": record.name }, severity=_helpers._normalize_severity(record.levelno), labels=getattr(th, "labels", None), trace=getattr(th, "trace", None), span_id=getattr(th, "span_id", None) )
CloudLoggingMiddleware
は,requestからtrace id
やspan id
を取り出して,threading.local()
に保存します.このようにすることで,マルチスレッドなwebサーバー環境でも動作します*4.ついでに,Djangoのユーザーとしてログインしていたら,user pk
をラベルに追加します.
取得したコンテキストをlog_struct()
を呼び出すときに取得し設定します.このようにすることで,いつもどおりにlogging
を使用するだけで自動的に必要なコンテクストを設定することができます.
上記のCloudLoggingMiddleware
とCloudLoggingHandler
は,以下のソースコードを参考に作成しました.
python-logging/handlers.py at master · googleapis/python-logging · GitHub
python-logging/request.py at master · googleapis/python-logging · GitHub
Cloud RunでDjangoをマルチスレッドで実行する
以下のgunicorn-config.pyを使ってgunicornを起動します.
workers = 3 worker_class = 'sync' threads = 3 preload_app = True
workerとthreadsを使ってマルチスレッドにします.Cloud Runの制約のため,preload_app
を有効にしています.以下のGunicornログから,workerが正常に3個起動したことを確認しました.
Using worker: threads [INFO] Booting worker with pid: 3 [INFO] Booting worker with pid: 6 [INFO] Booting worker with pid: 11
Settings — Gunicorn 20.0.4 documentation
Cloud Runで並列処理を許可し,複数のインスタンスが起動しないようにするために,以下の設定を追加しました.
Concurrency 9 Max instances 1
複数のHTTPリクエストを並行して送信する
以下のPythonスクリプトを使って,Cloud RunのURLに対して複数のHTTPリクエストを並行して送信します.
import requests import asyncio url = "https://xxxxxxxx.a.run.app/xxx" def send_request(i): print(i) requests.get(url) async def run(loop): async def run_req(i): return await loop.run_in_executor(None, send_request, i) tasks = [run_req(i) for i in range(10)] return await asyncio.gather(*tasks) loop = asyncio.get_event_loop() loop.run_until_complete(run(loop)
呼び出すviewは200msごとにログを出力し,これがマルチスレッドで実行されるので,以下のように複数のリクエストのログが入り乱れます.これは多数のリクエストを並行して処理するWebサーバーでは日常的な現象です.
このログを追跡するのは困難です.幸いなことに,全てのログにtrace id
を設定しているので,一連のログのみを表示することができます.
以上で,Django のログインユーザーと,Cloud Runのリクエストログと,アプリケーションログが全て関連付きました.
Cloud Trace
上記でコンテキストの設定時に,span id
も指定しているので,このままCloud Traceでトレースすることができます.
例えば,先程の200ms毎に12個のログを出力するviewをトレースするとこのようになります.
説明通りに処理されていることが視覚的に分かります.
まとめ
Cloud LoggingとDjangoが関連して動作するようにすることで,Webサーバーのログがとても見やすくなりました.