【Django3 入門】ログの出力方法

Django

今回は、エラー個所の特定などに必要なログの出力方法をみていきます。

まずはpythonでのログ出力の扱い方を確認し、それをDjangoで用いる方法を紹介します。

pythonでログの出力

基本的な使い方

ログレベル

critical重大なエラー
errorエラー
warning警告
info情報
debugデバッグ情報


適当な作業ディレクトリに「logging_sample」というディレクトリと、その中に「logging_sample01.py」というファイルをつくります。

import logging

logging.basicConfig(
    level=logging.ERROR, # ここで指定したレベル以上のログが出力される
    filename='logging_sample/sample01.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('error.log')
logging.critical('critical.log')


このファイルを実行すると、「logging_sample」の中に「sample01.log」が作られ、
以下のようなログが出力されます。

2021-09-29 10:47:56,769-58232-ERROR-error.log
2021-09-29 10:47:56,770-58232-CRITICAL-critical.log

ログに変数を利用

.
.
.
user = 'taro'
logging.error(f'user={user} raised error')

実行↓

.
.
.
2021-09-29 10:58:43,908-16452-ERROR-user=taro raised error

エラーの発生場所の出力

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

実行↓

.
.
.
2021-09-29 11:01:00,810-61912-ERROR-division by zero
Traceback (most recent call last):
  File "ファイルのパス", line 23, in <module>
    c = a / b
ZeroDivisionError: division by zero

loggingモジュールの利用

「logging_sample02.py」の作成、実行

import logging

logger = logging.getLogger(__name__)

# loggerの閾値
logger.setLevel(logging.DEBUG)

# handler
s_handler = logging.StreamHandler() # コマンドラインに出力
f_handler = logging.FileHandler('logging_sample/sample02.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にFormatterを設定
s_handler.setFormatter(s_formatter)
f_handler.setFormatter(f_formatter)

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

logger.debug('debug.log')
logger.info('info.log')
logger.warning('warning.log')
logger.error('error.log')
logger.critical('critical.log')


コマンドラインへの出力

__main__-DEBUG-debug.log
__main__-INFO-info.log
__main__-WARNING-warning.log
__main__-ERROR-error.log
__main__-CRITICAL-critical.log


ファイルへの出力

2021-09-29 15:35:55,717-__main__-ERROR-error.log
2021-09-29 15:35:55,718-__main__-CRITICAL-critical.log

Logの設定を別ファイルに記述

基本的な使い方

「conf」ディレクトリと、その中に「logger.conf」を作成

[loggers]
keys=root

[handlers]
keys=consolehandler, filehandler

[formatters]
keys=sampleformatter

[logger_root]
level=DEBUG
handlers=consolehandler, filehandler

[handler_consolehandler]
class=StreamHandler
level=INFO
formatter=sampleformatter
args=(sys.stdout,)

[handler_filehandler]
class=Filehandler
level=ERROR
formatter=sampleformatter
args=['logs/app.log', 'a', 'utf-8']

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


「/」に「logs」ディレクトリを作成

「logging_sample03.py」の作成、実行

import logging
import logging.config

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

logger = logging.getLogger(__name__)

logger.debug('debug.log')
logger.info('info.log')
logger.warning('warning.log')
logger.error('error.log')
logger.critical('critical.log')

コマンドラインへの出力

2021-09-29 16:02:19,257-62140-INFO-info.log
2021-09-29 16:02:19,257-62140-WARNING-warning.log
2021-09-29 16:02:19,258-62140-ERROR-error.log
2021-09-29 16:02:19,258-62140-CRITICAL-critical.log


ファイルへの出力

2021-09-29 16:02:19,258-62140-ERROR-error.log
2021-09-29 16:02:19,258-62140-CRITICAL-critical.log

カスタマイズしたloggerの利用

「samplelogger」と「sampleconsolehandler」という、自分でロガーとハンドラーを定義して利用します。

[loggers]
keys=root, samplelogger

[handlers]
keys=consolehandler, filehandler, sampleconsolehandler

[formatters]
keys=sampleformatter

[logger_root]
level=DEBUG
handlers=consolehandler, filehandler

[logger_samplelogger]
level=DEBUG
handlers=filehandler, sampleconsolehandler
qualname=samplelogger
propagate=0

[handler_consolehandler]
class=StreamHandler
level=INFO
formatter=sampleformatter
args=(sys.stdout,)

[handler_filehandler]
class=FileHandler
level=ERROR
formatter=sampleformatter
args=['logs/app.log', 'a', 'utf-8']

[handler_sampleconsolehandler]
class=StreamHandler
level=DEBUG
formatter=sampleformatter
args=(sys.stdout,)

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


「logging_sample03.py」の修正、実行

import logging
import logging.config

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

# logger = logging.getLogger(__name__)

# logger.debug('debug.log')
# logger.info('info.log')
# logger.warning('warning.log')
# logger.error('error.log')
# logger.critical('critical.log')

logger = logging.getLogger('samplelogger')
logger.debug('debug.log')
logger.info('info.log')
logger.warning('warning.log')
logger.error('error.log')
logger.critical('critical.log')


コマンドラインへの出力

2021-09-29 16:18:50,146-34724-DEBUG-debug.log
2021-09-29 16:18:50,147-34724-INFO-info.log
2021-09-29 16:18:50,147-34724-WARNING-warning.log
2021-09-29 16:18:50,147-34724-ERROR-error.log
2021-09-29 16:18:50,148-34724-CRITICAL-critical.log

ログローテーション

基本的な使い方

ファイルへのログ出力量が一定数を超えると、自動的に別ファイルへ書き込むようにします。


「logging_sample04.py」の作成、実行

import logging
import logging.handlers

logger = logging.getLogger(__name__)

r_handler = logging.handlers.RotatingFileHandler(
    'logs/rotation_file.log',
    maxBytes=1000,
    backupCount=5, # バックアップ用のログファイルの数
    encoding='utf-8'
)
t_handler = logging.handlers.TimedRotatingFileHandler(
    'logs/rotation_time_file.log',
    when='S', # 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)
logger.addHandler(r_handler)
logger.addHandler(t_handler)

import time

for _ in range(1000):
    logger.debug('debug.log')
    logger.info('info.log')
    logger.warning('warning.log')
    logger.error('error.log')
    logger.critical('critical.log')
    time.sleep(1)


「logs」ディレクトリの中にログファイルと、
最大5つ(backupCountで指定)のバックアップファイルが生成されます。

バックアップファイルは古いものから削除されていきます。

設定を別ファイルに記述

「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')

[handler_timedrotatinghandler]
class=handlers.TimedRotatingFileHandler
level=ERROR
formatter=sampleformatter
args=('logs/setting_timed_rotation.log', 'S', 10, 5, 'utf-8') # 10秒間隔で最大5つバックアップファイルを作成

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


「logging_sample05.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('debug.log')
    logger.info('info.log')
    logger.warning('warning.log')
    logger.error('error.log')
    logger.critical('critical.log')
    time.sleep(1)


ログとバックアップファイルが生成されます。

Djangoでログの出力

基本的な使い方

「settings.py」の修正

.
.
.
LOGGING = {
    'version': 1,
    'disable_existing': False,
    'formatters': {
        'sample': {
            'format': '%(asctime)s %(levelname)s [%(pathname)s:%(lineno)s] %(message)s',
        }
    },
    'handlers': {
        'console_handler': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'sample'
        }
    },
    'loggers': {
        'application-logger': {
            'handlers': ['console_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画面を表示')
        context['name'] = kwargs.get('name')
        context['time'] = datetime.now()
        return context
.
.
.


ホーム画面にアクセスすると、コマンドラインに「Home画面を表示」と出力されます。

ログファイルに出力

「settings.py」の修正

.
.
.
'handlers': {
    'console_handler': {
        'level': 'DEBUG',
        'class': 'logging.StreamHandler',
        'formatter': 'sample'
    },
    'timed_file_handler': {
        'level': 'INFO',
        'class': 'logging.handlers.TimedRotatingFileHandler',
        'filename': os.path.join('logs', 'application.log'),
        'when': 'S',
        'interval': 10,
        'backupCount': 10,
        'formatter': 'sample',
        'encoding': 'utf-8',
        'delay': True,
    }
},
'loggers': {
    'application-logger': {
        'handlers': ['console_handler', 'timed_file_handler',],
.
.
.


「models.py」の修正

.
.
.
import logging

application_logger = logging.getLogger('application-logger')
.
.
.
@receiver(models.signals.post_delete, sender=Picture)
def delete_picture(sender, instance, **kwargs):
    if instance.picture:
        if os.path.isfile(instance.picture.path):
            os.remove(instance.picture.path)
            application_logger.info(f'{instance.picture.path}を削除しました')


「manage.py」と同階層に「logs」ディレクトリを作成

編集画面から画像を削除


すると、コマンドラインにログが出力され、
「logs」ディレクトリの中に「application.log」というファイルが作成されます。

エラーログ

「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': 'sample',
        'encoding': 'utf-8',
        'delay': True,
    }
},
'loggers': {
.
.
.
    'error-logger': {
        'handlers': ['timed_error_handler', ],
        'level': 'ERROR',
        'propagate': False
    }
.
.
.

「views.py」の修正

.
.
.
from django.http import Http404

application_logger = logging.getLogger('application-logger')
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画面を表示')
        if kwargs.get('name') == 'aaa':
            error_logger.error('この名前は使用できません')
            raise Http404('この名前は使用できません')
        context['name'] = kwargs.get('name')
        context['time'] = datetime.now()
        return context
.
.
.


特定の条件(この例では「kwargs.get(‘name’) == ‘aaa’」)の場合、
「logs」ディレクトリの中に「application_error.log」が作成されます。

ミドルウェア

「settings.py」の「MIDDLEWARE」に設定されています。

リクエストの場合は上から、
レスポンスの場合は下から実行されます。

MIDDLEWARE = [
    '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',
]

基本的な使い方

プロジェクトディレクトリに「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())
        


「settings.py」の修正

.
.
.
MIDDLEWARE = [
.
.
.
    'プロジェクト名.middleware.MyMiddleware'
]
.
.
.


ブラウザで任意のパスにアクセスすると、コマンドラインにそのパスがログとして表示され、
「logs」ディレクトリの中にファイルが作成されます。

エラーログの出力

「middleware.py」の修正

import logging
from django.utils.deprecation import MiddlewareMixin

application_logger = logging.getLogger('application-logger')
error_logger = logging.getLogger('error-logger')

class MyMiddleware(MiddlewareMixin):
    def process_view(self, request, view_func, view_args, view_kwargs): # viewを呼び出す前に実行
        application_logger.info(request.get_full_path())

    def process_exception(self, request, exception):
        error_logger.error(exception, exc_info=True)


viewでのエラーログ出力を無効

.
.
.
class HomeView(TemplateView):
    template_name = 'home.html'

    def get_context_data(self, **kwargs):
        context = super().get_context_data(**kwargs)
        application_logger.debug('Home画面を表示')
        if kwargs.get('name') == 'aaa':
            # error_logger.error('この名前は使用できません')
            raise Http404('この名前は使用できません')
        context['name'] = kwargs.get('name')
        context['time'] = datetime.now()
        return context
.
.
.


特定の条件(この例では「kwargs.get(‘name’) == ‘aaa’」)の場合、
「logs」ディレクトリの中に「application_error.log」が作成されます。

パフォーマンスの出力

「settings.py」の修正

.
.
.
'handlers': {
.
.
.
    'timed_performance_handler': {
        'level': 'INFO',
        'class': 'logging.handlers.TimedRotatingFileHandler',
        'filename': os.path.join('logs', 'application_performance.log'),
        'when': 'S',
        'interval': 10,
        'backupCount': 10,
        'formatter': 'sample',
        'encoding': 'utf-8',
        'delay': True,
    }
},
'loggers': {
.
.
.
    'performance-logger': {
        'handlers': ['timed_performance_handler', ],
        'level': 'INFO',
        'propagate': False
    },
}
.
.
.


「middleware.py」の修正

import logging
from django.utils.deprecation import MiddlewareMixin
import time

application_logger = logging.getLogger('application-logger')
error_logger = logging.getLogger('error-logger')
performance_logger = logging.getLogger('performance-logger')

class MyMiddleware(MiddlewareMixin):
    def process_view(self, request, view_func, view_args, view_kwargs): # viewを呼び出す前に実行
        application_logger.info(request.get_full_path())

    def process_exception(self, request, exception):
        error_logger.error(exception, exc_info=True)

class PerformanceMiddleware(MiddlewareMixin):
    def process_view(self, request, view_func, view_args, view_kwargs):
        start_time = time.time()
        request.start_time = start_time

    def process_template_response(self, request, response):# viewが呼び出された後に実行
        response_time = time.time() - request.start_time
        performance_logger.info(f'{request.get_full_path()}: {response_time}ms')
        return response


「settings.py」の修正

.
.
.
MIDDLEWARE = [
    'プロジェクト名.middleware.PerformanceMiddleware',
.
.
.
]
.
.
.


ブラウザで任意のパスにアクセスすると「logs」ディレクトリの中に「application_performance.log」が作成され、
表示に要した時間が出力されます。





今回は以上になります。
ご覧いただきありがとうございました!

コメント

コンタクトフォーム

    タイトルとURLをコピーしました