Djangoにて、 django-log-request-id を使ってHTTPリクエストごとの識別子(Request-ID) をログに出力する

Django

OpenTelemetryやログ集約などが不要そうな小さなシステムであっても、HTTPリクエストごとの識別子がログに含まれていると、何かあった時に「どのHTTPリクエストによりログが出力されたのか」を追いかけやすいです。

　
そこで、DjangoでHTTPリクエストごとの識別子をログへ出力するにはどうすればよいか調べたことから、メモを残します。

　
目次

　

環境

　

HTTPリクエストごとの識別子は何が良いか

よく見かけるのが

  • X-Request-ID
  • X-Correlation-ID

などのHTTPヘッダの値です。

Wikipediaでは、 Common non-standard request fields として両者が

Correlates HTTP requests between a client and server.

　
https://en.wikipedia.org/wiki/List_of_HTTP_header_fields

と書いてあります。

ただ、Wikipediaでは併記されていたものの、今回の場合だとどちらの名前を使うのが適切なのか、調べてみました。

すると、 Request-ID を使っているものが多い印象でした。

　
ということで、今回は X-Request-ID を使っていきます。

　

Djangoでの対応について

Django標準の機能

Djangoのドキュメントを見ましたが、それらしいものは見当たりませんでした。

そのため、

などの対応が必要そうでした。

　

自作する方法について

DjangoにてHTTPリクエストに介入することから、Djangoミドルウェアあたりを自作すれば良さそうでした。

実際にDjangoミドルウェアとして作っている記事もありました。
Adding a Unique Request ID to Each Request in Django | Clivern

　
ただ、すでにサードパーティライブラリが存在していればそちらに乗ったほうが良さそうと考え、「自作する」という方向はいったん保留します。

　

サードパーティライブラリについて

調べてみるといくつかのサードパーティライブラリが存在していました。

　
今回は、Herokuに記載されていることもあり、 django-log-request-id を使ってみます。

　

基本となるアプリの作成

必要な機能の検討

今回は、ログに X-Request-ID の値が出力されているかを確認します。

特に

  • リクエスト/レスポンスのログ
  • SQLクエリを実行した時のログ
  • 例外が発生した時のログ

のそれぞれで出力されているかを確認します。

なお、アプリ自体はがんばらず、

とします。

　

実装

Djangoチュートリアルに従いアプリを作ります。

SQLクエリ実行時のログを確認するため、今回はチュートリアルのモデルのうち Question のみ用意すれば十分です。

# models.py
class Question(models.Model):
    question_text = models.CharField(max_length=200)
    pub_date = models.DateTimeField("date published")

　
データの投入ができるよう、admin.pyも実装しておきます。

admin.site.register(Question)

　
Viewでは

  • index
    • SQLクエリを実行した結果をログへ出力
    • HTTPリクエストヘッダの内容をログへ出力
  • exception
    • 例外が発生した時の内容をログへ出力

という2つの関数を用意します。

import logging

from django.http import HttpResponse

from polls.models import Question


def index(request):
    logger = logging.getLogger(__name__)

    # リクエストヘッダーのキーを確認するため、headersとMETAを見る
    # なお、request-id が埋め込まれたログが出力される
    logger.debug(list(request.headers.keys()))
    logger.debug(list(request.META.keys()))

    # x-request-id ヘッダの中身を確認
    logger.debug(request.META.get('HTTP_X_REQUEST_ID'))

    # ログへSQLの内容を出力するために、list()を使ってSQLを即時実行する
    list(Question.objects.all())

    return HttpResponse("Hello, world!!")


def exception(request):
    logger = logging.getLogger(__name__)

    try:
        raise Exception('my exception')
    except Exception as e:
        logger.debug(e)
        raise e

　
pollsアプリのurls.pyは以下のような感じです。

urlpatterns = [
    path("", views.index, name="index"),
    path("exception", views.exception, name="exception"),
]

　
最後にログの設定を settings.py へ行います。

django-log-request-id のREADMEに記載されている LOGGING の設定を元に、今回のアプリに合わせた設定となっています。

filter では、まだ指定していない log_request_id.filters.RequestIDFilter を使っていますが、ひとまず問題なく動作します。

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'request_id': {
            '()': 'log_request_id.filters.RequestIDFilter'
        }
    },
    'formatters': {
        'standard': {
            'format': '%(levelname)-8s [%(asctime)s] [%(request_id)s] %(name)s: %(message)s'
        },
    },
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'filters': ['request_id'],
            'formatter': 'standard',
        },
    },
    'loggers': {
        # 「"GET /polls/ HTTP/1.1" 200 14」のようなログを出すのは django.server
        'django.server': {
            'handlers': ['console'],
            'level': 'INFO',
            'propagate': False,
        },
        # pollsアプリのログを出力する
        'polls': {
            'handlers': ['console'],
            'level': 'DEBUG',
            'propagate': False,
        },
        # SQLのログも出力する
        'django.db.backends': {
          'level': 'DEBUG',
          'handlers': ['console'],
        },
    }
}

　

動作確認

準備ができたため、curlで動作確認します。

まずはViewのindex関数へリクエストすると、レスポンスが返ってきました。

$ curl http://localhost:8000/polls/
Hello, world!!

　
ログを見ると、知りたかった情報が想定通り出力されていました。

DEBUG [2024-01-03 07:06:17,389] [none] polls.views: ['Content-Length', 'Content-Type', 'Host', 'User-Agent', 'Accept']

　
DEBUG [2024-01-03 07:06:17,389] [none] polls.views: ['PATH', ... , 'wsgi.file_wrapper']

　
DEBUG [2024-01-03 07:06:17,389] [none] polls.views: None

　
DEBUG [2024-01-03 07:06:17,390] [none] django.db.backends: (0.000) SELECT "polls_question"."id", "polls_question"."question_text", "polls_question"."pub_date" FROM "polls_question"; args=(); alias=default

　
INFO [2024-01-03 07:06:17,390] [none] django.server: "GET /polls/ HTTP/1.1" 200 14

　
続いて exception 関数へリクエストすると、エラーのHTMLが返ってきました。

$ curl http://localhost:8000/polls/exception
...
</html>

　
ログを見ると、例外のスタックトレースが出力されていました。

DEBUG [2024-01-03 07:09:00,047] [none] 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

　
ERROR [2024-01-03 07:09:00,064] [none] django.server: "GET /polls/exception HTTP/1.1" 500 62621

　

django-log-request-id を組み込む

まずはインストールします。

$ pip install django-log-request-id

　

settings.pyへの追記

各種設定を settings.py に追記します。

まずはDjangoミドルウェアとして動作するように設定します。

なお、READMEには MIDDLEWARE_CLASSES として登録することが記載されています。ただ、 MIDDLEWARE_CLASSES は廃止されて MIDDLEWARE になっています。
Django 1.10 以前のスタイルのミドルウェアをアップグレードする | ミドルウェア (Middleware) | Django ドキュメント | Django

そのため、 MIDDLEWARE の最後に log_request_id.middleware.RequestIDMiddleware を追加します。

MIDDLEWARE = [
    'django.middleware.security.SecurityMiddleware',
    # ...

    # for django-log-request-id
    'log_request_id.middleware.RequestIDMiddleware',
]

　
次に、

  • request.METAへ追加するRequest-ID のキー名を指定する
  • 元々のリクエストヘッダに X-Request-ID がない場合に、Request-IDを生成する

のため、 settings.py の末尾に以下を追記します。

# リクエストヘッダに `X-Request-ID` を追加すると、request.METAには以下のキーで値が設定される
LOG_REQUEST_ID_HEADER = 'HTTP_X_REQUEST_ID'
# リクエストヘッダに `X-Request-ID` がない場合、 request-id を生成する
GENERATE_REQUEST_ID_IF_NOT_IN_HEADER = True

　
他にも設定できる内容はありますが、今回は以上です。

　

動作確認

curlからのHTTPリクエストヘッダに X-Request-ID があるかどうかにより動作が変わるため、それぞれ動作確認していきます。

　

HTTPリクエストヘッダに X-Request-ID が無い場合

curlコマンドは先ほどと同様です。

$ curl http://localhost:8000/polls/

　
すると、Request-IDが生成されて、ログに出力されました。

DEBUG [2024-01-03 07:20:05,480] [275ffb946010493e9dbc435b7263ca57] polls.views: ['Content-Length', 'Content-Type', 'Host', 'User-Agent', 'Accept']

　
DEBUG [2024-01-03 07:20:05,480] [275ffb946010493e9dbc435b7263ca57] polls.views: ['PATH', ..., 'wsgi.file_wrapper']

　
DEBUG [2024-01-03 07:20:05,480] [275ffb946010493e9dbc435b7263ca57] polls.views: None

　
DEBUG [2024-01-03 07:20:05,480] [275ffb946010493e9dbc435b7263ca57] django.db.backends: (0.000) SELECT "polls_question"."id", "polls_question"."question_text", "polls_question"."pub_date" FROM "polls_question"; args=(); alias=default

　
INFO [2024-01-03 07:20:05,481] [275ffb946010493e9dbc435b7263ca57] django.server: "GET /polls/ HTTP/1.1" 200 14

　
なお、ログにもある通り、Viewのindex関数の引数 request の属性

  • META
  • headers

に対して、django-log-request-id のミドルウェアは何も追加しないようです。

middleware.pyのソースコードを見ると、生成した Request-ID を

  • Local() した local.request_id への設定
  • reuqest.id への設定

を行っているだけです。

　
Viewのもう一つのexception関数で出力されるログでも、Request-IDが設定されました。

DEBUG [2024-01-03 07:29:16,852] [4a928e7e11cd4593b3accc525fd611d6] 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

　
ERROR [2024-01-03 07:29:16,870] [4a928e7e11cd4593b3accc525fd611d6] django.server: "GET /polls/exception HTTP/1.1" 500 63027

　

HTTPリクエストヘッダに X-Request-ID がある場合

続いて、curlでHTTPリクエストヘッダに X-Request-ID の値 123abc を追加して動作確認します。

$ curl -H 'X-Request-ID:123abc' http://localhost:8000/polls/

　
すると、DjangoではRequest-IDを生成せず、HTTPリクエストヘッダの X-Request-ID の値がログに出力されました。

DEBUG [2024-01-03 07:31:50,736] [123abc] polls.views: ['Content-Length', 'Content-Type', 'Host', 'User-Agent', 'Accept', 'X-Request-Id']

　
DEBUG [2024-01-03 07:31:50,736] [123abc] polls.views: ['PATH', ... , 'wsgi.file_wrapper']

　
DEBUG [2024-01-03 07:31:50,736] [123abc] polls.views: 123abc

　
DEBUG [2024-01-03 07:31:50,737] [123abc] django.db.backends: (0.000) SELECT "polls_question"."id", "polls_question"."question_text", "polls_question"."pub_date" FROM "polls_question"; args=(); alias=default

　
INFO [2024-01-03 07:31:50,738] [123abc] django.server: "GET /polls/ HTTP/1.1" 200 14

　
Viewのexception関数もためしてみます。

$ curl -H 'X-Request-ID:123abc' http://localhost:8000/polls/exception

　
こちらも同様に、HTTPリクエストヘッダの X-Request-ID の値がログに出力されました。

DEBUG [2024-01-03 07:35:49,925] [123abc] 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

　
ERROR [2024-01-03 07:35:49,941] [123abc] django.server: "GET /polls/exception HTTP/1.1" 500 63160

　
以上より、django-log-request-id を使ってHTTPリクエストごとの識別子(Request-ID) をログに出力することができました。

　

ソースコード

Githubにあげました。
https://github.com/thinkAmi-sandbox/django_with_django-log-request-id-example

今回のプルリクはこちら。
https://github.com/thinkAmi-sandbox/django_with_django-log-request-id-example/pull/1