最近の砂場でのpythonのサンプルコードの実行方法について

日記的なrepositoryを作っていて、何か調べたいことがあったときにそこにサンプルコードを書いて調べたりしている。そのサンプルコードの書き方でdebugとinfoの実行形態を分ける方法が便利だったのでメモ。

趣旨

この方法の趣旨は以下のような感じ。

• 通常は、INFOレベルでログが出れば良い
• 時折、詳しく調べたいときにDEBUGレベルのログを出したい

そしてこれらを オプションの指定など無し で切り替えたい。

方法

今の所はMakefileを使っている。サンプルコードのファイル名を概ね"\d{2}\S+.py"みたいな名前にしている(e.g. "00sample.py", "11app.py")。

そしてMakefileは以下の様な形にすると良さそうなことに気づいた(各タスクは手書きしている。その方が管理しやすい気がしている。時折、特定のタスクだけ実行するコマンドも変えたいときがあるので)。

PYTHON ?= LOGLEVEL=DEBUG PYTHONASYNCIODEBUG=1 python -W default

00:
  ${PYTHON} 00*.py
01:
  ${PYTHON} 01*.py
02:
  ${PYTHON} 02*.py
03:
  ${PYTHON} 03*.py

実行するときは以下の様に。

# 通常の実行
$ python 00*.py

# 詳細な出力が欲しい場合の実行
$ make 00

実行例

そして具体的には以下の様なコードを書く。

00hello.py

import os
import logging
logger = logging.getLogger(__name__)


def main():
    logger.debug("debug message1")
    logger.info("hello")
    logger.debug("debug message2")


# 丁寧にmain()を定義したり__name__のifを付けない場合もある
if __name__ == "__main__":
    logging.basicConfig(level=getattr(logging, os.environ.get("LOGLEVEL", "INFO")))
    main()

このときの実行結果は以下の様な形。makeから実行したときだけdebug出力になる。

00hello.py

# 通常の実行
$ python 00*.py
INFO:__main__:hello

# 詳細な出力が欲しい場合の実行
$ make 00
LOGLEVEL=DEBUG PYTHONASYNCIODEBUG=1 python -W default 00*.py
DEBUG:__main__:debug message1
INFO:__main__:hello
DEBUG:__main__:debug message2

最近気づいたのは、オプションの入力(--foo的なもの)を調整することすら面倒に感じることがあり、それらが不要な形にしておくとストレスが減るということだった。考えてみると、コンソール上でオプションを調節するためのカーソル移動がけっこうストレスだったりしたのかもしれない。

ただちょっとコード自体書くのが面倒な感じもするのでloggedpyを作ってみたのと同じ感じで短くできないかなと思ったりはしている(osとloggingのimportなくしたい)。

オプションの意味

python -W default

詳細な実行のときにはpython -W defaultの指定もあると便利(詳しくはドキュメントを)。色々なwarningをもう少し細かく教えてくれる。シェルのaliasに指定しても良い位かもしれない。

$ python 01*.py
9
01warning.py:8: DeprecationWarning: The 'warn' method is deprecated, use 'warning' instead
  logger.warn("xxxx")
WARNING:__main__:xxxx

$ make 01
LOGLEVEL=DEBUG PYTHONASYNCIODEBUG=1 python -W default 01*.py
9
01warning.py:8: DeprecationWarning: The 'warn' method is deprecated, use 'warning' instead
  logger.warn("xxxx")
WARNING:__main__:xxxx
sys:1: ResourceWarning: unclosed file <_io.TextIOWrapper name='01warning.py' mode='r' encoding='UTF-8'>

01warning.py

import os
import logging
logger = logging.getLogger(__name__)

logging.basicConfig(level=getattr(logging, os.environ.get("LOGLEVEL", "INFO")))
f = open(__file__)
print(len(f.read().split("\n")))
logger.warn("xxxx")

PYTHONASYNCIODEBUG=1

asyncioのコードを確認するときにはdebugを有効にしておいた方が良いこともある(詳しくはドキュメントを)。色々な情報を出力してくれたりするので。今見てみたら、python -X devと書いても大丈夫のようでこちらのほうが楽かもしれない。

$ python 02*.py
INFO:__main__:hello
00hello.py
01warning.py
02asyncio.py
Makefile

INFO:__main__:bye


$ make 02
LOGLEVEL=DEBUG PYTHONASYNCIODEBUG=1 python -W default 02*.py
DEBUG:asyncio:Using selector: EpollSelector
INFO:__main__:hello
DEBUG:asyncio:run shell command 'sleep 1 && ls' stdout=<pipe> stderr=<pipe>
DEBUG:asyncio:process 'sleep 1 && ls' created: pid 12225
DEBUG:asyncio:Read pipe 6 connected: (<_UnixReadPipeTransport fd=6 polling>, <ReadSubprocessPipeProto fd=1 pipe=<_UnixReadPipeTransport fd=6 polling>>)
DEBUG:asyncio:Read pipe 8 connected: (<_UnixReadPipeTransport fd=8 polling>, <ReadSubprocessPipeProto fd=2 pipe=<_UnixReadPipeTransport fd=8 polling>>)
INFO:asyncio:run shell command 'sleep 1 && ls': <_UnixSubprocessTransport pid=12225 running stdout=<_UnixReadPipeTransport fd=6 polling> stderr=<_UnixReadPipeTransport fd=8 polling>>
DEBUG:asyncio:<Process 12225> communicate: read stdout
DEBUG:asyncio:<Process 12225> communicate: read stderr
INFO:asyncio:poll took 1000.727 ms: 1 events
INFO:asyncio:<_UnixReadPipeTransport fd=6 polling> was closed by peer
INFO:asyncio:<_UnixReadPipeTransport fd=8 polling> was closed by peer
DEBUG:asyncio:process 12225 exited with returncode 0
INFO:asyncio:<_UnixSubprocessTransport pid=12225 running stdout=<_UnixReadPipeTransport closed fd=6 closed> stderr=<_UnixReadPipeTransport closed fd=8 closed>> exited with return code 0
DEBUG:asyncio:<Process 12225> communicate: close stdout
DEBUG:asyncio:<Process 12225> communicate: close stderr
00hello.py
01warning.py
02asyncio.py
Makefile

INFO:__main__:bye
DEBUG:asyncio:Close <_UnixSelectorEventLoop running=False closed=False debug=True>

02asyncio.py

import os
import logging
import asyncio
import subprocess
logger = logging.getLogger(__name__)

logging.basicConfig(level=getattr(logging, os.environ.get("LOGLEVEL", "INFO")))


async def main(n):
    logger.info("hello")
    await asyncio.sleep(n)
    p = await asyncio.create_subprocess_shell(
        "sleep 1 && ls",
        stdout=subprocess.PIPE,
        stderr=subprocess.PIPE,
    )
    print((await p.communicate())[0].decode("utf-8"))
    logger.info("bye")


loop = asyncio.get_event_loop()
loop.run_until_complete(main(0.1))
loop.close()

その他 python -X tracemalloc とか指定したくなることもあるかもしれない。あるいはPYTHONTRACEMALLOCだとか(指定可能な環境変数はman pythonに載っている)。