python logging module 使い方メモ

# 背景
`python`を使って、スクレイピングのプログラムを作成しています。収集した情報をリアルタイムで確認したいため、ログの機能が必要です。
`python`でログを出力するときには、基本的に`logging`モジュールを使用します。

# 問題
1. `MyLogger`というクラスを作成したが、他の二つのクラスで使用した場合、同じログが何度も書き込まれる問題が発生しました。
1. 生成されたログファイル名は`.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`の生成方法も修正しました。
```python 
dfn = self.rotation_filename(self.baseFilename + "_" + time.strftime(self.suffix, timeTuple) + ".log")
```

# 実装コード
ログの出力間隔を1時間、時間のフォーマットを'H'に設定し、新しいファイルに1時間ごとにログを書き込むようにしています。
```python
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`を修正する必要があります。さらに、時間のフォーマットも対応が必要で、実装が複雑になりそうです。そのため、今回は一度この方法を見送ることにします。