みーのぺーじ

みーが趣味でやっているPCやソフトウェアについて.Python, Javascript, Processing, Unityなど.

Cloud RunでDjangoの快適なlogging設定

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.RootLoggerinfo()を呼ぶ関数で,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.pyLOGGINGに設定内容を記載するだけです.以下の設定で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にログが送信されます.

f:id:atsuhiro-me:20210123192959p:plain

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")

f:id:atsuhiro-me:20210123194402p:plain

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.")

f:id:atsuhiro-me:20210123203528p:plain

項目の重複がなくなり見やすくなりました.

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})

呼び出すと以下のようなログが生成されます.

f:id:atsuhiro-me:20210124035314p:plain

また,Cloud Loggingのtrace context*3に対応するために,以下のようなCloudLoggingMiddlewareCloudLoggingHandlerを新たに追加しました.

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 idspan idを取り出して,threading.local()に保存します.このようにすることで,マルチスレッドなwebサーバー環境でも動作します*4.ついでに,Djangoのユーザーとしてログインしていたら,user pkをラベルに追加します.

取得したコンテキストをlog_struct()を呼び出すときに取得し設定します.このようにすることで,いつもどおりにloggingを使用するだけで自動的に必要なコンテクストを設定することができます.

上記のCloudLoggingMiddlewareCloudLoggingHandlerは,以下のソースコードを参考に作成しました.

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サーバーでは日常的な現象です.

f:id:atsuhiro-me:20210124035455p:plain

このログを追跡するのは困難です.幸いなことに,全てのログにtrace idを設定しているので,一連のログのみを表示することができます.

f:id:atsuhiro-me:20210124035905p:plain

以上で,Django のログインユーザーと,Cloud Runのリクエストログと,アプリケーションログが全て関連付きました.

Cloud Trace

上記でコンテキストの設定時に,span idも指定しているので,このままCloud Traceでトレースすることができます.

例えば,先程の200ms毎に12個のログを出力するviewをトレースするとこのようになります.

f:id:atsuhiro-me:20210124042133p:plain

説明通りに処理されていることが視覚的に分かります.

まとめ

Cloud LoggingとDjangoが関連して動作するようにすることで,Webサーバーのログがとても見やすくなりました.