手軽な実験のためのimport logger;logger.infoが面倒だったのでhandofcatsにprintを追加した
手軽な実験のための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}")
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
ちなみに環境変数で触れるようにしておくと、こういう設定をMakefileにまとめてかけちゃう点が便利。特にちょっとした実験コードのファイルが増えてきた場合には。コマンドラインオプションではなかなかこうはいかない。そして全部に適用したい場合にはexportしてしまっても良いし。
追記
そういえば、昔にrun_in_executor()を使えば大丈夫とは思わないでみたいな記事を書いたりしてた。
gist
いつもの
新しいgithub CLI toolのghコマンドが更新チェックをいつ行っているのか気になったので調べた
最近githubがhubの代わりにghという新しいgithub用のCLIツールを出していました。cli/cliという位置にあるので組織名とリポジトリ名がすごい。特等席。
例えばmacでは以下の様な形でインストールすると、このghコマンドが使える様になる。
$ brew install github/gh/gh # upgrade # brew update && brew upgrade gh
現在のcwdが所属していそうなgithub repositoryに対してその場でPRの作成ができたり、ステータスが見れたりとけっこう便利。
まぁそれは置いておいて、このghコマンドを使っていたときに、どうも自動で更新チェックをやってくれるようだった。これをどのタイミングでやっているのかなーと気になったのでソースコードを覗いて見たらなるほど～と思うことがあったのでメモをしておく。
ghコマンドの更新チェックのメッセージ
ghコマンドにアップデートがあったときにはどのようなメッセージが表示されるかというと以下の様な表示がされる。
$ gh pr status ... A new release of gh is available: 0.5.4 → v0.5.7 https://github.com/cli/cli/releases/tag/v0.5.7
まぁそういう感じで最新のバージョンを使うことを促される。 この更新チェックを行っている処理があるはず。
更新チェックを行っているコード
そんなわけでmain.goを覗いてみるとほとんどこのファイルそのものが答え。
なるほど、立ち上がると同時に徐にgoroutineを動かしていた。なるほど。これは賢い。
こういう感じのコードになっている(コメントは勝手に追加したもの)。
func main() { currentVersion := command.Version // 更新確認のためのgoroutineを起動 updateMessageChan := make(chan *update.ReleaseInfo) go func() { rel, _ := checkForUpdate(currentVersion) updateMessageChan <- rel }() // 通常の処理 hasDebug := os.Getenv("DEBUG") != "" if cmd, err := command.RootCmd.ExecuteC(); err != nil { printError(os.Stderr, err, cmd, hasDebug) os.Exit(1) } // 起動したgoroutineを待つ newRelease := <-updateMessageChan if newRelease != nil { // 更新があったときのメッセージ msg := fmt.Sprintf("%s %s → %s\n%s", ansi.Color("A new release of gh is available:", "yellow"), ansi.Color(currentVersion, "cyan"), ansi.Color(newRelease.Version, "cyan"), ansi.Color(newRelease.URL, "yellow")) stderr := utils.NewColorable(os.Stderr) fmt.Fprintf(stderr, "\n\n%s\n\n", msg) } }
なるほど。コマンドを立ち上げたタイミングで安直にgoroutineを立ち上げてしまえば良い。便利。
あとはふつうに通常の処理を書いてしまって、終了したタイミングでgoroutineを待てば良い。ふつう実行自体が終わったタイミングでは終了しているだろうし、githubに対するコマンドなどというのはネットワークがつながっていなければ何もできないのだから、常にrequestしてしまっても良い。
これは何か他にCLIのツールを作るときには参考になるかもしれないなーと思ったりした。
ちなみに更新チェックの処理自体の実装は
ちなみにcheckforUpdate()自体は以下の様な実装になっていて、pipeでつなげていたりしたときには省略されそうな感じ。
func shouldCheckForUpdate() bool { return updaterEnabled != "" && utils.IsTerminal(os.Stderr) } func checkForUpdate(currentVersion string) (*update.ReleaseInfo, error) { if !shouldCheckForUpdate() { return nil, nil } client, err := command.BasicClient() if err != nil { return nil, err } repo := updaterEnabled stateFilePath := path.Join(context.ConfigDir(), "state.yml") return update.CheckForUpdate(client, stateFilePath, repo, currentVersion) }
処理自体も特に複雑なことをしているわけではなくgithubのreleases apiを呼んで良い感じにやっていっているだけの模様。
$ http -b https://api.github.com/repos/cli/cli/releases
[
{
"assets": [
{
"browser_download_url": "https://github.com/cli/cli/releases/download/v0.5.7/gh_0.5.7_checksums.txt",
"content_type": "text/plain; charset=utf-8",
"created_at": "2020-02-20T22:23:34Z",
"download_count": 16,
"id": 18185843,
"label": "",
"name": "gh_0.5.7_checksums.txt",
"node_id": "MDEyOlJlbGVhc2VBc3NldDE4MTg1ODQz",
"size": 1100,
"state": "uploaded",
"updated_at": "2020-02-20T22:23:35Z",
"uploader": {
"avatar_url": "https://avatars2.githubusercontent.com/u/887?v=4",
"events_url": "https://api.github.com/users/mislav/events{/privacy}",
"followers_url": "https://api.github.com/users/mislav/followers",
"following_url": "https://api.github.com/users/mislav/following{/other_user}",
"gists_url": "https://api.github.com/users/mislav/gists{/gist_id}",
"gravatar_id": "",
"html_url": "https://github.com/mislav",
"id": 887,
"login": "mislav",
"node_id": "MDQ6VXNlcjg4Nw==",
"organizations_url": "https://api.github.com/users/mislav/orgs",
"received_events_url": "https://api.github.com/users/mislav/received_events",
"repos_url": "https://api.github.com/users/mislav/repos",
"site_admin": true,
"starred_url": "https://api.github.com/users/mislav/starred{/owner}{/repo}",
"subscriptions_url": "https://api.github.com/users/mislav/subscriptions",
"type": "User",
"url": "https://api.github.com/users/mislav"
},
"url": "https://api.github.com/repos/cli/cli/releases/assets/18185843"
},
...
]
