前回の記事では、 Django + django-log-request-id という構成で、HTTPリクエストごとの識別子(Request-ID) をログに出力してみました。
また、記事ではRequest-IDをログに出力するサードパーティライブラリを調べました。その中にASGIミドルウェアの asgi-correlation-id がありました。
snok/asgi-correlation-id: Request ID propagation for ASGI apps
ただ、前回は
と書いたものの、実際に組み込めるのか気になったことから、ためしてみた時のメモを残します。
目次
環境
- Django 5.0.1
- asgi-correlation-id 4.2.0
ちなみに、ログに出力するためのアプリは前回と同じpollsを使います。
そのため、前回との差分は
- asgi.py
- settings.py
のみとなりました。
ASGIミドルウェアをDjangoに組み込む
まずは、ASGIミドルウェアである asgi-correlation-id をDjangoに組み込んでいきます。
asgi-correlation-id をインストール
リポジトリのREADMEに従い、インストールします。
$ pip install asgi-correlation-id ... Successfully installed anyio-4.2.0 asgi-correlation-id-4.2.0 idna-3.6 sniffio-1.3.0 starlette-0.34.0
ASGIミドルウェアをDjangoに組み込む
ASGIミドルウェアの組み込みについては、Djangoの公式ドキュメントに記載があります。
ASGI ミドルウェアの適用 | ASGIでデプロイする | Django ドキュメント | Django
その記載に従い、 config/asgi.py を修正し、ASGIミドルウェアをDjangoに組み込みます。
import os from django.core.asgi import get_asgi_application from asgi_correlation_id import CorrelationIdMiddleware os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'config.settings') application = get_asgi_application() # add asgi-correlation-id middleware application = CorrelationIdMiddleware(application)
asgi-correlation-id 向けのLOGGING設定を行う
ASGIミドルウェアの組み込みが終わりました。
次はログ出力の設定を行うため、 settings.py にて LOGGING を修正します。
なお、前回の記事との違いは
- LOGGINGの中で
request_idとしていたところを、correlation_idへと変更- 具体的には以下の中
- filters
- formatters
- handlers
request_idのままだとエラーになってしまう
- 具体的には以下の中
- filterで、
'asgi_correlation_id.CorrelationIdFilter'を指定 - loggersから
django.serverを削除- 今回はUvnicornでDjangoを起動することから、
django.serverは使わないため
- 今回はUvnicornでDjangoを起動することから、
となります。
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'filters': {
'correlation_id': {
'()': 'asgi_correlation_id.CorrelationIdFilter',
'uuid_length': 32,
'default_value': '',
}
},
'formatters': {
'standard': {
'format': '%(levelname)-8s [%(asctime)s] [%(correlation_id)s] %(name)s: %(message)s'
},
},
'handlers': {
'console': {
'level': 'DEBUG',
'class': 'logging.StreamHandler',
'filters': ['correlation_id'],
'formatter': 'standard',
},
},
'loggers': {
# 「"GET /polls/ HTTP/1.1" 200 14」のようなログを出すのは Uvicorn なので loggers には設定できない
# pollsアプリのログを出力する
'polls': {
'handlers': ['console'],
'level': 'DEBUG',
'propagate': False,
},
# SQLのログも出力する
'django.db.backends': {
'level': 'DEBUG',
'handlers': ['console'],
},
}
}
Uvnicornをインストールして、Djangoを起動
ここまででDjangoの準備はできました。
続いて、DjangoをASGIサーバで起動してみます。
Django の公式ドキュメントではいくつかのASGIサーバが紹介されていますが、今回は Uvicornを使ってみます。
Djangoの公式ドキュメントでは、Uvicornによる起動方法も記載されているため、それに従って作業してみます。
How to use Django with Uvicorn | Django documentation | Django
まずは Uvicorn をインストールします。
$ pip install uvicorn ... Successfully installed click-8.1.7 h11-0.14.0 uvicorn-0.25.0
続いて、UvicornでDjangoアプリを起動します。
python -m uvicorn config.asgi:application --reload
動作確認
まずはViewのindex関数のエンドポイントにHTTPリクエストします。
$ curl http://localhost:8000/polls/
Djangoのログを確認すると、Request-IDが出力されていました。
前回の記事と異なり、HTTPリクエストヘッダには X-Request-Id が含まれた状態でDjangoに渡されているようです。
DEBUG [2024-01-03 11:29:23,835] [e93dcb359a0143ccac6b83a3fef50524] polls.views: ['Host', 'User-Agent', 'Accept', 'X-Request-Id']
DEBUG [2024-01-03 11:29:23,835] [e93dcb359a0143ccac6b83a3fef50524] polls.views: ['REQUEST_METHOD', 'QUERY_STRING', 'SCRIPT_NAME', 'PATH_INFO', 'wsgi.multithread', 'wsgi.multiprocess', 'REMOTE_ADDR', 'REMOTE_HOST', 'REMOTE_PORT', 'SERVER_NAME', 'SERVER_PORT', 'HTTP_HOST', 'HTTP_USER_AGENT', 'HTTP_ACCEPT', 'HTTP_X_REQUEST_ID']
DEBUG [2024-01-03 11:29:23,835] [e93dcb359a0143ccac6b83a3fef50524] polls.views: e93dcb359a0143ccac6b83a3fef50524
DEBUG [2024-01-03 11:29:23,836] [e93dcb359a0143ccac6b83a3fef50524] django.db.backends: (0.000) SELECT "polls_question"."id", "polls_question"."question_text", "polls_question"."pub_date" FROM "polls_question"; args=(); alias=default
INFO: 127.0.0.1:46036 - "GET /polls/ HTTP/1.1" 200 OK
exception関数のエンドポイントも同様でした。
$ curl http://localhost:8000/polls/exception
ログは以下です。こちらでも Request-ID が出力されていました。
DEBUG [2024-01-03 11:32:42,006] [e85ca12da762422a8c43aaa58e7e463b] polls.views: my exception Internal Server Error: /polls/exception Traceback (most recent call last): ... File "path/to/polls/views.py", line 29, in exception raise Exception('my exception') Exception: my exception
INFO: 127.0.0.1:46038 - "GET /polls/exception HTTP/1.1" 500 Internal Server Error
なお、デフォルト設定の場合、asgi-correlation-id の validator のしくみにより、たとえHTTPリクエストヘッダに X-Request-ID が含まれていたとしても、値が不適切な場合は再度 Request-ID を生成するようです。
$ curl -H 'X-Request-ID:123abc' http://localhost:8000/polls/
しかし、ログでは since request header value failed validation とあるように、 X-Request-ID の値が無視されて値が再生成されています。
Generated new request ID (ac92bd74acad4e85ab14421d631dd3c6), since request header value failed validation DEBUG [2024-01-03 11:34:29,505] [ac92bd74acad4e85ab14421d631dd3c6] polls.views: ['Host', 'User-Agent', 'Accept', 'X-Request-Id']
これだと不便な場合もあるため、次はRequest-IDの再生成を行わないようにしてみます。
Request-ID を再生成しないよう、DjangoにてASGIミドルウェアへ引数を渡す
実装
「どんな値であってもRequest-IDを再生成しない」を実現するためにREADMEを読んだところ、 validator=None を設定すれば良さそうでした。
https://github.com/snok/asgi-correlation-id?tab=readme-ov-file#middleware-configuration
このオプションをどのように渡せばよいか見たところ、 asgi-correlation-id のミドルウェアは dataclass として定義されていました。
@dataclass class CorrelationIdMiddleware: # ... # https://github.com/snok/asgi-correlation-id/blob/v4.2.0/asgi_correlation_id/middleware.py#L30
そこで、asgi.pyにてオプションを渡すよう修正します。
application = CorrelationIdMiddleware(application, validator=None)
動作確認
UvicornでDjangoを起動した後、curlを実行します。
$ curl -H 'X-Request-ID:123abc' http://localhost:8000/polls/
すると、ログには X-Request-ID の値 123abc が出力されるようになりました。
DEBUG [2024-01-03 11:54:57,980] [123abc] polls.views: ['Host', 'User-Agent', 'Accept', 'X-Request-Id']
以上より、ASGIミドルウェアの asgi-correlation-id をDjangoに組み込むことができました。
また、ミドルウェアのオプションの設定方法もわかりました。
ソースコード
Githubにあげました。
https://github.com/thinkAmi-sandbox/django_with_asgi-correlation-id-example
今回のプルリクはこちら。
https://github.com/thinkAmi-sandbox/django_with_asgi-correlation-id-example/pull/1
