Azure Functionsの分離ワーカープロセスで指定したミドルウェアのログの出方が独特

リクエストとレスポンスと、Functionsとミドルウェアの関係を表した図です。

11月から異様に忙しく、落ち着いたと思ったら前回のポストから1ヵ月以上開いていました。

さて、今日は再び技術ネタをひとつ。

Azure Functionsの分離ワーカープロセスは、ミドルウェアという機能を持っています。

分離ワーカー プロセスにおける C# Azure Functions の実行のガイド

公式の情報によれば「関数の実行前と実行後にロジックを挿入したりすることができます。」となっており、例えばHttpTrrigerのハンドラを考えると、冒頭の図のような実行モデルであることが推測できます。

つまり、RequestはFunctionsよりも前にMiddlewareの層を通過し、Functionsで処理された後Middlewareの層を抜けてResponseとして返っていくイメージです。

これを考えて、私はAzureのログはRequestを受け付けたログの次にMiddlewareで出しているログ、次いで図中のHttpTrriger Functionsの実行を開始するログの順でログが出てくると思っていました。

しかし、実際にログを出力して参照してみるとわかるのですが、ログの見え方としてはRequestのログ→HttpTrriger Functionsの実行を開始するログ→Middlewareのログとして出力されます。

つまり、ログ中に Exectuing 'HttpTrriger Functions...' のようなメッセージが出力されているタイミングでは、まだMiddlewareの処理は始まっていないのです。

もしもRequest~最初の実行ログまでの間に何かトラブルが生じていたとしても、それはユーザ側で管理できるものではなく、マイクロソフトに問い合わせが必要な内容になると思われます。

こんなログの出方に驚かされるとは思っても見ませんでしたので、備忘録的にメモしておきます。