loggingの有効/無効を真面目に書くのがめんどくさくなったのでDEBUG=1を見て勝手に有効にすることにした

loggingの有効/無効を真面目に書くのがめんどくさくなったのでDEBUG=1を見て勝手に有効にすることにしました。めんどくさかったので。

バージョン2.5.0の話です

$ pip install handofcats
$ pip freeze | grep handofcats
handofcats==2.5.0

普通に使う

例えば以下の様なコードがあるとします。

hello.py

from handofcats import as_command
import logging

logger = logging.getLogger(__name__)


@as_command
def hello(*, name: str = "world") -> None:
    logger.debug("DEBUG")
    logger.info(f"hello {name}")
    logger.warning("WARN")

引数なし

普通に使う場合にはloggingは有効になりません。ただしpythonのデフォルトの動作としてWARNING以降のログレベルのものは表示されます。

$ python hello.py
WARN

loggingを追加

-h でヘルプを見ると --logging オプションが追加されています。

$ python hello.py -h
usage: hello.py [-h] [--expose] [--inplace] [--typed] [--name NAME]
                  [--logging {CRITICAL,FATAL,ERROR,WARN,WARNING,INFO,DEBUG,NOTSET}]

optional arguments:
  -h, --help            show this help message and exit
  --expose
  --inplace
  --typed
  --name NAME           (default: 'world')
  --logging {CRITICAL,FATAL,ERROR,WARN,WARNING,INFO,DEBUG,NOTSET}

なにか困ったときに見たいのは、INFOないしはDEBUGのログです。そんなわけで --logging=INFO をつけて実行してみます。INFO以降も出てきました。

$ python hello.py --logging=INFO
level:INFO  name:__main__   where:hello.py:10   relative:36.0102653503418   message:hello world
level:WARNING   name:__main__   where:hello.py:11   relative:36.16213798522949  message:WARN

なんとなくLTSVで表示しています。

ここの表示内容は変えるかもしれません。あるいは何かいい感じのpresetを指定するような形にしてdefaultはいじらないようにするかもしれません。ただあんまり頑張りたくはない気持ちもあったりします。

個人的には、スタートしてからどれくらいの時間が経ったのかという relativeCreatedAt やファイル名と行数が見たかったりします。

messageの部分が後ろになってしまうという問題はあったりしますが、まぁそこはデバッグのときには、出力できそうな情報を全部の情報出力して、あとでgrepしたりエディタで開いたりという形が多そうな気がするので良いということにしてしまっています。

DEBUG=1

コマンドラインオプションなんてめんどくさいということがあったりすると思います。例えばMakefile越しに実行されているときなどは、環境変数を経由して渡せます。どうせDEBUGのときにはすべての情報が見たいということだろうと思うので、DEBUG=1で有効になります。

$ DEBUG=1 python hello.py
** handofcats.injectlogging: DEBUG=1, activate logging **
level:DEBUG name:__main__   where:hello.py:9    relative:38.42568397521973  message:DEBUG
level:INFO  name:__main__   where:hello.py:10   relative:38.67387771606445  message:hello world
level:WARNING   name:__main__   where:hello.py:11   relative:38.74564170837402  message:WARN

ちなみに --logging=INFO などloggingオプションが渡されていた場合にはそちらが優先されます。

もう少し真面目に環境変数を扱う

もう少し真面目に環境変数を扱ってみます。例えばJSON形式で無理やり出力したいということはできなくはないです。

LOGGING_FORMAT
LOGGING_STREAM
LOGGING_LEVEL

が使えます。ただ真面目に使おうとする機会がそんなにくるとは思っていないです。せいぜいstderrではなくstdoutに出力したいくらいの要望なような気がしています。あとはフォーマットが気に入らない場合など。

$ LOGGIG_FORMAT=stdout
$ LOGGING_FORMAT='{"level": "%(levelname)s", "funcname": "%(funcName)s", "message": "%(message)r"}'
$ LOGGING_LEVEL=DEBUG
$ python hello.py
{"level": "DEBUG", "funcname": "hello", "message": "'DEBUG'"}
{"level": "INFO", "funcname": "hello", "message": "'hello world'"}
{"level": "WARNING", "funcname": "hello", "message": "'WARN'"}

例えば以下の様なMakefile越しに使う感じにすればまだましになるかもしれません (あるいはexportしてあげると毎回定義する必要はなくなります)。

04: LEVEL ?= DEBUG
04: FORMAT ?= {"level": "%(levelname)s", "funcname": "%(funcName)s", "message": "%(message)r"}
04: STREAM ?= stdout
04:
  LOGGIG_FORMAT=${STREAM} LOGGING_FORMAT='${FORMAT}' LOGGING_LEVEL=${LEVEL} python hello.py

もちろんas_commandデコレータを付けていないコードにも

もちろんas_commandを付けていない関数にもhandofcats越しに実行してあげれば大丈夫です。

$ DEBUG=1 python -m handofcats ./messages.py:debug
** handofcats.injectlogging: DEBUG=1, activate logging **
level:DEBUG name:messages   where:messages.py:7 relative:38.02919387817383  message:DEBUG

このときのコードは以下の様な感じです。

messages.py

import logging

logger = logging.getLogger(__name__)


def debug():
    logger.debug("DEBUG")


def info():
    logger.info("INFO")


def warning():
    logger.warning("WARNING")