Djangoのlogにユーザー情報など出力

Djangoのログにリクエストユーザー情報など[LogRecord属性](https://docs.python.org/ja/3/library/logging.html#logrecord-attributes)にない情報を出力しようとすると、

```python
logger.info(message, extra={'username' : request.user.username})
```
こんな感じのが見つかるけどちょっと違うな～と。ルールを守ってくれない開発メンバーがいたり、自分で書いたログにしか効かないし、と思ってたところ解決策がありました。

# 概要
- [Middleware](https://docs.djangoproject.com/ja/3.0/topics/http/middleware/)を使ってリクエスト時にユーザー情報をthreading.local()に設定
- [logging.filter](https://docs.python.org/ja/3/library/logging.html#logging.Logger.filter)でthreading.local()のユーザー情報をLogRecordに追加
- settings.pyのLOGGINGの設定

# Middleware
 - requestからusernameを取得。（APIだったらJWTをpharseしてユーザー情報を取得したりとか…）
 - 上記で取得したusernameをthreading.local()に設定。(後述のfilterから参照するため)
 - self.get_response(request)の後はクリアする意味でNoneを設定

```python:

import logging
import threading

local = threading.local()

class CustomAttrMiddleware:
    """
    logに出力するカスタム項目を取得するMiddleware
    """
    def __init__(self, get_response):
        self.get_response = get_response

    def __call__(self, request):
        """
        クライアントからのリクエスト時にrequestのusernameを取得して
        threading.local()に一時保存
        """
        if request.user:
            setattr(local, 'user', request.user.username)
        else:
            setattr(local, 'user', None)

        response = self.get_response(request)

        # response時はクリアしておく
        setattr(local, 'user', None)

        return response
```

# filter
 - Middlewareでthreading.local()に設定したusernameをLogRecordに設定。
 - 必ずTrueをreturnする。

```python:
class CustomAttrFilter(logging.Filter):
    """
    logにカスタム項目を出力するためのfilter
    """
    def filter(self, record):
        record.user = getattr(local, 'user', None)
        return True
```

# settings.py
 - 上記で作成したMiddlewareを追加。
 - LOGGINGのformattersにユーザーの出力形式（user=%(user)s）を追加
 - LOGGINGのfiltersに上記で作成したfilterを追加
 - 追加したfilterをLOGGINGのhandlersで使用するよう設定

```python:
MIDDLEWARE = [
     ...
    'middleware.custom_logging.CustomAttrMiddleware',
]

LOGGING = {
     ...
    'formatters': {
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s '
                      '%(process)d %(thread)d user=%(user)s %(message)s'
        },
    },
    'filters' : {
        'custom': {
            '()': 'middleware.custom_logging.CustomAttrFilter'
        },
    },
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'verbose',
            'filters': ['custom']
        },
    },
     ...
}
```

# views（動作確認用）
```python:
class LoggingExceptListView(generics.ListAPIView):
    """
    ログでexception出力を確認するためのListView
    """
    def list(self, request, *args, **kwargs):
        """
        Exceptionをraiseするだけ
        """
        raise Exception('ログ確認用')
```




# log出力結果
 - 上記の動作確認用viewsを実行
 - 以下のログの"user=CustomAttrUser"の部分

```log:
ERROR 2020-05-06 17:12:02,703 log 13516 10376 user=CustomAttrUser Internal Server Error: /sample_api/logging-exp/
Traceback (most recent call last):
  File "C:\ProgramData　...
　...  raise Exception('ログ確認用')
```

# ソース
https://github.com/ping2shi2/DRF-sample

# 参考文献
- [Django: Adding a Custom Attribute to All Log Lines](https://medium.com/@adriennedomingus/django-adding-a-custom-attribute-to-all-log-lines-439178991925)