pythonのスクリプトでログを出力しようとして、
色々と調べて、結局どうすればよいのかを自分なりに整理したので、
メモを残しておきます。

このエントリでは、以下の想定要件で、ログ出力を実装してみます。

本番環境では、INFOレベル以上をファイルに出力
開発環境では、DEBUGレベル以上を標準エラー出力とファイルに出力
ログファイルは日ごとにローテション
importするモジュールのログ出力レベルは、メイン処理とは別に設定
ログにはスクリプト名と行数を出力

以下の流れで段階を追って、実装してきます。

ファイルにログ出力
ログのローテート
ログのフォーマット変更
開発環境向け: 標準エラー出力にログを出力
ライブラリ固有のログ出力を設定

ファイルにログ出力

ファイルにログを出力するように、
メインのスクリプトと、logging.conf(ログ出力の設定)を作成します。

sample.py

#! /usr/bin/python
import logging.config

logging.config.fileConfig("logging.conf")

logger = logging.getLogger()

logger.info("info level log")
logger.debug("debug level log")

logging.conf

[loggers]
keys=root

[handlers]
keys=fileHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=INFO
handlers=fileHandler

[handler_fileHandler]
class=FileHandler
formatter=simpleFormatter
args=('root.log','a')

[formatter_simpleFormatter]

以下のように、sample.pyを実行してログを確認します。

$ python sample.py
$ cat root.log
info level log

細かい説明はせずにどんどん進めますが。

logging.confの
「handler_fileHandler」の部分でログの出力先
「formatter_simpleFormatter」の部分でログの出力形式
を設定できそうなことは想像できると思います。

logging.confのフォーマットは以下を参考にします。

参考) 16.7. logging.config - ロギングの環境設定:
http://docs.python.jp/3.5/library/logging.config.html

ログのローテート

次にログをローテートさせます。前項で触れたように「handler_fileHandler」の部分で、ログの出力先をコントロールできるので、 logging.confを以下のように変更します。

logging.conf 抜粋

[handler_fileHandler]
class=handlers.TimedRotatingFileHandler
formatter=simpleFormatter
args=('root.log','S')

以下のように、sample.pyを実行してログを確認します。

$ python sample.py
$ cat root.log
info level log
$ ls
logging.conf
root.log
root.log.YYYY-MM-DD_hh-mm-ss ※←実際は実行時のタイムスタンプ
sample.py

ここでは動作確認のために、1秒ごとのログをローテートしていますが、
args=('root.log','S')の部分をargs=('root.log','D')とすると日毎にローテートします。

他のhandlerやオプションは以下を参考にします。

参考) 16.8. logging.handler - ロギングハンドラ
http://docs.python.jp/3.5/library/logging.handlers.html

ログのフォーマット変更

次にログのフォーマットを変更します。
前々項で触れたように
「formatter_simpleFormatter」の部分で、ログの出力形式をコントロールできるので、
logging.confを以下のように変更します。

logging.conf 抜粋

[formatter_simpleFormatter]
format=[%(asctime)s][%(levelname)s](%(filename)s:%(lineno)s) %(message)s
datefmt=%Y/%m/%d %H:%M:%S

以下のように、sample.pyを実行してログを確認します。

$ python sample.py
$ cat root.log
[YYYY/MM/DD hh:mm:ss][INFO](sample.py:8) info level log ※←実際は実行時のタイムスタンプ

フォーマットでしているできる変数については以下を参考にします。

参考) LogRecord 属性 | 16.6. logging - Python 用ロギング機能
http://docs.python.jp/3.5/library/logging.html#logrecord-attributes

開発環境向け: 標準エラー出力にログを出力

次に開発環境用に、標準エラー出力ログを出力します。
sample.pyを以下のように変更して、開発環境用のlogging.confを参照するようにします。

sample.py

#!/usr/bin/python
import logging.config

logging.config.fileConfig("logging_debug.conf")

logger = logging.getLogger()

logger.info("info level log")
logger.debug("debug level log")

開発環境用のlogging.conf(logging_debug.conf)を作成します。
levelをDEBUGにして、handler_stderrHandlerを追加しています。

logging_debug.conf

[loggers]
keys=root

[handlers]
keys=fileHandler,stderrHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=fileHandler,stderrHandler

[handler_fileHandler]
class=handlers.TimedRotatingFileHandler
formatter=simpleFormatter
args=('root.log','D')

[handler_stderrHandler]
class=StreamHandler
formatter=simpleFormatter
args=(sys.stderr,)

[formatter_simpleFormatter]
format=[%(asctime)s][%(levelname)s](%(filename)s:%(lineno)s) %(message)s
datefmt=%Y/%m/%d %H:%M:%S

以下のように、sample.pyを実行してログを確認します。

$ python sample.py
[YYYY/MM/DD hh:mm:ss][INFO](sample.py:8) info level log
[YYYY/MM/DD hh:mm:ss][DEBUG](sample.py:9) debug level log
$ cat root.log
[YYYY/MM/DD hh:mm:ss][INFO](sample.py:8) info level log
[YYYY/MM/DD hh:mm:ss][DEBUG](sample.py:9) debug level log

logging_debug.conf, logging.conf の切り替えは、
環境変数なり、起動オプションなり、実行ユーザ名/ホスト名などで行えば良いかと思います。

ライブラリ固有のログ出力を設定

importするモジュールからもログを出力できるようにします。

まずは、
モジュール(functions.py)を作成し、sample.pyから呼び出すよう修正します。

functions.py

#!/usr/bin/python
from logging import getLogger
logger = getLogger(__name__)

def test_func():
    logger.info("test func: info level log")
    logger.debug("test func: debug level log")

sample.py

#!/usr/bin/python
import functions
import logging.config

logging.config.fileConfig("logging_debug.conf")

logger = logging.getLogger()

logger.info("info level log")
logger.debug("debug level log")

functions.test_func()

この段階では、sample.pyを実行してもfunctionsのログは出力されません。

$ python sample.py
[YYYY/MM/DD hh:mm:ss][INFO](sample.py:8) info level log
[YYYY/MM/DD hh:mm:ss][DEBUG](sample.py:9) debug level log

以下のように、logging_debug.confを変更します。
logger_functionsを追加しています。

[loggers]
keys=root,functions

[handlers]
keys=fileHandler,stderrHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=fileHandler,stderrHandler

[logger_functions]
level=INFO
handlers=fileHandler,stderrHandler
qualname=functions
propagate=0

[handler_fileHandler]
class=handlers.TimedRotatingFileHandler
formatter=simpleFormatter
args=('root.log','D')

[handler_stderrHandler]
class=StreamHandler
formatter=simpleFormatter
args=(sys.stderr,)

[formatter_simpleFormatter]
format=[%(asctime)s][%(levelname)s](%(filename)s:%(lineno)s) %(message)s
datefmt=%Y/%m/%d %H:%M:%S

以下のように、sample.pyを実行してログを確認します。

$ python sample.py
[YYYY/MM/DD hh:mm:ss][INFO](sample.py:9) info level log
[YYYY/MM/DD hh:mm:ss][DEBUG](sample.py:10) debug level log
[YYYY/MM/DD hh:mm:ss][INFO](functions.py:6) test func: info level log

sample.pyのログはDEBUGレベル以上
functions.pyのログはINFOレベル以上
が表示されていることが確認できます。

logging.getLogger()でloggerを取得する際、
ロガーの名称を指定しないとrootのロガーを取得
指定するとその名称のロガーを取得することを利用して。

sample.pyでは指定せず、rootのロガー(level=DEBUG)
functions.pyは「_name_」(=‘functions’)を指定して、functionsのロガー(level=INFO)
を取得するようにしています。
このようにして、ログ出力レベルをメイン処理とは別に設定できるようにしています。

以上で、最初に上げた想定要件を満たしたログ出力ができているはず。