毎度忘れるpytyhon loggerをライブラリ化する

取り敢えずpprintでデバッグ的な事はやるとして
運用に乗せ始めたときに logファイルに書き出すようにせねば、、で毎回「どうだったっけ？」となるのがpythonのloggeer。ほんとに毎回。

ということで簡単に扱えるよう整理してライブラリ化してみました。
ほとんどはdictConfigでカバーするということになりました。

## dictConfigとは 
（公式）https://docs.python.org/ja/3/library/logging.handlers.html
loggerの各種めんどい定義をコード内で記述せず、定義ファイルとして外持ちさせる仕組みです。

サンプルを元にちょっとだけカスタムした定義ファイルです。
日次ローテション、2W保持にしています。

```
{
  "version": 1,
  "disable_existing_loggers": false,
  "root": {
    "level": "DEBUG",
    "handlers": [
      "consoleHandler",
      "logFileHandler"
    ]
  },
  "handlers": {
    "consoleHandler": {
      "class": "logging.StreamHandler",
      "level": "INFO",
      "formatter": "consoleFormatter",
      "stream": "ext://sys.stdout"
    },
    "logFileHandler": {
      "class": "logging.handlers.TimedRotatingFileHandler",
      "level": "DEBUG",
      "formatter": "logFileFormatter",
      "filename": "/tmp/log/app.log",
      "when": "D",
      "backupCount": 14,
      "encoding": "utf-8"
    }
  },
  "formatters": {
    "consoleFormatter": {
      "format": "[%(levelname)-8s]%(name)s:%(lineno)s - %(message)s"
    },
    "logFileFormatter": {
      "format": "%(asctime)s[%(levelname)-8s]%(filename)s::%(name)s:%(lineno)s - %(message)s"
    }
  }
}
```

## ログ出力
よさげです。
### コンソール出力
```
[INFO    ]__main__:13 - This is a info message
[INFO    ]__main__:13 - This is a info message
[INFO    ]__main__:13 - This is a info message
[INFO    ]__main__:13 - This is a info message
```
### Debugログファイル出力
```
2021-02-12 08:55:22,584[INFO    ]test_logger.py::__main__:13 - This is a info message
2021-02-12 08:55:22,584[DEBUG   ]test_logger.py::__main__:14 - This is a debug message
2021-02-12 08:55:23,635[INFO    ]test_logger.py::__main__:13 - This is a info message
2021-02-12 08:55:23,635[DEBUG   ]test_logger.py::__main__:14 - This is a debug message
```

## 利用者側の負担を減らす
dictConfigへ定義を寄せることで見通しが良くなりそうです。
でもいちいち利用者側がファイルの存在とか読み込み処理を書くのがめんどいので
ライブラリ化します。

```python

from logging import config
from logging import Logger
from json import load
from pathlib import Path
import sys

def ConfigLogger(logger):
    '''dictConfig定義ファイルロード

        dictConfigを利用してlogger定義ファイルを読見込み
        loggerオブジェクトをカスタムする

        Args:
            logger   呼出側でのgetLogger(__name__)実行結果オブジェクト

        Return:
            logger dictConfig結果を反映した状態のlogger

        Raises:
            TypeError: 引数型の不備
            FileNotFoundError: 定義ファイル存在しない

        Examples:
            >>> logger = KaisuiUtilsLoggingHelper.ConfigLogger(getLogger(__name__))
            >>> logger.info('[INFO] This is test message infomartion')

        Note:

    '''

    # loggin定義 json Path 
    LIBPATH = "/home/satoshi/work/jenkins_script/app/python/env/logging_TimedRotate.json"
    #LIBPATH = "/home/satoshi/work/jenkins_script/app/python/env/logging_TimedRotate.jsonx"
    #LIBPATH = "/home/satoshi/work/jenkins_script/app/python/env/logging_Rotate.json"
    #LIBPATH = "/home/satoshi/work/jenkins_script/app/python/env/logging.json"

    # 引数チェック 型    
    if not isinstance(logger, Logger):
        print(f'引数：loggerの型が正しくありません Logger <-> {type(logger)}')
        raise TypeError

    # dictConfigファイル存在チェック
    filepath = Path(f'{LIBPATH}')
    if not filepath.exists():
        print(f'指定したdictConfigファイルが存在しません: {LIBPATH}')
        raise FileNotFoundError

    # dictConfigを使用してlogger設定定義を取り込む
    with open(f'{str(filepath)}', "r", encoding="utf-8") as f:
      config.dictConfig(load(f))

    return logger
```

## 呼出側
簡単になります！

```python

import sys
from logging import getLogger
from logging import config
from logging import handlers
from json import load

sys.path.append('/home/satoshi/work/jenkins_script/app/python/lib')
from KaisuiUtilsLoggingHelper import ConfigLogger

# logger生成
logger = ConfigLogger(getLogger(__name__))

# 実行
logger.info('This is a info message')
logger.debug('This is a debug message')
```


## ついでにtimer系も作ってみました（追伸）

よくある実行開始から終了までをロギングするヤツです。


```python
@contextmanager
def timer(title, logger):
    '''実行時間をロギングする

        dictConfigを利用してlogger定義ファイルを読見込み
        loggerオブジェクトをカスタムする

        Args:
            title: str    テストイベント名
            logger:Logger 呼出側でのgetLogger(__name__)実行結果オブジェクト

        Return:
            logger dictConfig結果を反映した状態のlogger

        Raises:
            TypeError: 引数型の不備
            FileNotFoundError: 定義ファイル存在しない

        Examples:
            >>> from KaisuiUtilsLoggingHelper import ConfigLogger
            >>> from KaisuiUtilsLoggingHelper import timer
            >>> logger = ConfigLogger(getLogger(__name__))
            >>> 
            >>> with timer('test', logger):
            >>>     sleep(5)

        Note:

    '''
    # 引数チェック 型    
    if not isinstance(title, str):
        print(f'引数：titleの型が正しくありません str <-> {type(title)}')
        raise TypeError
    
    # 引数チェック 型    
    if not isinstance(logger, Logger):
        print(f'引数：loggerの型が正しくありません Logger <-> {type(logger)}')
        raise TypeError

    # 引数受け渡し
    values = title

    # 本体テストスタート
    # loggerとは別に強制表示する
    print(f'---------------- {values} start ---------------')

    t0 = time.time()
    logger.info(f'{title} {datetime.now()} - start')
    # 本体テスト終了待ち
    ## try〜except〜finallyを組み込むこと
    try:
        yield values
    except Exception as e:
        logger.info(f'本体処理でエラーが発生: {e}')
        raise
    finally:
        # 本体テスト終了
        logger.info(f'{title} {datetime.now()} - end')
        # テスト実行時間算出
        logger.info(f'{title} - done in {time.time() - t0:.0f}s')

        # loggerとは別に強制表示する
        print(f'---------------- {values} end   ---------------')
```

実行側はこうなります

```python

import sys 
from logging import getLogger
from time import sleep

sys.path.append('/home/satoshi/work/jenkins_script/app/python/lib')

from KaisuiUtilsLoggingHelper import ConfigLogger
from KaisuiUtilsLoggingHelper import timer

logger = ConfigLogger(getLogger(__name__))

with timer('test',logger) as p:
    # テストイベント実行
    sleep(5)

```

結果

```
---------------- test start ---------------
[INFO    ]__main__:126 - test 2021-02-12 19:25:04.557872 - start
[INFO    ]__main__:136 - test 2021-02-12 19:25:09.563192 - end
[INFO    ]__main__:138 - test - done in 5s
---------------- test end   ---------------

```