手軽な実験のためのimport logger;logger.infoが面倒だったのでhandofcatsにprintを追加した

github.com

手軽な実験のためのimport logger;logger.infoが面倒だったのでhandofcatsにprintを追加した。 callstackを取り出してloggerに渡す名前を推測してみたりなどと色々と考えたりもしたけれど、結局保守的な実装に落ち着いた。

handofcats.print

handofcatsのprintの実装はほんとに単純でDEBUG=1という環境変数が渡されていたらlogger.infoを使う。そして通常はprintをそのまま返すというだけ。もともとhandofcatsで管理されたコマンドはDEBUG=1をつけて実行するとデフォルトではlogging.levelがDEBUGでlogging.basicConfig()が実行されるのでそれを用いる。

$ make 00
DEBUG=1 python 00hello.py
** handofcats.customize: DEBUG=1, activate logging **
level:INFO  name:__main__L6 message:hello
level:INFO  name:__main__L7 message:byebye

このときのコードは以下の通り。そのままlogger.infoがexportされるだけ。

00hello.py

from handofcats import as_command, print


@as_command
def run():
    print("hello")
    print("byebye")

もちろん何も付けずに実行すればふつうのprintとして振る舞う。

$ python 00hello.py
hello
byebye

⚠ logger.infoをexportしているだけなので、print("foo", file=sys.stderr) みたいなprint()関数独自のオプションなどを使われると困る。もちろん対応していない。ただそういう処理が必要なコードは日々の手軽な実験の範囲を超えるのではないか？という認識でいる。

またどこかからimportされるであろうモジュールに関してもhandofcats.printを使うのはあまりおすすめできない。これはhandofcatsの中でloggerオブジェクトを作っているので実質singletonなので。すなおにloggerを作りましょう。

import logging
logger = logging.getLogger(__name__)

はい。

おまけ asyncioのコードの実験にはrelativeCreatedが便利

asyncioのコードの実験のときにはloggingのrelativeCreatedのフィールドを有効にするのが便利だったりする。

logging モジュールが読み込まれた時刻に対する、LogRecord が生成された時刻を、ミリ秒で表したもの

asctimeなどを使うよりも相対時刻で表されているので掛かった時間がわかりやすく、わざわざ自分でtime.time()から引いて計算したりする必要もないので。

たとえば、昨日のghコマンドの更新チェックのコードをpythonでやろうとしてみたときに同期的なコードを非同期的なcontextに持ってきた場合にはrun_in_executor()を付けたほうが良いということなどが気軽に実験できて便利。

handofcatsではLOGGING_TIME=relativeというオプションを追加することで有効になる。async/awaitのcontext上で同期的な関数をそのまま使ったコードはあまりイケていない(コード自体は後で貼る)。

relativeの時間に注目してほしい。

$ make 01
LOGGING_TIME=relative DEBUG=1 python 01update_check.py
** handofcats.customize: DEBUG=1, activate logging **
level:DEBUG name:asyncioL59 relative:238.86394500732422 message:Using selector: KqueueSelector
level:INFO  name:__main__L23    relative:239.61997032165527 message:do something (main)
level:INFO  name:__main__L25    relative:239.76802825927734 message:.
level:INFO  name:__main__L25    relative:340.717077255249   message:.
level:INFO  name:__main__L25    relative:445.12104988098145 message:.
level:INFO  name:__main__L25    relative:549.9541759490967  message:.
level:INFO  name:__main__L25    relative:650.8128643035889  message:.
level:INFO  name:__main__L25    relative:751.5740394592285  message:.
level:INFO  name:__main__L27    relative:856.255054473877   message:ok
level:INFO  name:__main__L8 relative:856.6339015960693  message:-> update_check ...
level:INFO  name:__main__L10    relative:1358.9298725128174 message:<- ... update_check
level:INFO  name:__main__L37    relative:1359.1439723968506 message:A new release of gh is available: xxx → 0.8.8

run_in_executor()を使ったときにはupdate_checkもいい感じに動く(もちろんこうではなくawaitable functionで定義した場合もensure_future()で実行してあげれば良い感じに動く(gatherやwaitなどを使っても良い))。

$ make 02
LOGGING_TIME=relative DEBUG=1 python 02update_check.py
** handofcats.customize: DEBUG=1, activate logging **
level:DEBUG name:asyncioL59 relative:133.13603401184082 message:Using selector: KqueueSelector
level:INFO  name:__main__L23    relative:137.1607780456543  message:do something (main)
level:INFO  name:__main__L8 relative:137.43209838867188 message:-> update_check ...
level:INFO  name:__main__L25    relative:137.53795623779297 message:.
level:INFO  name:__main__L25    relative:238.74998092651367 message:.
level:INFO  name:__main__L25    relative:339.03002738952637 message:.
level:INFO  name:__main__L25    relative:442.10100173950195 message:.
level:INFO  name:__main__L25    relative:546.6411113739014  message:.
level:INFO  name:__main__L10    relative:639.4338607788086  message:<- ... update_check
level:INFO  name:__main__L25    relative:647.2370624542236  message:.
level:INFO  name:__main__L27    relative:752.1660327911377  message:ok
level:INFO  name:__main__L38    relative:752.5920867919922  message:A new release of gh is available: xxx → 0.8.8

releativeに注目してほしい。はい。

このときのコード。

01update_check.py

import typing as t
import asyncio
import random
from handofcats import as_command, print


async def update_check() -> t.Awaitable[t.Optional[str]]:
    print("-> update_check ...")
    await asyncio.sleep(0.5)
    print("<- ... update_check")

    if random.random() < 0.2:
        # update is not found
        return None

    # update is found
    return "0.8.8"


def run_main():
    import time

    print("do something (main)")
    for i in range(6):
        print(".")
        time.sleep(0.1)
    print("ok")


@as_command
def main():
    async def run():
        fut = asyncio.ensure_future(update_check())
        run_main()
        update_version = await fut
        if update_version is not None:
            print(f"A new release of gh is available: xxx → {update_version}")

    asyncio.run(run())

printしか書かなくて済むのは便利(--exposeした場合にはimport部分が消えるだけなのでふつうのprint()になる)。

diff

--- 01update_check.py    2020-03-01 15:37:07.000000000 +0900
+++ 02update_check.py 2020-03-01 15:37:22.000000000 +0900
@@ -31,7 +31,8 @@
 def main():
     async def run():
         fut = asyncio.ensure_future(update_check())
-        run_main()
+        loop = asyncio.get_event_loop()
+        await loop.run_in_executor(None, run_main)
         update_version = await fut
         if update_version is not None:
             print(f"A new release of gh is available: xxx → {update_version}")

Makefile

00:
  DEBUG=1 python $(shell echo $@*.py)
01:
  LOGGING_TIME=relative DEBUG=1 python $(shell echo $@*.py)
02:
  LOGGING_TIME=relative DEBUG=1 python $(shell echo $@*.py)
03:
  diff -u 01*.py 02*.py > 0102.diff