Cloud RunでDjangoのプロジェクトを快適に実行するためのloggingについてまとめます．
実行環境
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
ログのフォーマットを決定します．以下の例では，フォーマットを指定しているので，出力されるログには時刻などの情報が追加されます．
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
Cloud Logging | Google Cloud
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")
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は，以下のソースコードを参考に作成しました．
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サーバーのログがとても見やすくなりました．
