xin9le.net

Microsoft の製品/技術が大好きな Microsoft MVP な管理人の技術ブログです。

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

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

  1. Azure Functions (Isolated Worker) を利用したい
    • .NET 7 を利用する場合はこれ一択
  2. Application Insights にログを出力するに際して下記 NuGet パッケージを利用する *1
  3. 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);
    });
});

ふたつ方法を載せましたが、必要な方を選べばよいと思います。僕は念のため (?) どちらも書いておきました。この実装を加えたものをデプロイしてログの出力状況を確認してみましょう。結果は以下の通りです。これで使い物になりそうですね!

*1:Microsoft.Azure.Functions.Worker.ApplicationInsights の NuGet Package を利用しない場合は再現しない