Azure Functions (Isolated Worker) で AppInsights に出力したログが LogLevel.Warning 以上にフィルターされてしまう問題への対処

タイトルがだいぶ長いんですが、執筆時点でタイトル通りの問題が発生します。最近 .NET 7 がリリースされたので、業務コードを順次 C# 11 / .NET 7 へ移行を開始しています。そんな中 Azure Functions を In-Process Model から Isolated Model に乗せ換えるにあたって Application Insights のログ周りでハマったので、今回はその回避方法を紹介します。まずは発生状況を箇条書きで整理しましょう。

Azure Functions (Isolated Worker) を利用したい
- .NET 7 を利用する場合はこれ一択
Application Insights にログを出力するに際して下記 NuGet パッケージを利用する *1
- Microsoft.Azure.Functions.Worker.ApplicationInsights
- AppInsights 向けの設定を Programmable に変更したい場合には間違いなく利用する
LogLevel.Warning 未満のログを出力したい
- LogLevel.Information とか高頻度で使いますよね？

つまり .NET 7 + Azure Functions の環境では発生しそうです。

問題を再現させてみる

Step.1 : NuGet Package を参照

先に示した通り Microsoft.Azure.Functions.Worker.ApplicationInsights のパッケージを参照します。執筆時点では 1.0.0-preview3 が最新です。

<ItemGroup>
    <PackageReference Include="Microsoft.Azure.Functions.Worker" Version="1.10.0" />
    <PackageReference Include="Microsoft.Azure.Functions.Worker.ApplicationInsights" Version="1.0.0-preview3" />
    <PackageReference Include="Microsoft.Azure.Functions.Worker.Extensions.Http" Version="3.0.13" />
    <PackageReference Include="Microsoft.Azure.Functions.Worker.Sdk" Version="1.7.0" />
</ItemGroup>

Step.2 : AppInsights SDK を DI に登録

公式の Isolated Process Model の導入ガイドにも書かれていますが、以下のような初期化コードを書きましょう。

new HostBuilder().ConfigureFunctionsWorkerDefaults(static (context, builder) =>
{
    builder.AddApplicationInsights();
    builder.AddApplicationInsightsLogger();
});

Step.3 : 関数を実装

検証目的ということで、今回は HttpTrigger が叩かれた際に全ての LogLevel を出力するコードを書いていきます。

public sealed class SampleFunction
{
    [Function(nameof(SampleFunction))]
    public async Task<HttpResponseData> EntryPoint(
        [HttpTrigger(AuthorizationLevel.Anonymous, "get")] HttpRequestData request,
        FunctionContext context)
    {
        var logger = context.GetLogger<SampleFunction>();
        var levels = new[]
        {
            // わかりやすいように Enum.GetValues<LogLevel>() と同じ配列を自前で作る
            LogLevel.Trace,        // 0
            LogLevel.Debug,        // 1
            LogLevel.Information,  // 2
            LogLevel.Warning,      // 3
            LogLevel.Error,        // 4
            LogLevel.Critical,     // 5
            LogLevel.None,         // 6
        };
        foreach (var x in levels)
        {
            await Task.Delay(10);  // ログの出力順が綺麗になるように少し delay を入れておく
            logger.Log(x, "LogLevel.{LogLevel}", x);
        }

        return request.CreateResponse(HttpStatusCode.OK);
    }
}

Step.4 : `LogLevel` の設定を環境変数に追加

最後に Azure Functions のインスタンスの環境変数として以下を設定します。Application Insights に出力する LogLevel を最低の Trace に設定しておきます。

{
    "Logging": {
        "ApplicationInsights": {
            "LogLevel": {
                "Default": "Trace"
            }
        }
    }
}

実行結果

ザックリとな再現手順の解説でしたが、ここまで終わりです。実際に Azure Functions に Zip Deploy をして API を叩いてみましょう。すると次のようなログが出力されます。

見事に LogLevel.Warning 以上ですね。困ったぞ、と。

原因

ではどこでこのフィルターが働いているのかというと、AppInsights の Core SDK の奥底にある既定のフィルタールールに依ります。

// The default behavior is to capture only logs above Warning level from all categories.
// This can achieved with this code level filter -> loggingBuilder.AddFilter<Microsoft.Extensions.Logging.ApplicationInsights.ApplicationInsightsLoggerProvider>("",LogLevel.Warning);
// However, this will make it impossible to override this behavior from Configuration like below using appsettings.json:
// {
//     "Logging": {
//         "ApplicationInsights": {
//             "LogLevel": {
//                 "": "Error"
//             }
//         }
//     },
//     ...
// }
// The reason is as both rules will match the filter, the last one added wins.
// To ensure that the default filter is in the beginning of filter rules, so that user override from Configuration will always win,
// we add code filter rule to the 0th position as below.

loggingBuilder.Services.Configure<LoggerFilterOptions>(static options =>
{
    options.Rules.Insert(0, new LoggerFilterRule
    (
        "Microsoft.Extensions.Logging.ApplicationInsights.ApplicationInsightsLoggerProvider",
        null,
        LogLevel.Warning,
        null
    ));
});

これまでの In-Process Model な Azure Functions では環境変数等に書いた LogLevel がこのフィルタールールを override する形で設定されていました。これは ASP.NET Core + App Service でも同じ挙動ですし、AppInsights のコード上にもコメントで「ユーザー設定で override できるように 0 番目に挿入する」というメモまで残っています。ですが、Isolated Model 向けの AppInsights SDK を利用するとその意に反して override されない状態になっています。Isolated Model 向け SDK の初期化順序が良くないということなんだと思います。

回避方法

実運用において LogLevel.Information が出ないのは全く使い物にならないということで workaround していきましょう。初期化処理に以下のようなコードを付け加えます。

new HostBuilder().ConfigureFunctionsWorkerDefaults(static (context, builder) =>
{
    builder.AddApplicationInsights();
    builder.AddApplicationInsightsLogger();

    // 方法 1 : 構成情報で上書きする
    builder.Services.AddLogging(logging =>
    {
        var config = context.Configuration.GetSection("Logging");
        logging.AddConfiguration(config);
    });

    // 方法 2 : AppInsights 向け LoggerProvider の特別ルールを削除して既定に戻す
    builder.Services.Configure<LoggerFilterOptions>(static options =>
    {
        var rule = options.Rules.FirstOrDefault(static x => x.ProviderName == typeof(ApplicationInsightsLoggerProvider).FullName);
        if (rule is not null)
            options.Rules.Remove(rule);
    });
});