loggingに関する考え方、その後

前回: ログ出力のための print と import logging はやめてほしい

上記の記事、いまだに妙に人気があるんですが、最初に書いたのが2016年とめっちゃ古いんですよね……（この記事執筆時点で2020年）

私の意見がそう変わったわけでもないながらも、いま書ける補足というのもあるので、いったん書いておきます。

元記事の背景についての言い訳

他のOSSソフトウェアのログ周りのひっどい挙動を見たんです。で、「ムキー！」ってなりまして。その勢いで書いた文章なのです。

なんで、教科書のような正確さや、記事の「フェアさ」みたいのはまるで意識してませんでした。レビューなぞ、もちろん受けてないです。

ただまぁ……感情まみれの記事の割には（むしろ勘定まみれだったから？）、この記事は妙にいいね・LGTMついてまして……

読んでいる方の気持ちは、なんとなーくわかる気はします。プログラミングの中でもロギングの作法の話って、本やブログでも驚くほど書かれてない。そういうところかな、と。私も日々苦労してます。プログラミング言語毎に細部が結構違ったりするしね。

というわけで、単なるヒントレベルであっても記事が重宝されるのかなと。それは単純にありがたい。

で、上記の記事に限らないことですが、私の場合、QiitaなんかでLGTMやストックの通知があると、しばしば文章を読み直して文章を手直しします。その手直しの際に、当初の「ムキー」感がだんだんマイルドになっていて今の上の記事に至ります。内容についても、今見返しても「ま……、悪い話を書いているわけではないな」ということで、ちょっと意見変わってたりもするんですが、消したりはしてません。

ちなみに「そうじゃないぞ！」ってしっかりした反論記事が目に入ってこないのは実はちょっと残念です。「ぼくのかんがえたさいきょうのろぎんぐ」みたいにみんなが色々書いてくれると面白いかなぁ、なんて思ったりしてたんですけどね。

（コメントの指摘はよかったですね。見知った友人なんですけどね）

正しいロギング戦略をみんな考えてほしいし、共有してほしい

Pythonに限らず、ログというのは、ソフトウェアの運用時において、

• ユーザとの数少ない接点の一つになるもので、かつ
• 同時にプログラムとの数少ない接点の一つになるもの

です。これをソフトウェア開発の主要課題として真面目に考えないのは、ちとあり得ないとは思います。

その重要性にも関わらず、テストと比べてログについての考察が異様に少ないようにも思います。みんな手探りというか、自分の所属する分野や経験とにらめっこしつつ作り込んでいる、というのが印象です。

一方、後述することと被るのですが、ロギング戦略は共通項よりは分野（ドメイン）ごとに特異な点が生じることも多いと思っています。共有するにしても、単にベストプラクティスとして数行書き散らかすだけではなかなか共有知にはしづらい可能性は、ありますね。

良いロギング ⇔ 良いソフト

ログは上記のようにヒトとモノの「双方向」を向くものなので、ちょっと視点や主語がブレると、一瞬で「このログ、どういう意味？？？」となります。誰にとっての情報なのかがあまりに簡単にわからなくなってしまう。

良いログはユーザや運用者にとって良いソフトにつながる大事な要件、とも言える、かもしれません（まぁ直接のUIの方がずっと大事ですけどねその場合）

開発者以外の（良識ある）人が、レポートするまでもなく、自分の実行環境を見直せる、そういうログに着地させるには、そもそもエラーハンドリングとかソフトウェアの根っこの品質が良くないと無理だったりします。「こういう疑いがあるから、ここを調べてみてね！」というログを運用者に気軽に伝えられるログを出すソフトとはつまり、自分の能力と限界をしっかり見極めているソフトでなければならない、と思うのです。

WARNING: Found duplicate entries for the query "otemoyan". Choosing the first.

上のログは一例ですが、「何が起きていて」「何が問題視されていて」「ソフトはそこで何を選択したか」が分かるようにしています。暗黙に「通常このパターンで二重エントリはないはずなのだが、エラーというほどではないけど気をつけてください」という意図も暗示しています（しているつもりです）。もしそれがログの読み手に大事なら「誰がそのクエリを投げたか」もここに足すかもしれません。仮想例として、query部分が個人情報に当たるのなら、そこはプロダクション時にはぼかす必要があります。

このログが「良い」と思える前提がおそらくあり、文脈によってそれは「常に」異なります。

私の場合「顧客から提出されたログをag/grep程度で十分読み取れて、そこから顧客環境の問題を特定する」みたいなことを私がBtoBtoB向けの受託開発とかでやっていた時代があるからこういう例が出るんですが、そういう環境ではこの手のログは効く印象を持っていました。間に入っているサポートのヒトがその先の顧客対応をスムーズに対応できていた、ような、きがします（このあたりはあんまり感想とか聞かせてもらえないんですけどね、私のところにおしかりこなかったし、いいじゃんべつに）。

当時取りこぼしていた、今では大事だと思っていること

元の記事を書いてから相当経ったあとなんですが、指摘のなかで「なるほど、しまったな」と素直に思った最大の反省点というのがあります。

「ロギング戦術・戦略は、入り口から出口に至るまで、そのドメインに寄り添っている必要がある」

ん、どういうこと？

以下のような前提が、ロギング戦略にははっきりきっちりがっつり影響してくるはずなのです。

• 対象のプログラムの大きさで違う
• ソフトウェアが使われる分野（自分向け、社内サービス、小規模の受託、ベンチャー規模のBtoB、BtoC、それこそGoogle規模の世界規模サービス、モバイルフロントエンド）で違う
• 取り扱う（ログの）データサイズで違う
• ログの閲覧頻度、警告以上が発生した際の対処ルートで違う

元の記事では、ここがPythonという言語に絞った範囲においても雑でした。いやまぁそれにしても、Pythonの利用者は幅が広いですからねぇ……

言い訳的に言うと、私が当初想定していた規模感というのは「自分向け」「小規模の受託」くらいからはじめて「育てていく」ようなイメージでのソフトウェア開発でした。まず自分が使い、次に社内もしくは仕事をくれた発注者を含めた少数名、利用者はそのあと「もしかすると」増えるけど当初の負荷は大きくない、そういうイメージです。

一方例えば、設計のはじめから「世界規模サービス」を想定して開発をスタートしたソフトウェアにおけるロギング戦略は、大きく違うでしょう。例えばもともと人気のある大規模SaaSのリライトとかだったりすると、最初から相手は数千人とか数億人とか、何桁億QPSとか。

その場合、単純に言えばソフトウェアが出会う標準的な規模感が違ってくるはずで、開発当初から、ロギング戦略もそちらを第一着地点とするはずです。ログの分量、蓄積する速度（んで、そのログストリームが流れるインフラストラクチャの複雑度）も違います。

最初から想定している着地点も、はじめから大きい体系を意識するとおのずと変わります。私の（勝手な）感覚だと、規模が大きくなるほど、私が気にしているようなログレベルの細分化は意味がなくなり、ユーザ環境での発生頻度と実際の影響に意識を振り分ける必要が出てくるかと思います。まぁこのあたり、マジで当て推量ですけどねぇ……

そういった、読み手のドメインが自分のそれと一致するとは限らない中で一部で断定表現があったんですが、これは明らかに書き手として不適正だったなと思うわけです（ちなみに元記事側はあえて直してません。そういう記事なので、そのようにお楽しみください）

「ドメインが同じで意見が異なる」ならそれは意見の相違と、それをすり合わせる過程を意識して議論もしやすいのですが、考えているドメインが違う中ではすり合わせは厳しいことが多いです。「私が考えている領域はここ。それについてのロギング戦略はこれ」と伝えていなかったのは、振り返ってみるとよろしくない状況だったと言えます。

ちなみにPythonではないですが、私、モバイル業界でアプリ書いていたこともあるにはあるので、そのときにもロギング戦略を考えることはありました。元の記事を書く2016年よりさらに５年くらい前ですね。

このときには、まぁ……想定規模は確かに「世界規模」なんですが、それが一つのサーババックエンドにおける絶えざるログストリームとして流れ込んでくるわけではありませんでした。
対象は各個別の端末であり、それがパラで類似のログをバラバラと発生させるのです。このときのロギング戦略はサーバサイドの小規模ログ管理とは異なってきます。

大規模サーババックエンドとも少しは違うでしょうね。ソフトウェアバージョン、ハードウェアバージョンを意識させる流儀が変わってくるように思います。
「このエラーが出るときのログメッセージの文言を変えたのは、どのバージョンからだっけ」といったことがトラブルシューティングに効くことも、なくはないのです。

いずれにせよ、ソフトウェアがこれだけ社会に浸透していると、その動作の背景にある論理は全然違ってきて、それを支えるロギングについての考え方も、まぁ全然違ってくるでしょう。

今、試していること

上記のことをおいておきつつ、あくまで私のドメインに関して試していることを補足的に書いておきます。

関数に logger: Logger もしくは logger: Optional[Logger] を渡すというのを一部のプロジェクトでやっています。デフォルトとなる引数は指定しません。ただし None を明示的に渡すの許すことがあります（想定するソフトウェアの規模は「かなり小さい」と思ってください）

• Optional でないということは「必ずロガーを渡せ」ということです。これは粒度が非常に小さい関数であるとか、文脈（外部環境）への依存度が低いコンポーネントでそうしていることが多い気がします。
• Optional ということは「ロガーを渡したくなければNoneを渡せ」ということです。呼び出された側の関数ではオブジェクトが渡されればそれを使い、そうでなければその関数が所属するドメインの標準ロガーなどを使います

一時期 logger: Optional[Logger] = None も使っていましたがこれは悪手でした。暗黙にログが握りつぶされることがあり、非常に悲しい思いをするので、今は一旦２択です。２択である必要は、まぁないかもしれませんけどね。

この方法は「全体のログを掌握できる」「きめ細やかにコンポーネントの面倒を見られる」規模の開発くらいでしかおそらく役に立たないでしょう。自分が扱うサービスが規模が国内有力BtoCくらいだったら、負荷次第ですが、こんな戦略は多分とりません。

よって、この方法に汎用性はあまり「ない」と思いますが、ただ、私個人が扱う範囲では一貫してこうすることで、そのプロジェクトにおいてはログの見通しはだいぶ良くなりました。

そもそもここは、なんというか、規模の小ささに加えて「コダワリ」の部分があると思いますね。ログに対する拘りが良いか悪いか自体に議論の余地はあると思っていますが、 print()よりはましだよ、という点は変わりません。他の技術者がリーダーをしていてコーディング規約として別のロギング規約を設けたならそれに静かに従うでしょうね。

今、思案していること

これは以前とあまり変わらず、 Logger.info() と Logger.debug() だけでは粒度が荒すぎる問題です。 Logger.trace() (debug()より下。関数の開始と終了レベルまでこまかーく) ほしいなぁとか、(Zabbix用語かもですが) Logger.average() (warningより上、errorより下。もしくはinfoとwarningの間）がほしいなぁ、と思う瞬間があります（これもまた、ソフトウェア規模が大きくなるほどどうでもいい問題かもしれません）

Loggerのラッパーを作れば、多分「出来るは出来る」んですよね。PythonではDEBUG, INFO等は定数値であり、それらの定数値の間には十分な隙間がありますから (https://docs.python.org/3/library/logging.html#logging-levels)

ただ、言語やフレームワークの「標準」に寄り添う方が長期的には機能するという経験則もあり、直感的には「妙に悪賢い」感じがしないでもなく、ためらっている経緯があります。traceがはじめから入っているlogbackはただ羨ましい。

まとめ

今回は感情が高ぶっているということもなく適当に書いただけなので、面白い内容ではなかったかもしれませんが、一応フォローアップとして書いておきました。