Exceptional logging of exceptions in Python

Aaron Maxwell は Powerful Python.

Exceptions happen(例外は起こる)の著者です。 そして、開発者として、私たちは単にそれらに対処しなければなりません。 ブリトーを見つけるのを助けるソフトウェアを書いているときでさえも。 私が言っていたように 例外をどのように扱うかは、言語によって異なります。 そして、大規模に動作するソフトウェアでは、ログはエラー条件を処理するための最も強力で貴重なツールの 1 つです。

「ビッグタープ」パターン

私たちは、1 つの極端な方法から始めるつもりです。 コードのブロック (すなわち main_loop()) が予期しない多くの例外を発生させることが分かっている、いくつかのコード パスに適しています。 そして、プログラムを終了させるよりも、エラー情報を記録し、そこから継続することが望ましいと判断します。 (logger はアプリケーションのロガー・オブジェクトで、例えば logging.getLogger() から返されたものです)。 この素晴らしいメソッドは、except ブロックのコンテキストで完全なスタックトレースをキャプチャし、それを完全に書き込みます。

ここで例外オブジェクトを渡す必要がないことに注意してください。 メッセージ文字列を渡す必要があります。 これは、完全なスタック トレースを記録しますが、メッセージの行を前に追加します。 つまり、ログに表示される複数行のメッセージは、次のようになります。 最初の行は logger.exception() に渡したメッセージで、その後の行は例外の型 (この場合は ZeroDivisionError) を含む完全なスタックトレースであることに注意してください。

デフォルトでは、logger.exception は ERROR のログレベルを使用します。

while True: try: main_loop() except Exception: logger.error("Fatal error in main loop", exc_info=True)

exc_info を True に設定すると、logger.exception() と同様に完全なスタックトレースを含むログが記録されます。 唯一の違いは、ログレベルをエラー以外のものに簡単に変更できることです。 たとえば、logger.errorlogger.warn に置き換えるだけです。

面白い事実: Big Tarp パターンには、ほとんど極悪非道な対極があります。 OpenBurrito SDK を使用しているとします。これは、現在地の近くにある深夜営業のブリトー ジョイントを見つけるという重要な問題を解決するライブラリです。 このライブラリにはfind_burrito_joints()という関数があり、通常、適切なレストランのリストを返します。 しかし、特定のまれな状況では、BurritoCriteriaConflict と呼ばれる例外が発生することがあります。

from openburrito import find_burrito_joints, BurritoCriteriaConflict# "criteria" is an object defining the kind of burritos you want.try: places = find_burrito_joints(criteria)except BurritoCriteriaConflict as err: logger.warn("Cannot resolve conflicting burrito criteria: {}".format(err.message)) places = list()

ここでのパターンは、いくつかのコード (この場合、find_burrito_joints() への呼び出し) を try ブロック内で最適に実行することです。 特定の例外タイプが発生した場合、メッセージを記録し、状況に対処し、次に進みます。

重要な違いは、except 節です。 Big Tarp では、基本的にあらゆる可能な例外をキャッチしてログに記録します。 ピンポイントでは、コード内の特定の場所で意味的に関連性のある、非常に特定の例外タイプをキャッチします。 (この記事では、warn() を目にしたときは、info()error() などで代用できます。) 言い換えると、スタックトレース全体を記録する代わりに、特定の重大度でメッセージを記録しています。 それは、コードのロジックで明確な意味を持つ特定の例外タイプをキャッチしているこのコンテキストでは、それほど有用ではないからです。 たとえば、次のスニペットでは、

characters = {"hero": "Homer", "villain": "Mr. Burns"}# Insert some code here that may or may not add a key called# "sidekick" to the characters dictionary.try: sidekick = charactersexcept KeyError: sidekick = "Milhouse"

ここで、KeyError は単なるエラーではありません。 このエラーが発生した場合、特定の状況が発生したことを意味します。つまり、私のキャラクタには「相棒」の役割が定義されていないため、デフォルトに戻らなければなりません。 スタックトレースでログを埋めても、このような状況には役に立ちません。

「Transformer」パターン

ここでは、例外をキャッチし、それをログに記録し、別の例外を発生させるということを行っています。

try: something()except SomeError as err: logger.warn("...") raise DifferentError() from err

Python 2 では “from err” を削除しなければなりません:

try: something()except SomeError as err: logger.warn("...") raise DifferentError()

(これは大きな意味を持つことがわかりました。

たとえば、深夜営業のブリトー店を見つけることができるキラー アプリのために openburrito SDK を使用しているとします。 この場合、find_burrito_joints() 関数は BurritoCriteriaConflict を発生させる可能性があります。 これは SDK によって公開される API ですが、アプリケーションの上位レベルのロジックに都合よくマッピングされるわけではありません。 コードのこの時点でよりよく適合するのは、NoMatchingRestaurants.

この状況では、次のようなパターンを適用します (Python 3 用):

from myexceptions import NoMatchingRestaurantstry: places = find_burrito_joints(criteria)except BurritoCriteriaConflict as err: logger.warn("Cannot resolve conflicting burrito criteria: {}".format(err.message)) raise NoMatchingRestaurants(criteria) from err

これはログに 1 行の出力を引き起こし、新しい例外をトリガします。 キャッチされなかった場合、その例外のエラー出力は次のようになります:

Traceback (most recent call last): File "transformerB3.py", line 8, in places = find_burrito_joints(criteria) File "/Users/amax/python-exception-logging-patterns/openburrito.py", line 7, in find_burrito_joints raise BurritoCriteriaConflictopenburrito.BurritoCriteriaConflictThe above exception was the direct cause of the following exception:Traceback (most recent call last): File "transformerB3.py", line 11, in raise NoMatchingRestaurants(criteria) from errmyexceptions.NoMatchingRestaurants: {'region': 'Chiapas'}

さて、これは興味深いものです。 この出力には NoMatchingRestaurants のスタックトレースが含まれています。 そして、BurritoCriteriaConflict を開始したことも報告しています…どちらがオリジナルであるかを明確に指定しています。

Python 3 では、例外を連結することができるようになりました。 raise ... from ... 構文がこれを提供します。 err から raise NoMatchingRestaurants(criteria) と言ったとき、それは typeNoMatchingRestaurants の例外を発生させます。 この発生した例外は__cause__という属性を持っており、その値は発生させた例外である。 Python 3 では、エラー情報を報告する際にこれを内部的に利用します。

Python 2 でこれを行うにはどうしたらよいでしょうか。 まあ、無理でしょう。 これは、アップグレードしないと手に入らないグッズの 1 つです。 Python 2 では、”raise … from” 構文はサポートされていないので、あなたの例外出力は NoMatchingRestaurants のスタックトレースだけを含むことになります。 Transformer パターンはもちろんまだ完全に有用です。

The “Message and Raise” Pattern

このパターンでは、特定のポイントで例外が発生したことを記録し、それが伝搬してより高いレベルで処理されるようにします:

try: something()except SomeError: logger.warn("...") raise

あなたは実際に例外を処理しているわけではありません。 イベントを記録するために一時的にフローを中断しているだけです。 具体的には、エラーに対するより高いレベルのハンドラーがあり、それにフォールバックしたい場合、さらにコードの特定の場所でエラーが発生したこと、またはその意味を記録したい場合に、これを行います。

「暗号化メッセージ」アンチパターン

次に、いくつかのアンチパターン…コードでやってはいけないことに目を向けます。

ERROR: something bad happened

ここで、実際のログに「何か悪いことが起こった」という言葉が表示されないことを祈りたいと思います。 しかし、実際に目にするログの文章は、同じように不可解なものであるかもしれません。

さて、まず最初に、この曖昧なメッセージがコード ベースのどこでログに記録されているかを把握することです。 運がよければ、コードをすばやく grep して、正確に 1 つの可能性を見つけることができます。 運が悪ければ、複数の全く異なるコードパスでログメッセージを見つけることができます。

  • これらのうちどれがエラーをトリガーしているのでしょうか。 あるいは、それらすべてですか?
  • ログのどのエントリがどの場所に対応していますか?

しかし、ログ テキストが生成されているため、どこで起こっているかを見つけるためにコードを grep または検索することさえできないことがあります。 Consider:

 what = "something" quality = "bad" event = "happened" logger.error("%s %s %s", what, quality, event)

どうやって検索したらいいのかすらわからない。 最初にフルフレーズで検索してヒットしない限り、思いつかないかもしれません。

理想的なソリューションは、exc_info 引数を渡すことです:

try: something()except Exception: logger.error("something bad happened", exc_info=True)

これを実行すると、アプリケーション ログに完全なスタック トレースが含まれます。 これにより、どのファイルのどの行が問題を引き起こしているか、誰がそれを呼び出したか、など、デバッグを開始するために必要なすべての情報が正確にわかります。

The Most Diabolical Python Antipattern

If you ever see this one, I will come to your house to confisculate your computers, then hack into your github account and delete all your repos:

try: something()except Exception: pass

The Most Diabolical Python Antipattern として、私のニュースレターに記載しています。 これは有用な例外情報を与えないだけでなく、どのようなものであるかに注目してください。 また、そもそも何かが間違っているという事実を完全に隠すことに成功しています。 すべての可能なトラブルシューティング情報が抑制されているため、夜明けまでかかって解明する方法で、生産が壊れているため、午前 2 時にページングされるまで、変数名を間違えたことにさえ気づかないかもしれません (そう、これは実際に NameError を隠しているのです)。 もし、単にすべてのエラーをキャッチして無視しなければならないと感じるなら、少なくともその下に大きなシートを投げなさい (すなわち、pass の代わりに logger.exception() を使う)。

その他の例外ログパターン

異なるトレードオフ、利点と欠点を持つ Python で例外情報をログする多くのパターンがあります。 どのようなパターンが有用で、あるいは有用でないと思われましたか。 コメントでみんなに知らせてください。

Loggly と SolarWinds の商標、サービスマーク、およびロゴは、SolarWinds Worldwide, LLC またはその関連会社の独占的な所有物です。 他のすべての商標はそれぞれの所有者の財産です。

コメントを残す

メールアドレスが公開されることはありません。