背景
pythonを使って、スクレイピングのプログラムを作成しています。収集した情報をリアルタイムで確認したいため、ログの機能が必要です。
pythonでログを出力するときには、基本的にloggingモジュールを使用します。
問題
-
MyLoggerというクラスを作成したが、他の二つのクラスで使用した場合、同じログが何度も書き込まれる問題が発生しました。 - 生成されたログファイル名は
.log時間、想定していた時間.logのフォーマットと異なっていました。
問題の解決
問題1を解決するため、lockとシングルトンパターンを使用しました。
my_logger.py
class MyLogger:
_instance = None
_lock = threading.Lock()
def __new__(cls, *args, **kwargs):
with cls._lock:
if cls._instance is None:
cls._instance = super().__new__(cls)
cls._instance.__init_log(*args, **kwargs)
return cls._instance
def __init_log(self, log_filename="link", log_level=logging.DEBUG, log_folder='log'):
# 省略
def create_logger(self):
# 省略
def debug(self, message):
with self.lock:
self.logger.debug(message)
"""
省略
"""
問題2を解決するため、TimedRotatingFileHandlerのdoRolloverというメソッドをオーバーライドしました。
また、dfnの生成方法も修正しました。
dfn = self.rotation_filename(self.baseFilename + "_" + time.strftime(self.suffix, timeTuple) + ".log")
実装コード
ログの出力間隔を1時間、時間のフォーマットを'H'に設定し、新しいファイルに1時間ごとにログを書き込むようにしています。
self.file_handler = CustomTimedRotatingFileHandler(log_file_name, when='H', interval=1, backupCount=24)
以下は完全なクラスコードです。
my_logger.py
import logging
import os
import threading
from logging.handlers import TimedRotatingFileHandler
from filelock import FileLock
import time
class CustomTimedRotatingFileHandler(TimedRotatingFileHandler):
def __init__(self, filename, when='H', interval=1, backupCount=0, encoding=None, delay=False, utc=False, atTime=None):
super(CustomTimedRotatingFileHandler, self).__init__(filename, when, interval, backupCount, encoding, delay, utc, atTime)
def doRollover(self):
"""
do a rollover; in this case, a date/time stamp is appended to the filename
when the rollover happens. However, you want the file to be named for the
start of the interval, not the current time. If there is a backup count,
then we have to get a list of matching filenames, sort them and remove
the one with the oldest suffix.
"""
if self.stream:
self.stream.close()
self.stream = None
# get the time that this sequence started at and make it a TimeTuple
currentTime = int(time.time())
dstNow = time.localtime(currentTime)[-1]
t = self.rolloverAt - self.interval
if self.utc:
timeTuple = time.gmtime(t)
else:
timeTuple = time.localtime(t)
dstThen = timeTuple[-1]
if dstNow != dstThen:
if dstNow:
addend = 3600
else:
addend = -3600
timeTuple = time.localtime(t + addend)
dfn = self.rotation_filename(self.baseFilename + "_" + time.strftime(self.suffix, timeTuple) + ".log")
if os.path.exists(dfn):
os.remove(dfn)
self.rotate(self.baseFilename, dfn)
if self.backupCount > 0:
for s in self.getFilesToDelete():
os.remove(s)
if not self.delay:
self.stream = self._open()
newRolloverAt = self.computeRollover(currentTime)
while newRolloverAt <= currentTime:
newRolloverAt = newRolloverAt + self.interval
if self.when == 'MIDNIGHT' or self.when.startswith('W'):
newRolloverAt = self.computeRollover(newRolloverAt)
self.rolloverAt = newRolloverAt
class MyLogger:
_instance = None
_lock = threading.Lock()
def __new__(cls, *args, **kwargs):
with cls._lock:
if cls._instance is None:
cls._instance = super().__new__(cls)
cls._instance.__init_log(*args, **kwargs)
return cls._instance
def __init_log(self, log_filename="link", log_level=logging.DEBUG, log_folder='log'):
self.log_folder = log_folder
self.log_filename = log_filename
self.log_level = log_level
self.lock = threading.Lock()
lock_file_path = os.path.join(log_folder, ".lock")
with FileLock(lock_file_path):
self.create_logger()
def create_logger(self):
if not os.path.exists(self.log_folder):
os.mkdir(self.log_folder)
self.logger = logging.getLogger(__name__)
self.logger.setLevel(self.log_level)
log_file_name = os.path.join(self.log_folder, f"{self.log_filename}.log")
self.file_handler = CustomTimedRotatingFileHandler(log_file_name, when='H', interval=1, backupCount=24)
self.file_handler.setLevel(self.log_level)
self.file_handler.suffix = "%Y-%m-%d_%H"
formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
self.file_handler.setFormatter(formatter)
self.logger.addHandler(self.file_handler)
def debug(self, message):
with self.lock:
self.logger.debug(message)
def info(self, message):
with self.lock:
self.logger.info(message)
def warning(self, message):
with self.lock:
self.logger.warning(message)
def error(self, message):
with self.lock:
self.logger.error(message)
def critical(self, message):
with self.lock:
self.logger.critical(message)
def close(self):
if self.file_handler is not None:
self.file_handler.close()
self.logger.removeHandler(self.file_handler)
使い方
ログを出力したいクラスのコンストラクタの中に、以下のコードを追加すれば、使用できます。
sample.py
from my_logger import MyLogger
class Sample:
def __init__(self):
self.logger = MyLogger()
"""
Write your code here
"""
def output_log(self):
self.logger.debug("this is a debug message.")
気になる点
ログの生成方法が自分の想定と違います。
loggingモジュールによるログ生成のタイミングは、正時ではなく、プログラム実行後1時間が経過した時点で行われます。
また、ログファイルへ書き込む際に、まずは basefile（例：link.log）に書き込み、1時間経過後にそのファイルを「link_時間.log」にリネームして、再び link.log に書き込むという方法です。
正時に新しいファイルを作成し、そこに書き込む方法を実現するには、TimedRotatingFileHandlerのdoRolloverを修正する必要があります。さらに、時間のフォーマットも対応が必要で、実装が複雑になりそうです。そのため、今回は一度この方法を見送ることにします。