Pythonである程度しっかり開発することになり、ログ出力について学習しました。2時間くらいで終わらせようと甘く見ていたら、理解に1日以上かけてしまいました。そのくらいprintの次ステップは単純ではなかったです。
記事「ログ出力のための print と import logging はやめてほしい」を読み、全てはないですがエッセンスは理解できたと考えています。
他にも以下の記事は結構読みました。

GitHubに今回のコードをのせています。

はじめに - `print`でもいい場合と卒業する場合

printは簡単にメッセージ出力できるのが良い点です。loggingパッケージを知った今でも、Jupyterなどではprintを使おうと考えていますし、開発・検証中はprintは大きな武器です。
以下の点に当てはまる場合、printを卒業してloggingパッケージを使うのが適切かと考えています。

自動的にタイムスタンプや出力元プログラム位置等の情報を付加したい
ログ内容の統一性を持たせたい
ログの重要度を識別したい
コンソールとログファイルに同じログを出力したい

loggingパッケージを使うことで、以下のようにログ出力のコマンドを少し書くだけで

logger.info('Process Start!')
logger.debug('debug')
logger.info('info')
logger.warning('warning')
logger.error('error')
logger.info('Process End!')

タイムスタンプや出力元プログラム位置など、以下のようなログ出力をすることが出来ます
ディープラーニングのような時間がかかる処理時に、タイムスタンプを出してくれるのは後で確認するときに嬉しいです。

2019-07-02 23:29:26,518 __main__:25 main [INFO]: Process Start!
2019-07-02 23:29:26,519 __main__:26 main [DEBUG]: debug
2019-07-02 23:29:26,519 __main__:27 main [INFO]: info
2019-07-02 23:29:26,519 __main__:28 main [WARNING]: warning
2019-07-02 23:29:26,519 __main__:29 main [ERROR]: error
2019-07-02 23:29:26,519 __main__:30 main [INFO]: Process End!

そして、コンソールに出力するだけでなく、ファイルにも同じ/違った内容を書き込んでくれます。

loggingパッケージの基本

まずは、私が学んだloggingパッケージ基本の3項目です。

間違えにくいようにfrom logging import getLoggerを使う(propagate系注意点あり)
Loggerインスタンスを使う。ルートを汚さない。
環境設定ファイル(json/YAML)で設定する(propagate系注意点あり, iniは古い)
str.format/stringTemplateにする

1と2 : `from logging import getLogger`を使い、`Logger`インスタンスを使う

まずimportは以下のように書きます。logger.info('message')とlogging.info('message')が似ているので、間違ってloggingを使わないように必要なモジュールのみをimportさせます。

いい例(import)

from logging import getLogger
logger = getLogger(__name__)
logger.info('message')

悪い例(import)

import logging
logging.info('message')

そもそもloggingでなくloggerを使う理由なのですが、loggingを使ってしまうとルートを使った出力となってしまうからです。詳しくは記事「ログ出力のための print と import logging はやめてほしい」を参照ください(詳しすぎるほど書いてあります)。

3. 環境設定ファイルを使う

3.1. 環境設定ファイル(JSON)

こんなjsonファイルを作って、loggingの出力方法を定義しておきます。"disable_existing_loggers"の値は"false"にすることをおすすめします。 理由は記事「Python: ロギング設定をファイルから読み込むときの注意点」

log_config.json

{
    "version": 1,
    "disable_existing_loggers": false,
    "formatters": {
        "simple": {
            "format": "%(asctime)s %(name)s:%(lineno)s %(funcName)s [%(levelname)s]: %(message)s"
        }
    },

    "handlers": {
        "consoleHandler": {
            "class": "logging.StreamHandler",
            "level": "INFO",
            "formatter": "simple",
            "stream": "ext://sys.stdout"
        },
        "fileHandler": {
            "class": "logging.FileHandler",
            "level": "INFO",
            "formatter": "simple",
            "filename": "to be replaced"
        }
    },

    "loggers": {
        "__main__": {
            "level": "DEBUG",
            "handlers": ["consoleHandler", "fileHandler"],
            "propagate": false
        },
        "same_hierarchy": {
            "level": "DEBUG",
            "handlers": ["consoleHandler", "fileHandler"],
            "propagate": false
        },
        "lower.sub": {
            "level": "DEBUG",
            "handlers": ["consoleHandler", "fileHandler"],
            "propagate": false
        }
    },

    "root": {
        "level": "INFO"
    }
}

環境設定ファイルの定義方法は公式 - 環境設定辞書スキーマに詳しく書かれています。
ファイル内でext://sys.stderrやINFOといった定義をしています。それらは
公式 - 外部オブジェクトへのアクセスや公式 - 内部オブジェクトへのアクセスに詳しく記載しています。
また、formattersのformat部分で使える属性はPython公式 - LogRecord 属性を参照ください。

3.2. 環境設定ファイル(JSON)をPythonで読み込む

あとは、dictConfig関数を使って読み込むだけです。

環境設定ファイル(json/YAML)を使った例

import json
from logging import getLogger, config

with open('../log_config.json', 'r') as f:
    log_conf = json.load(f)

config.dictConfig(log_conf)

# ここからはいつもどおり
logger = getLogger(__name__)

3.3. 環境設定ファイル(JSON)のPythonでの編集

JSONファイルの定義に対してpython上で条件分岐や変数での編集も可能です。

import json

with open('../log_config.json', 'r') as f:
    log_conf = json.load(f)

# ファイル名をタイムスタンプで作成
log_conf["handlers"]["fileHandler"]["filename"] = \
    '../data/logs/{}.logs'.format(datetime.utcnow().strftime("%Y%m%d%H%M%S"))

# パラメータが設定されていればレベルをINFOからDEBUGに置換
if ARGS.verbose:
    log_conf["handlers"]["fileHandler"]["level"] = DEBUG

# logging設定
config.dictConfig(log_conf)

3.4. コード方式にすると・・・

環境設定ファイル方式でなく、コード方式で書くと大雑把に以下のようになります。コード方式は開発者によって書き方の差が大きいので、環境設定ファイル方式の方が若干優れていると考えています。

コード方式で設定した例

from logging import getLogger, Formatter, StreamHandler, FileHandler, DEBUG, INFO

def get_module_logger(module, verbose):
    logger = getLogger(module)
    logger = _set_handler(logger, StreamHandler(), False)
    logger = _set_handler(logger, FileHandler(LOG_DIR), verbose)
    logger.setLevel(DEBUG)
    logger.propagate = False
    return logger


def _set_handler(logger, handler, verbose):
    if verbose:
        handler.setLevel(DEBUG)
    else:
        handler.setLevel(INFO)
    handler.setFormatter(Formatter('%(asctime)s %(name)s:%(lineno)s %(funcName)s [%(levelname)s]: %(message)s'))
    logger.addHandler(handler)
    return logger

3.5. 環境設定ファイル(YAML)方式について

YAML形式も可能です。YAML形式の方がJSONより読みやすいのですが、YAMLを読み込む標準パッケージがなく、PyYAMLパッケージなどを追加インストールしないといけないため、私はJSONで定義しています。

3.6. 環境設定ファイル(configparser)方式について

また、fileConfig関数を使ったconfigparser形式もあるのですが、Python公式 - 環境設定ファイルの書式に以下の記載があるとおり、拡張性という点で劣っています。

注釈 fileConfig() API は dictConfig() API よりも古く、ロギングのある種の側面についてカバーする機能に欠けています。たとえば fileConfig() では数値レベルを超えたメッセージを単に拾うフィルタリングを行う Filter オブジェクトを構成出来ません。 Filter のインスタンスをロギングの設定において持つ必要があるならば、 dictConfig() を使う必要があるでしょう。設定の機能における将来の拡張は dictConfig() に対して行われることに注意してください。ですから、そうするのが便利であるときに新しい API に乗り換えるのは良い考えです。

loggingパッケージ使用で個人的にやっていること

方式の優越や必須とかではなく、現時点で私が「これがいいだろう」と考え実践していることです。

1. `Logger`インスタンスはnameにしなくてもいい

公式 - ロガーオブジェクトに以下の記述があります。

推奨される構築方法 logging.getLogger(__name__) を使用してロガーをモジュール単位で構成すれば、Python パッケージ階層と同一になります。これは、モジュールの中では __name__ が Python パッケージ名前空間におけるモジュール名だからです。

しかし、私は大規模なプログラムを開発するわけではないので、モジュール単位に準備すると環境設定ファイルがやや複雑になってしまいます。そのため、メインのモジュールでlogging.getLogger(__name__)をして、他モジュールに渡しています。

2. StreamHandlerとFileHandlerの併用

基本的にSteramHandlerとFileHandlerを併用しています。使ったことはないですが、ファイルローテーションをするハンドラもあるので、より複雑なことが必要になったら使う予定です。

環境設定ファイルのハンドラ部分抜粋

    "handlers": {
        "consoleHandler": {
            "class": "logging.StreamHandler",
            "level": "INFO",
            "formatter": "simple",
            "stream": "ext://sys.stdout"
        },
        "fileHandler": {
            "class": "logging.FileHandler",
            "level": "INFO",
            "formatter": "simple",
            "filename": "to be replaced"
        }
    },

3. パラメータでレベル指定

FileHandlerはargparseパッケージを使ってパラメータを受け取って、値の内容によってDEBUG/INFOレベルのログを出しています。argparseパッケージについては以前、記事「openCVの顔検出でパラメータを指定して手っ取り早く検出精度を高める」で書きましたので参考にしてください。

__main__のあたりで引数を定義し、受け取ります(import argparseは省略)。

if __name__ == '__main__':
    parser = argparse.ArgumentParser()
    parser.add_argument(
        '-v', '--verbose', action='store_true',
        help='Log level DEBUG for FileHandler'
    )

    ARGS, _ = parser.parse_known_args()

で、環境設定ファイル(JSON)を読み込み、上書きをして設定。

    with open('../log_config.json', 'r') as f:
        log_conf = json.load(f)

    # パラメータが設定されていればレベルをINFOからDEBUGに置換
    if ARGS.verbose:
        log_conf["handlers"]["fileHandler"]["level"] = DEBUG

    # logging設定
    config.dictConfig(log_conf)

ログ出力方法

1. 基本出力

ログレベルを指定して出力するだけです。formatterを定義していれば、定義内容に従って出力されます。

logger.debug('debug')
logger.info('info')
logger.warning('warning')
logger.error('error')

2. 変数を使用した出力

printと同じようにformatを使って変数値を表示します。

test1 = '値1'
test2 = '値2'
logger.info('変数:{}'.format(test1))
logger.info('変数:{0}, {1}'.format(test1, test2))

実行結果。

変数:値1
変数:値1, 値2

%も使って以下のように書いても同じ結果です。

logger.info('変数:%s', test1)

しかし、 %を使った書式は後方互換性の維持のためと「Python公式 - 固有の書式化スタイルをアプリケーション全体で使う」に書いてあり、あえて使う意味はなさそうです。

Python 3.2 では、Formatter クラスが style という名前のオプションのキーワード引数を受け取ります。このデフォルト値は後方互換性を維持するために % となっていますが、 { か $ を指定することで、str.format() か string.Template でサポートされているのと同じ書式化のアプローチを採れます。

はじめに - printでもいい場合と卒業する場合