LogLevelをどう設定すべきか

行いたいタスク そのタスクに最適なツール
通常の操作中に発生したイベント logging.info()
診断のための詳細な出力 logging.debug()
特定のランタイムイベントに関わる警告（呼び出し側を修正すべき） warnings.warn()
特定のランタイムイベントに関わる警告 logging.warning()
特定のランタイムイベントに関わるエラー raise exception
例外の送出をしないエラーの抑制 logging.error(), logging.exception(), logging.ciritical()

getLogger()

getLogger()で一度生成されたloggerは同一プロセス内では1つの実体として動作している。loggingクックブック内ではモジュールのグローバル変数としてloggerを定義している。

logging.getLogger(‘someLogger’)の複数回の呼び出しは同じloggerへの参照を返します。これは同じPythonインタプリタプロセス上で動いている限り、一つのモジュールの中からに限らず、モジュールをまたいでも当てはまります。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
import logging

# create logger
module_logger = logging.getLogger('spam_application.auxiliary')

class Auxiliary:
    def __init__(self):
        self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
        self.logger.info('creating an instance of Auxiliary')

    def do_something(self):
        self.logger.info('doing something')
        a = 1 + 1
        self.logger.info('done doing something')

def some_function():
    module_logger.info('received a call to "some_function"')

disable_existing_loggersでloggerが無効化される

logging.config.dictConfigで設定を読み込んくとすでに作成済のloggerが無効化されてしまう。無効化させないためにはdisable_existing_loggersをFalseに設定する。

disable_existing_loggers.py

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
import logging
import logging.config

logger = logging.getLogger(__name__)

# load config from file
# logging.config.fileConfig('logging.ini', disable_existing_loggers=False)
# or, for dictConfig
logging.config.dictConfig({
    'version': 1,
    'disable_existing_loggers': False,  # this fixes the problem
    'formatters': {
        'standard': {
            'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
        },
    },
    'handlers': {
        'default': {
            'level':'INFO',
            'class':'logging.StreamHandler',
            'formatter':'standard'
        },
    },
    'loggers': {
        '': {
            'handlers': ['default'],
            'level': 'INFO',
            'propagate': True
        }
    }
})

logger.debug('Debug log message')
logger.info('Info log message')
logger.warning('Warning log message')
logger.error('Error log message')

disable_existing_loggersがTrueの場合

ログが出力されない。

1
$python disable_existing_loggers.py

disable_existing_loggersがFalseの場合

期待通りのログが出力される。

1
2
3
4
$python disable_existing_loggers.py
2020-04-22 13:54:22,207 [INFO] __main__: Info log message
2020-04-22 13:54:22,209 [WARNING] __main__: Warning log message
2020-04-22 13:54:22,209 [ERROR] __main__: Error log message

loggerとdisable_existing_loggersの挙動をみる

logging_treeモジュール

loggerをツリー構造で見やすく表示する、logging_treeを使う。pip install logging_treeでインストールしておく。

my_module.py

テスト用のClassとFunctionでいくつかのLogLevelのメッセージを表示するモジュール。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
import logging

def foo():
    logger = logging.getLogger(__name__)
    logger.debug('Debug log message/function')
    logger.info('Info log message/function')
    logger.warning('Warning log message/function')
    logger.error('Error log message/function')

class Bar(object):
    def __init__(self, logger=None):
        self.logger = logger or logging.getLogger(__name__)

    def bar(self):
        self.logger.debug('Debug log message/method')
        self.logger.info('Info log message/method')
        self.logger.warning('Warning log message/method')
        self.logger.error('Error log message/method')

main.py

テスト用のモジュールでログ出力とloggerのツリー構造を確認する。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
import logging
import logging.config
import logging_tree

# load my module
import my_module

print("--------------------------------------------------------")
print("Step1: 標準のroot logger")
logging_tree.printout()
print("--------------------------------------------------------")

print("--------------------------------------------------------")
print("Step2: なにも設定せずgetLogger()を呼ぶ")
my_module.foo()
bar = my_module.Bar()
bar.bar()
print("")
print("getLogger()によってmy_moduleというloggerが生成されている")
logging_tree.printout()
print("--------------------------------------------------------")

print("--------------------------------------------------------")
print("Step3: logging.ini / disable_existing_loggers=True")
logging.config.fileConfig('logging.ini', disable_existing_loggers=True)
my_module.foo()
bar = my_module.Bar()
bar.bar()
print("")
print("すでにStep1でmy_module loggerは作成済だったので、無効化されている")
logging_tree.printout()
print("--------------------------------------------------------")

print("--------------------------------------------------------")
print("Step4: logging.ini / disable_existing_loggers=False")
logging.config.fileConfig('logging.ini', disable_existing_loggers=False)
my_module.foo()
bar = my_module.Bar()
bar.bar()
print("")
print("disable_existing_loggers=Falseで有効化されている")
logging_tree.printout()
print("--------------------------------------------------------")

logging.ini

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
[loggers]
keys=root

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

main.py実行結果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
$python main.py
--------------------------------------------------------
Step1: 標準のroot logger
<--""
   Level WARNING
--------------------------------------------------------
--------------------------------------------------------
Step2: なにも設定せずgetLogger()を呼ぶ
Warning log message/function
Error log message/function
Warning log message/method
Error log message/method

getLogger()によってmy_moduleというloggerが生成されている
<--""
   Level WARNING
   |
   o<--"my_module"
       Level NOTSET so inherits level WARNING
--------------------------------------------------------
--------------------------------------------------------
Step3: logging.ini / disable_existing_loggers=True

すでにStep1でmy_module loggerは作成済だったので、無効化されている
<--""
   Level DEBUG
   Handler Stream <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
     Level DEBUG
     Formatter fmt='%(asctime)s - %(name)s - %(levelname)s - %(message)s' datefmt=''
   |
   o<--"my_module"
       Level NOTSET so inherits level DEBUG
       Disabled
--------------------------------------------------------
--------------------------------------------------------
Step4: logging.ini / disable_existing_loggers=False
2020-04-04 22:03:42,281 - my_module - DEBUG - Debug log message/function
2020-04-04 22:03:42,281 - my_module - INFO - Info log message/function
2020-04-04 22:03:42,281 - my_module - WARNING - Warning log message/function
2020-04-04 22:03:42,281 - my_module - ERROR - Error log message/function
2020-04-04 22:03:42,281 - my_module - DEBUG - Debug log message/method
2020-04-04 22:03:42,281 - my_module - INFO - Info log message/method
2020-04-04 22:03:42,281 - my_module - WARNING - Warning log message/method
2020-04-04 22:03:42,281 - my_module - ERROR - Error log message/method

disable_existing_loggers=Falseで有効化されている
<--""
   Level DEBUG
   Handler Stream <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
     Level DEBUG
     Formatter fmt='%(asctime)s - %(name)s - %(levelname)s - %(message)s' datefmt=''
   |
   o<--"my_module"
       Level NOTSET so inherits level DEBUG
--------------------------------------------------------

Pythonの例外処理とトレースバック

Pythonの例外処理をCatchして、ログ出力する。StuckTraceは改行を含む複数行の内容になるので、JSON形式でのログ出力を行う。JSON形式でログ出力するために、jsonloggerを使うのでpip install python-json-loggerでインストールする。

複数行の例外は読みやすいですが、外部のログサービスを使用してログを集計している場合は、ログをJSONに変換して、複数行のログが正しく解析されるようにする必要があります。

lowermodule.py

  • 例外をキャッチしてスタックトレースをログに記録する
  • スタックトレースは複数行になるので、JSON形式で扱いやすく出力する
  • JSONにはカスタム項目（extra=）を追記することも可能
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
# lowermodule.py
import logging.config
import traceback
import time
from pythonjsonlogger import jsonlogger
import logging_tree

def word_count(myfile):
    #logger = logging.getLogger(__name__)
    logger = logging.getLogger('lowermodule')
    logging.config.fileConfig('logging.json.ini', disable_existing_loggers=False)
    print(logger.name)
    logging_tree.printout()
    try:
        starttime = time.time()
        with open(myfile, 'r') as f:
            file_data = f.read()
            words = file_data.split(" ")
            final_word_count = len(words)
            endtime = time.time()
            duration = endtime - starttime
            logger.info("this file has %d words", final_word_count, extra={"run_duration":duration})
            return final_word_count
    except OSError as e:
        logger.error(e, exc_info=True)
    except:
        logger.error("uncaught exception: %s", traceback.format_exc())
        return False

if __name__ == '__main__':
    word_count('myfile.txt')

logging.json.ini

__name__がlowermoduleの場合にconsoleとjsonに出力する。consoleはroot loggerの定義によって、jsonはlowermodule loggerの定義によって出力される。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
[loggers]
keys=root,lowermodule

[handlers]
keys=consoleHandler,fileHandler

[formatters]
keys=simpleFormatter,json

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_lowermodule]
level=DEBUG
handlers=fileHandler
qualname=lowermodule

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[handler_fileHandler]
class=FileHandler
level=DEBUG
formatter=json
args=("myapp.log",)

[formatter_json]
class=pythonjsonlogger.jsonlogger.JsonFormatter
format=%(asctime)s %(name)s %(levelname)s %(message)s

[formatter_simpleFormatter]
format=%(asctime)s %(name)s - %(levelname)s:%(message)s

lowermodule.py実行結果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
$python lowermodule.py
lowermodule
<--""
   Level DEBUG
   Handler Stream <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
     Level DEBUG
     Formatter fmt='%(asctime)s %(name)s - %(levelname)s:%(message)s' datefmt=None
   |
   o<--"lowermodule"
       Level DEBUG
       Handler File '/work/logging_traceback/myapp.log'
         Level DEBUG
         Formatter <pythonjsonlogger.jsonlogger.JsonFormatter object at 0x7f41b0c0e040>
2020-04-05 01:12:37,312 lowermodule - ERROR:[Errno 2] No such file or directory: 'myfile.txt'
Traceback (most recent call last):
  File "lowermodule.py", line 16, in word_count
    with open(myfile, 'r') as f:
FileNotFoundError: [Errno 2] No such file or directory: 'myfile.txt'

$cat myapp.log
{"asctime": "2020-04-05 01:12:37,312", "name": "lowermodule", "levelname": "ERROR", "message": "[Errno 2] No such file or directory: 'myfile.txt'", "exc_info": "Traceback (most recent call last):\n  File \"lowermodule.py\", line 16, in word_count\n    with open(myfile, 'r') as f:\nFileNotFoundError: [Errno 2] No such file or directory: 'myfile.txt'"}