Django ログ出力とMiddlewareの利用（自分用メモ）

Django自分用メモになります

今回はログ出力とMiddlewareの利用（についてまとめます

開発環境

OS:mac
エディタ：vscode
python:3.10.9
django:4.1.0

ログの出力が何の役に立つか

・実務でも利用機会が多い
・リリースしたのちにエラーの解析をする場合に非常に便利
・パフォーマンス測定ができるためどの処理に時間がかかっているのかなどをみることができる
・ミドルウェアはマニアックだが知っておくと便利な機能

loggingモジュール

01_logging_sample.py

#logging

import logging

logging.basicConfig(
    level=logging.DEBUG, filename='sample.log',
    filemode='w',format='%(asctime)s-%(process)s-%(levelname)s-%(message)s'
)
logging.debug('debug.log')
logging.info('info.log')
logging.warning('warning.log')
logging.error('エラーです')
logging.critical('critical.log')

user = 'Taro'
logging.error(f'user={user} raised error') #変数を出力することもできる

a=10
b=0

try:
    c=a/b
except Exception as e:
    logging.error(e,exc_info=True)
    #exc_info=Trueでどこでエラーが起こったのかを詳細に出すことができる

実際に出力されたログ

sample.log

2023-08-23 16:41:03,590-27228-DEBUG-debug.log
2023-08-23 16:41:03,590-27228-INFO-info.log
2023-08-23 16:41:03,590-27228-WARNING-warning.log
2023-08-23 16:41:03,591-27228-ERROR-エラーです
2023-08-23 16:41:03,591-27228-CRITICAL-critical.log
2023-08-23 16:41:03,591-27228-ERROR-user=Taro raised error
2023-08-23 16:41:03,591-27228-ERROR-division by zero
Traceback (most recent call last):
  File "/Users/kitamotoryo/Desktop/iRup/LoggingSample/01_logging_sample.py", line 22, in <module>
    c=a/b
ZeroDivisionError: division by zero

ログのファイル出力とターミナル出力（ロガーのインスタンス化。ハンドラーの設定など）

全然よくわかってない

logger=logging.getLogger(__name__)とするとファイル間で被ることなく、どのファイルのロガーかわかるので推奨らしい。
__name__ :実行しているファイルなら__main__になり、importしたモジュールならモジュール名が入る。例えばmain.pyから同階層のsub.pyをimportした場合、sub.pyにある__name__はsubになり、dirディレクトリにあるsub.pyをimportした場合、dirディレクトリにあるsub.pyの__name__はdir.subになる

02_logging_sample.py

import logging

#ロガーのインスタンス化
logger = logging.getLogger(__name__)
#loggerの閾値
logger.setLevel(logging.DEBUG)

#handler
s_handler = logging.StreamHandler() #ターミナル上にログを出力するハンドラー
f_handler = logging.FileHandler('logging2.log',encoding='utf-8') # ファイルにログを出力するハンドラー

#handler 各ハンドラーのログレベル
s_handler.setLevel(logging.DEBUG)
f_handler.setLevel(logging.ERROR)

#Formatter
s_formatter=logging.Formatter('%(name)s-%(levelname)s-%(message)s')
f_formatter=logging.Formatter('%(asctime)s-%(name)s-%(levelname)s-%(message)s')

#handlerにformattrを設定
s_handler.setFormatter(s_formatter)
f_handler.setFormatter(f_formatter)

#loggerにhandlerを設定
logger.addHandler(s_handler)
logger.addHandler(f_handler)

logger.debug('デバッグログ')
logger.info('インフォログ')
logger.warning('ワーニングログ')
logger.error('エラーログ')
logger.critical('クリティカルログ')

a=10
b=0

try:
    c=a/b
    
except Exception as e:
    logger.error(e,exc_info=True)

ターミナルに出力された結果
s_formatterにはasctimeを設定していないのファイルネームから始まっている
setLevelをDEBUGからにしているのでそれ以降すべてのログが出力されている

ターミナル

__main__-DEBUG-デバッグログ
__main__-INFO-インフォログ
__main__-WARNING-ワーニングログ
__main__-ERROR-エラーログ
__main__-CRITICAL-クリティカルログ
__main__-ERROR-division by zero
Traceback (most recent call last):
  File "/Users/kitamotoryo/Desktop/iRup/LoggingSample/02_logging_sample.py", line 37, in <module>
    c=a/b
ZeroDivisionError: division by zero

ファイルに出力されたログ

logging2.log

2023-08-25 17:03:14,832-__main__-ERROR-エラーログ
2023-08-25 17:03:14,832-__main__-CRITICAL-クリティカルログ
2023-08-25 17:05:52,754-__main__-ERROR-エラーログ
2023-08-25 17:05:52,754-__main__-CRITICAL-クリティカルログ
2023-08-25 17:05:52,755-__main__-ERROR-division by zero
Traceback (most recent call last):
  File "/Users/kitamotoryo/Desktop/iRup/LoggingSample/02_logging_sample.py", line 37, in <module>
    c=a/b
ZeroDivisionError: division by zero

設定ファイルを読み込んでログを出力する方法

こちらもあんまり理解できていないが、
要は別ファイルにlevelやhandlerの設定を書いてそれを読み込んでログを出力するというもの
logging.confi.fileConfig(fname='〇〇')で指定のファイルを読み込む

03_logging_sample.py

import logging
import logging.config

logging.config.fileConfig(fname='conf/logger.conf') #ここからファイルを読みこむ

logger=logging.getLogger(__name__)

logger.debug('デバッグログ')
logger.info('インフォログ')
logger.warning('ワーニングログ')
logger.error('エラーログ')
logger.critical('クリティカルログ')


# カスタマイズしたロガー
logger = logging.getLogger('samplelogger') #ここでのsampleloggerはqualnameで設定した名前

logger.debug('デバッグログ')
logger.info('aaaインフォログ')
logger.warning('ワーニングログ')
logger.error('エラーログ')
logger.critical('クリティカルログ')

設定ファイル

logger.conf

[loggers] #?カスタマイズしたロガーの作成も可能、sampleloggerがそれ
keys=root,samplelogger

[handlers]
keys=consolehandler,filehandler,sampleconsolehandler

[formatters]
keys=sampleformatter

[logger_root] #アンダースコアとはrootの個別のloggerの設定のこと
level=DEBUG
handlers=consolehandler,filehandler

[logger_samplelogger] #?カスタマイズしたロガー
level=DEBUG
handlers=filehandler,sampleconsolehandler
#ロガーを作成する際に用いられる名前
qualname=samplelogger 
#? 1にするとlogger_rootまで呼び出されるのでログがダブってしまうため、ここは0に？
propagate=0 



[handler_consolehandler] #こちらのアンダースコアもconsolehandlerの個別のハンドラーの設定になる
#ターミナルに出力する設定
class=StreamHandler 
#表示レベルはインフォから
level=INFO
#表示項目を設定
formatter=sampleformatter 
args=(sys.stdout,) #?そのまま表示


[handler_filehandler]
class=FileHandler
level=ERROR
formatter=sampleformatter
#'logsというフォルダのapp.logという名前でファイルを出力する
args=['logs/app.log','a','utf-8'] #'a'とはこれまでのファイルに追記するという設定。wとすると新規作成して古いのは削除する

# [handler_sampleconsolehandler] #? カスタマイズしたロガーのハンドラー？ファイルに出力してみたver
# class=FileHandler
# level=DEBUG
# formatter=sampleformatter
# args=['logs2/app2.log','a','utf-8']

[handler_sampleconsolehandler] #? カスタマイズしたロガーのハンドラー？
class=StreamHandler
level=DEBUG
formatter=sampleformatter
args=(sys.stdout,)

[formatter_sampleformatter]
format=%(asctime)s-%(name)s-%(levelname)s-%(message)s

ローテーション（ファイル容量や日によって出力するファイルを変える）

画像のように時間によって、またはファイル容量によってログの出力先を変更することができる。

04_logging_sample.py

import logging
import logging.handlers

logger = logging.getLogger(__name__)

#どういうローテーションでログファイルを作成するか決める
r_handler=logging.handlers.RotatingFileHandler(
    'logs/rotation_file.log', #出力するファイル先
    maxBytes=1000, #1kbyteで次のファイルを作成する
    backupCount=5, #バックアップをとっておく数
    encoding='utf-8'
)

t_handler=logging.handlers.TimedRotatingFileHandler(
    'logs/rotation_time_file.log',
    when = 'S', #秒のこと M(分)、D(日)
    interval=10, #10秒ごとに新規ファイルに
    backupCount=5,
    encoding='utf-8'
)

logger.setLevel(logging.DEBUG)
sample_formatter=logging.Formatter('%(name)s-%(asctime)s-%(levelname)s-%(message)s')
r_handler.setFormatter(sample_formatter)
t_handler.setFormatter(sample_formatter)
logger.addHandler(r_handler)
logger.addHandler(t_handler)

import time

for _ in range(1000):
    logger.debug('デバッグログ')
    logger.info('インフォログ')
    logger.warning('ワーニングログ')
    logger.error('エラーログ')
    logger.critical('クリティカルログ')
    time.sleep(1)

設定ファイルを読み込んでローテーションのログファイルを出力する

05_logging_sample.py

import logging
import logging.config

logging.config.fileConfig(fname='conf/rotation_logger.conf')

logger=logging.getLogger(__name__)


import time
for _ in range(1000):
    logger.debug('デバッグログ')
    logger.info('インフォログ')
    logger.warning('ワーニングログ')
    logger.error('エラーログ')
    logger.critical('クリティカルログ')
    time.sleep(1)

設定ファイル

rotation_logger.conf

[loggers]
keys=root

[handlers]
keys=rotatinghandler,timedrotatinghandler

[formatters]
keys=sampleformatter

[logger_root]
level=DEBUG
handlers=rotatinghandler,timedrotatinghandler

[handler_rotatinghandler]
class = handlers.RotatingFileHandler
level=INFO
formatter=sampleformatter
args=('logs/setting_rotation.log','a',1000,5,'utf-8') #1kbyteでバックアップ数は5の意味

[handler_timedrotatinghandler]
class=handlers.TimedRotatingFileHandler
level=ERROR
formatter=sampleformatter
args=('logs/setting_timed_rotation.log','S',5,6,'utf-8') #5秒ごとにバックアップ数は５個の意味

[formatter_sampleformatter]
format=%(asctime)s-%(name)s-%(levelname)s-%(message)s

Djangoでログを出力してみる

前回使ったClassBasedViewのプロジェクトを使って
HomeViewを読み込んだ時にターミナルにログが出力される仕組みと
画像が削除された時にターミナルとファイルにログを出力する仕組みを作っていく
手順としてはsettings.pyに設定した後views.pyとmodels.pyににlogger.debug('デバッグのメッセージなど')を
書いていく

settings.pyには
formattersと
handlersと
loggersを設定する

settings.py

LOGGING={
    'version':1,
    'disable_existing_loggers':False, #Djangoでデフォルトで定義されているロガーを無効化するかどうか
    'formatters':{
        'simple':{
            'format':'%(asctime)s %(levelname)s [%(pathname)s:%(lineno)s] %(message)s',
        }
    },
    'handlers':{
        'console_handler':{
            'level':'DEBUG',
            'class':'logging.StreamHandler',
            'formatter':'simple',
        },
        'timed_file_handler':{
            'level':'INFO',
            'class':'logging.handlers.TimedRotatingFileHandler',
            'filename':os.path.join('logs','application.log'),
            'when':'S',
            'interval':10,
            'backupCount':10,
            'formatter':'simple',
            'encoding':'utf-8',
            'delay':True, #書き込みが終了するまで処理を待つ
        }
    },
    'loggers':{
        'application-logger':{
            'handlers':['console_handler','timed_file_handler'],
            'level':'DEBUG',
            'propagate':False,
        }
    }
}

views.py

import logging

application_logger=logging.getLogger('application-logger') #ロガーのインスタンス化

        
class HomeView(TemplateView):
    template_name = 'home.html'
    
    def get_context_data(self,**kwargs):
        context = super().get_context_data(**kwargs)
        #ターミナルにログの出力
        application_logger.debug('これはデバッグメッセージです。Home画面を表示します')
        application_logger.info('これはinfoメッセージです。Home画面を表示します')
        print(kwargs)
        context['name']=kwargs.get('name') #nameはkwargsに入ってくるのでパラメータのnameを取得してコンテキストに渡す
        context['time'] = datetime.now()
        return context

models.py

#画像の削除が行われたらDBからも削除する
@receiver(post_delete,sender=Pictures)
def delete_picture(sender,instance,**kwargs):
    #instanceの中に削除されたpictureのデータが入ってるので
    if instance.picture:
        if os.path.isfile(instance.picture.path):
            os.remove(instance.picture.path)
            application_logger.info(f'{instance.picture.path}を削除しました') #追加

実際にターミナルとファイルに表示されるログ

ターミナル

#HomeViewを読み込んだ時
2023-08-25 19:36:42,478 INFO [/Users/kitamotoryo/Desktop/iRup/ClassBasedView/class_based_view/store/views.py:46] これはinfoメッセージです。Home画面を表示します
#画像を削除した時
2023-08-25 19:58:26,695 INFO [/Users/kitamotoryo/Desktop/iRup/ClassBasedView/class_based_view/store/models.py:52] /Users/kitamotoryo/Desktop/iRup/ClassBasedView/class_based_view/media/picture/hanako.jpgを削除しました

エラー用のログを出力するよう組んでみる

エラー用のハンドラーとロガーを定義して発生した時にエラー用のファイルを出力するようにする

settings.py

'handlers':{
    #追加
    'timed_error_handler':{
        'level':'ERROR', #変更
        'class':'logging.handlers.TimedRotatingFileHandler',
        'filename':os.path.join('logs','application_error.log'), #変更
        'when':'S',
        'interval':10,
        'backupCount':10,
        'formatter':'simple',
        'encoding':'utf-8',
        'delay':True, #書き込みが終了するまで処理を待つ
    },
}
'loggers':{
    #追加
    'error-logger':{
        'handlers':['timed_error_handler'],
        'level':'ERROR',
        'propagate':False,
    }
}

views.py

import logging
from django.http import Http404
error_logger=logging.getLogger('error-logger') #インスタンス化

class HomeView(TemplateView):
    template_name = 'home.html'
    
    def get_context_data(self,**kwargs):
        context = super().get_context_data(**kwargs)
        #ターミナルにログの出力
        application_logger.debug('これはデバッグメッセージです。Home画面を表示します')
        application_logger.info('これはinfoメッセージです。Home画面を表示します')
        print(kwargs)
        #追加
        if kwargs.get('name') == 'ああああ':
            error_logger.error('{}:この名前は利用できません'.format(kwargs.get('name')))
            raise Http404('この名前は使用できません')
        context['name']=kwargs.get('name') #nameはkwargsに入ってくるのでパラメータのnameを取得してコンテキストに渡す
        context['time'] = datetime.now()
        return context

ミドルウェアとは

ミドルウェアは、リクエストとレスポンス処理にフックを加え、入力と出力の値を置き換えるフレームワーク
公式
django.utils.deprecation(MiddlewareMixin)を継承したクラスを作成し、以下の３つのメゾットを追加すればOK

def process_view(self,request,view_func,view_args,view_kwargs):
    #Djangoのビューを呼び出す前に実行される
    #requestはリクエスト、view_funcはViewの関数、view_args,view_kwargsは引数
    #NoneもしくはHttpResponseオブジェクトを返す。基本はNoneを返すのが一般的。
    #Noneを返すと他のprocess_viewミドルウェアを次に実行し、適切なビューを実行する。
    #HttpResponseオブジェクトを返すと適切なビューを呼び出さない

def process_exception(self,request,exception)
    #ビューで例外が発生した場合に実行される
    #NoneもしくはHttpResponseオブジェクトを返す。Noneの場合は、他のエラーハンドリング処理を実行する
    #ミドルウェア定義の逆順に実行される（のちに解説）

def process_template_response(self,request,response):
    #ビューの実行後に呼び出される
    #ミドルウェア定義の逆順に実行される（のちに解説）
    #responseを返す

ミドルウェア定義の逆順とは
settings.pyにMIDDLEWAREを設定をするけど
MIDDLEWARE=[
自作したものを追加
]
リクエストは上から実行されるのに対して
レスポンスの場合、下から実行される

実際にMiddlewareを使ってみる

今回はprocess_viewと前回作ったapplication-loggerをつかって、
ページを読み込んだ時にログを残すという処理を作ってみる

middleware.pyというファイルを作成し、MiddlewareMixinを継承したクラスを作成する

middleware.py

import logging
from django.utils.deprecation import MiddlewareMixin

application_logger = logging.getLogger('application-logger') #前回作ったログをファイルに出力する処理をインスタンス化


class MyMiddleware(MiddlewareMixin):
    def process_view(self,request,view_func,view_args,view_kwargs): #viewを呼び出す前に実行される
        application_logger.info(request.get_full_path()+'テストです') #get_full_path：どのファイルのパスのビューが呼び出されたのかを確認できる
        # print(dir(request))

settings.pyに自作したMiddlewareを追加

settings.py

MIDDLEWARE = [
    #追加
    'class_based_view.middleware.MyMiddleware' #class_based_viewフォルダの中のmiddlewareファイルの中のMyMiddlewareを追加
]

ページを読み込んでみると下記のようにログが出力された

ログ

2023-08-26 11:28:24,023 INFO [/Users/kitamotoryo/Desktop/iRup/ClassBasedView/class_based_view/class_based_view/middleware.py:9] /store/list_books/テストです

エラー用のログの出力をMiddlewareを使って一括で定義（個別で定義する必要がない）

def process_exceptionと前回作成したerror-loggerを使って、
エラーが出た時はmiddleware.pyに設定した記述で一括で定義して、views.pyなどでいちいち
個別に設定しなくてもいいようなMiddlewareを作成する

middleware.py

error_logger = logging.getLogger('error-logger') #前回作ったものをインスタンス化

class MyMiddleware(MiddlewareMixin):
#エラーログをMiddlewareをつかって一括に定義（views.pyでいちいち定義する必要がない） 
    def process_exception(self,request,exception):
        error_logger.error(exception,exc_info=True) #exc_info=True：スタックトレースも一緒に出力

これだけで完了。エラーが起きればapplication_error.logにこのように出力される

application_error.log

2023-08-26 11:37:54,348 ERROR [/Users/kitamotoryo/Desktop/iRup/ClassBasedView/class_based_view/class_based_view/middleware.py:14] この名前は使用できません
Traceback (most recent call last):
  File "/Users/kitamotoryo/anaconda3/envs/djangoenv/lib/python3.10/site-packages/django/core/handlers/base.py", line 197, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/Users/kitamotoryo/anaconda3/envs/djangoenv/lib/python3.10/site-packages/django/views/generic/base.py", line 103, in view
    return self.dispatch(request, *args, **kwargs)
  File "/Users/kitamotoryo/anaconda3/envs/djangoenv/lib/python3.10/site-packages/django/views/generic/base.py", line 142, in dispatch
    return handler(request, *args, **kwargs)
  File "/Users/kitamotoryo/anaconda3/envs/djangoenv/lib/python3.10/site-packages/django/views/generic/base.py", line 216, in get
    context = self.get_context_data(**kwargs)
  File "/Users/kitamotoryo/Desktop/iRup/ClassBasedView/class_based_view/store/views.py", line 53, in get_context_data
    raise Http404('この名前は使用できません')
django.http.response.Http404: この名前は使用できません

パフォーマンスを測定するミドルウェアを作成

標準ライブラリのtimeを使ったパフォーマンスを測定するクラスを新たに作成する
ビューの実行前と実行後に呼び出される関数を使って、呼び出し時間の差分を測定する

middleware.py

import time
performance_logger=logging.getLogger('performance-logger')

#パフォーマンスを測定するMiddleware    
#ビューの実行前と実行後に呼び出される関数を使って、呼び出し時間の差分を測定する  
class PerformanceMiddleware(MiddlewareMixin):
    def process_view(self,request,view_funce,view_args,view_kwargs):
        start_time = time.time() #現在時刻の取得
        request.start_time = start_time #requestのstart_timeというプロパティに追加する
        
    def process_template_response(self,request,response): #ビューの実行後に呼び出される
        response_time = time.time()-request.start_time #現在時刻の取得と呼び出し前の時間の差を測る
        performance_logger.info(f'{request.get_full_path()}:{response_time}s')
        return response

settings.pyに新たなhandlersとloggersを追加
MIDDLEWAREに作成したクラスを追加するが一番上に書くことが重要
リクエストは上から実行、レスポンスは下から実行されるため、
測定開始時とビューを表示し終えた差分を測れるようになる

settings.py

MIDDLEWARE = [
    'class_based_view.middleware.PerformanceMiddleware', #パフォーマンスの測定なので一番上に書く、リクエストが来て測定開始して、レスポンスが下から実行されていって最後に測定時間を拾うため
    'django.middleware.security.SecurityMiddleware',
    'django.contrib.sessions.middleware.SessionMiddleware',
    'django.middleware.common.CommonMiddleware',
    'django.middleware.csrf.CsrfViewMiddleware',
    'django.contrib.auth.middleware.AuthenticationMiddleware',
    'django.contrib.messages.middleware.MessageMiddleware',
    'django.middleware.clickjacking.XFrameOptionsMiddleware',
    #追加
    'class_based_view.middleware.MyMiddleware' #middlewareファイルの中のMyMiddlewareを追加
]
#
#LOGGING略
'handler':{
    'timed_performance_handler':{
        'level':'INFO', #変更
        'class':'logging.handlers.TimedRotatingFileHandler',
        'filename':os.path.join('logs','application_performance.log'), #変更
        'when':'S',
        'interval':10,
        'backupCount':10,
        'formatter':'simple',
        'encoding':'utf-8',
        'delay':True, #書き込みが終了するまで処理を待つ
    },   
},
'loggers':{
#追加
    'performance-logger':{
        'handlers':['timed_performance_handler'],
        'level':'INFO',
        'propagate':False,
    },
}

実際に作成されるログ：application_performance.log

2023-08-26 12:09:06,494 INFO [/Users/kitamotoryo/Desktop/iRup/ClassBasedView/class_based_view/class_based_view/middleware.py:27] /store/edit_book/9:0.005533933639526367s
2023-08-26 12:09:10,213 INFO [/Users/kitamotoryo/Desktop/iRup/ClassBasedView/class_based_view/class_based_view/middleware.py:27] /store/delete_book/9:0.001934051513671875s
2023-08-26 12:09:11,429 INFO [/Users/kitamotoryo/Desktop/iRup/ClassBasedView/class_based_view/class_based_view/middleware.py:27] /store/list_books/:0.003361940383911133s
2023-08-26 12:09:13,459 INFO [/Users/kitamotoryo/Desktop/iRup/ClassBasedView/class_based_view/class_based_view/middleware.py:27] /store/detail_book/8:0.0032987594604492188s