Azure Functions におけるロガーの扱いとフィルタの注意点

最近の Azure Functions 開発ではバインディングやトリガーなどに必要なものだけをメソッドのパラメータとして定義して、それ以外は全て DI を使ってコンストラクタから取るようにしていますが、Azure 上のみロガーから Application Insights に送信されない現象にはまったので残します。

結局のところは仕様で、ちゃんとドキュメントにも記載されているのですが、特定の環境では問答無用で Application Insights にログが出力される問題があったため解決に無駄な時間を要しました。

Azure Functions だと DI でゲッツした ILogger はデフォルトだとログ出ない設定になってるの罠すぎる

— しばやん (@shibayan) 2020年9月16日

恐らく一番シンプルな DI を使ったロガーのパターンは以下のようなものになります。

Azure Functions は歴史的にメソッドのパラメータとして ILogger を取るようになっていたため、たまに下位のメソッド呼び出し時にも ILogger を渡し続けていくコードが書かれたこともありました。

しかし今は DI 対象のクラスはコンストラクタで ILogger<T> を受け取れるので、ログを有効にしたまま Function の実装からさらに別クラスのメソッドを呼び出すのも簡単です。

public class Startup : FunctionsStartup
{
    public override void Configure(IFunctionsHostBuilder builder)
    {
        builder.Services.AddSingleton<IGreetingService, GreetingService>();
    }
}

public class GreetingService : IGreetingService
{
    public GreetingService(ILogger<GreetingService> logger)
    {
        _logger = logger;
    }

    private readonly ILogger<GreetingService> _logger;

    public string SayHello(string name)
    {
        _logger.LogInformation($"Invoke {nameof(SayHello)} method with {name}.");

        return $"Hello, {name}!";
    }
}

サービスクラスは抽象化された ILogger<T> だけ受け取れれば良いので、ASP.NET Core と Azure Functions 間での共有が簡単に出来るようになっているのも大きなポイントです。

実際に Web API は ASP.NET Core で実装しつつも、タイマーやイベントドリブンが必要な処理は Azure Functions を使う例で、同じ実装を DI 経由で利用できるのがかなり便利でした。

Function の実装クラスでは DI に登録したクラスを受け取りつつ、ILogger<T> も同時にコンストラクタで受け取るようにします。以下の例ではログの出力の違いを説明するためにメソッドにも ILogger を用意していますが、本質的には不要です。

public class Function1
{
    public Function1(IGreetingService greetingService, ILogger<Function1> logger)
    {
        _greetingService = greetingService;
        _logger = logger;
    }

    private readonly IGreetingService _greetingService;
    private readonly ILogger<Function1> _logger;

    [FunctionName("Function1")]
    public IActionResult Run([HttpTrigger(AuthorizationLevel.Function, "get")] HttpRequest req, ILogger log)
    {
        _logger.LogInformation("Logging from DI ILogger<T>.");

        log.LogInformation("Logging from Bind ILogger.");

        var message = _greetingService.SayHello(req.Query["name"]);

        return new OkObjectResult(message);
    }
}

この実装を Azure に作成した Function App に対してデプロイして実行してみると、バインディング経由で受け取った ILogger の内容しか Application Insights に出力されていないことが分かりますね。

ちなみに重要になるのがログのカテゴリです。Azure Functions はデフォルトで出力するログカテゴリを内部で保持しているので、それ以外のカテゴリは明示的に設定する必要があります。

もう原因は分かっているので host.json を弄って、今回のアプリケーション名前空間がカテゴリになっているログで Information 以上のレベルの場合は Application Insights に送信するようにします。

{
  "version": "2.0",
  "logging": {
    "applicationInsights": {
      "samplingExcludedTypes": "Request",
      "samplingSettings": {
        "isEnabled": true
      }
    },
    "logLevel": {
      "FunctionApp16": "Information"
    }
  }
}

修正後に再度デプロイを行い、実行してみると今度はちゃんと全てのログが出力されています。

カテゴリが名前空間 + クラス名になっていることも確認できます。

これだけ見ると簡単な話だったのですが、最悪なことに Azure Functions Runtime 3.0.14492 より以前のバージョンは、名前空間が Function から始まればフィルタをすり抜けてしまう問題がありました。

名前空間が Function から始まってたらログ送信は流石に雑すぎる。テンプレから適当に作ると FunctionApp** というプロジェクトだから無条件で送信されるという（

— しばやん (@shibayan) 2020年9月17日

今回は検証のために Visual Studio で新しく Function App を作ったのですが、デフォルトの名前空間が FunctionApp** なので正しく再現することが出来なかったというオチです。

しかも 2 週間ほど前に修正が行われて、この問題ではまった次の日にはデプロイされて直りました。

最後になりましたが、ローカル開発環境では何もしなくても全てのログが出力されます。

最近のランタイムアップデートで --verbose を付けないと Function が実行されたことすら表示されなくなったので、正直少し戸惑っています。少し注意が必要だと感じています。