今回は、エラー個所の特定などに必要なログの出力方法をみていきます。
まずは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 zerologgingモジュールの利用
「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.logLogの設定を別ファイルに記述
基本的な使い方
「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」ディレクトリの中にログファイルと、
最大５つ（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」が作成され、
表示に要した時間が出力されます。
今回は以上になります。
ご覧いただきありがとうございました！
コメント