1. いきさつ

ログ出力のための print と import logging はやめてほしい - Qiita

私も「うーん、なるほどなぁ」と思いながら読んでいました。
しかし、同時にこう思いました。

じゃあ、loggingってどうやって書けばいいんだろう？
タダでさえPythonのlogging苦手で時間かかるのにloggerとか無理!!

ということで、この記事を書くことにしました。
目的としては以下の通りです。

必死になってloggerと向き合った結果見つけた自分なりの理解を共有したい
みんながPythonでアプリ作るときにloggingに悩んで時間を無駄にしないでほしい

2. 結局、なんでloggingを使っちゃいけないの！？

公式ドキュメントと上のQiitaの記事を読んだ見解です。

loggingは階層構造になっています。

└── rootLogger
    ├── scanLogger
    │    ├── scanLogger.txt
    │    ├── scanLogger.html
    │    └── scanLogger.pdf
    └── anotherLogger

rootLoggerというloggerを親として、子のloggerを複数持っている（もしくは作られる）わけです。

たとえば...

urllib というmoduleは urllib というloggerを利用
apscheduler.scheduler というmoduleは apscheduler.schedulerというloggerを利用

これらのパッケージやアプリごとのloggerの元締めが rootLogger です。

bad_sample.py

import logging

logging.info("Taking log...")

とすることは、 rootLogger を直接いじることと同義なのでやめましょうということです。
class をいじるのではなく、 instanceをいじりましょうという概念と似ていますね。

3. loggingのサンプル

公式ドキュメントを見ても、サンプルを見ても書き方がイマイチわからないんですよね...汗
どこまで固定文言で、どこまで自分で変えていいのか。（自分で命名できる範囲）

というわけで、動作確認をしている構成を提示してしまいます。
困った時はコピペして使ってみてください。

なるべく、皆さんがカスタマイズしやすいようにコメントで解説も入れておきます。

3-1. (Pattern.1) Configファイルを利用

3-1-1. 実行環境

loggingのconfigファイルをtomlで書いています。
pip install tomlでtomlパッケージ参考になります。

yamlでの表記方法はこちら。

terminal

$ tree
.
├── app
│   ├── logger
│   │   ├── __init__.py
│   │   └── logger.py
│   ├── logging.config.toml
│   └── main.py
└── log
    ├── application.log
    └── error.log

$ cd app/
$ python app.py  # app/ディレクトリでこのコマンドを実行することが前提でサンプルを書いています

3-1-2. ファイル

Github サンプルコードも置いておきます。

main.py

# 前のloggerはディレクトリ。後ろのloggerはファイル。
from logger.logger import get_logger

logger = get_logger()

def main():
    logger.info("start = main()")
    # do something 
    logger.error("oops! something wrong!!")
    # do something 
    logger.info("end = main()")

if __name__ == "__main__":
    main()

logging.config.toml はconsole画面とfileにログを出力するように設定しています。

logging.config.toml

version = 1
disable_existing_loggers = false  # 他のmoduleのloggerを無効にしないようにする

[formatters]
    [formatters.basic]
    # logのフォーマットを設定。書き方の詳細は後述
    format = "%(asctime)s  [%(name)s][%(levelname)s]  %(message)s  (%(filename)s:%(module)s:%(funcName)s:%(lineno)d)" 
    datefmt = "%Y-%m-%d %H:%M:%S"

[handlers]
    [handlers.console]
    # ここでconsole出力の設定
    class = "logging.StreamHandler"  # 固定文言
    level = "DEBUG"                  # log level はお好みで
    formatter = "basic"              # formattersに記載しているlogフォーマットを選択
    stream = "ext://sys.stdout"      # 固定文言

    [handlers.file]
    class = "logging.handlers.TimedRotatingFileHandler"  # 固定文言。TimeRotatingFileHandlerの詳細は後述。注意点あり
    formatter = "basic"
    filename = "../log/application.log"                  # 相対pathで指定するなら $ python を実行するディレクトリから書く
    when = 'D'                                           # logファイルを切り替えるタイミングの単位。D = day。
    interval = 1                                         # 上でdayを選択しているので1日ごとに新規ファイル。
    backupCount = 31                                     # 上でdayを選択しているので31日分のlogファイルを保持

    [handlers.error]
    class = "logging.handlers.TimedRotatingFileHandler"
    level = "ERROR"
    formatter = "basic"
    filename = "../log/error.log"
    when = 'D'
    interval = 1
    backupCount = 31

[loggers]
    [loggers.app_name]  # app_nameはpythonから呼び出すloggerの名称。任意で命名
    level = "INFO"
    handlers = [
        "console",
        "file",
        "error",
    ]                   # 上で設定したhandlerのどれを使うかを設定
    propagate = false

[root]
level = "INFO"
handlers = [
    "console",
    "file",
    "error"
]                       # loggerの親玉rootLoggerの設定。rootLoggerもconsoleとfileに残したい

logger/__init__.py

from . import logger

logger.init_logger('logging.config.toml', 'app_name')
# 第一引数: configfile = configファイルの名称。pythonコマンドで実行するディレクトリの相対path or 絶対path
# 第二引数: loggername = configファイルで設定したloggerの名称

logger/logger.py

import os
import toml
from logging import getLogger
from logging.config import dictConfig

CONFIGFILE = "logging.config.toml"    # global変数として扱う。デフォルト値を左のようにしている。任意
LOGGERNAME = "root"                   # global変数として扱う。デフォルト値をrootにしている。任意

def init_logger(configfile, loggername):
    global CONFIGFILE 
    global LOGGERNAME
    CONFIGFILE = configfile
    LOGGERNAME = loggername
    dictConfig(toml.load(CONFIGFILE))

def get_logger():
    return getLogger(LOGGERNAME)

3-2. (Pattern.2) Pythonのdictを利用

Configファイルでのloggingと比べて、これちは柔軟性が高いです。
Configファイルでは親ディレクトリを ../ としていてOS依存が強くなります。
pythonのdictで設定すれば、 os.path.pardir で指定できます。

3-2-1. 実行環境

terminal

$ tree
.
├── app
│   ├── logger
│   │   ├── __init__.py
│   │   └── logger.py
│   └── main.py
└── log
    ├── application.log
    └── error.log

$ cd app/
$ python main.py

3-2-2. ファイル

Github サンプルコードも置いておきます。
main.py は上のmain.pyと同じです。
また、CONFIG の内容も上記の logging.config.toml と同じ内容です。

logger/__init__.py

from . import logger

logger.init_logger()

logger/logger.py

import os
from logging import getLogger
from logging.config import dictConfig

APP_NAME = os.getenv('APP_NAME', default='app_name')
CONFIG = {
    'version': 1, 
    'disable_existing_loggers': False,
    'formatters': {
        'basic': {
            'format': '%(asctime)s  [%(name)s][%(levelname)s]  %(message)s  (%(module)s:%(filename)s:%(funcName)s:%(lineno)d)', 
            'datefmt': '%Y-%m-%d %H:%M:%S'
            }
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler', 
                'level': 'DEBUG', 
                'formatter': 'basic', 
                'stream': 'ext://sys.stdout'
            }, 
            'file': {
                'class': 'logging.handlers.TimedRotatingFileHandler', 
                'formatter': 'basic', 
                'filename': os.path.join(os.path.pardir, 'log', 'application.log'), 
                'when': 'D', 
                'interval': 1, 
                'backupCount': 31
            }, 
            'error': {
                'class': 'logging.handlers.TimedRotatingFileHandler', 
                'level': 'ERROR', 
                'formatter': 'basic', 
                'filename': os.path.join(os.path.pardir, 'log', 'error.log'), 
                'when': 'D', 
                'interval': 1, 
                'backupCount': 31
            }
        }, 
        'loggers': {
            APP_NAME: {
                'level': 'INFO', 
                'handlers': [
                    'console', 
                    'file', 
                    'error'
                ], 
                'propagate': False
            }
        }, 
        'root': {
            'level': 'INFO', 
            'handlers': [
                'console', 
                'file', 
                'error'
            ] 
        }
    }

def init_logger():
    dictConfig(CONFIG)

def get_logger():
    return getLogger(APP_NAME)

3-3. 実行結果

Pattern 1. でも Pattern 2. でも出力のフォーマットは同じです。
[app_name] はlogger名。

terminal

$ cd app/
$ python main.py
2019-12-21 15:43:28  [app_name][INFO]  start = main()  (main:main.py:main:8)
2019-12-21 15:43:28  [app_name][ERROR]  oops! something wrong!!  (main:main.py:main:10)
2019-12-21 15:43:28  [app_name][INFO]  end = main()  (main:main.py:main:12)

$ cat ../log/application.log
2019-12-21 15:43:28  [app_name][INFO]  start = main()  (main:main.py:main:8)
2019-12-21 15:43:28  [app_name][ERROR]  oops! something wrong!!  (main:main.py:main:10)
2019-12-21 15:43:28  [app_name][INFO]  end = main()  (main:main.py:main:12)

$ cat ../log/error.log
2019-12-21 15:43:28  [app_name][ERROR]  oops! something wrong!!  (main:main.py:main:10)

3-4. ちょっと解説

3-4-1. TimedRotatingFileHandler

公式ドキュメントのTimedRotatingFileHandlerに「interval や when に何が設定できるか？」が書かれています！

設定した時間で新しいファイルにlogを出力します。
上記の例では 'D' つまり日毎にファイルを書き換えます。
過去のログファイルはファイル名に application.log.2019-12-21 のように日付のsurfixがつきます。

注意！
app.py が1日中起動しないようなアプリケーションでは TimedRotatingFileHandler は機能しません。
DjangoやFlaskのようなWebアプリでは有効ですが、cronなどでは正常に動作しない場合があります。

3-4-2. Format

公式ドキュメントのLogRecord 属性に各フォーマットの一覧があります。
自分なりに必要な項目をアレンジしてみましょう！

4. まとめ (Takeaways)

loggingの作り方を2種類紹介しました！それぞれを振り返りましょう！
（もう完璧という方は読み飛ばしてOK!!）

ちなみに、Takeawaysは「ポイント、要点」という意味です。
take away = 持ち帰る → 今日のプレゼンでこれだけは持ち帰ってくれ！といったニュアンスですね。

4-1. `import logging` がダメな理由

logger は rootLogger を親として、いくつも生成されている。
rootLogger → Class、 logger → instance のようなイメージ。

logging.info() はrootLoggerを直接いじることになるので、独自にloggerを作成してあげましょう。

4-2. サンプルファイル

じゃあ、具体的にどうやって作るの？

Configファイルからloggingの設定を読み込む
- tomlのサンプル
- yamlのサンプル
Pythonのdictionaryに設定を記述する
- サンプル

4-3. 注意点

disable_existing_loggers = False にしなければ gunicorn のloggerが壊れる
Configファイルを作る場合
- 相対パスのOS依存性に注意
- logフォルダの相対パスは $ python を実行するディレクトリから
TimedRotatingFileHandler
- intervalに対してプログラムの実行時間が短いと意味がない
- Django や Flask などのWebアプリ向け

5. さいごに

loggingの書き方は一概にこれが正しいというのは無いと思います。
pythonファイルに addHandler でhandlerを追加する方法もあります。
みなさんのオススメのloggingの設定方法をご教示いただけるとありがたい限りです。