Application Insights に送信される HTTP テレメトリに詳細な情報を付けたい

Application Insights をインストールしておけば、HTTP や SQL などの外部リソースへのアクセスを追跡してくれますが、HTTP の場合は URL とステータスコードぐらいしか情報がないので微妙な時があります。

HTTP レスポンスヘッダーに情報が入ってることが多いので調べてみると、ITelemetryInitializer を書くと最近のバージョンでは HTTP レスポンスの情報が取れるようになっていました。

凄く internal 向け感がありますが、これを使うとテレメトリに HTTP レスポンスの情報を追加できます。

とりあえず動作確認を兼ねて HTTP レスポンスヘッダーを、全てカスタムプロパティとして送信するコードを用意しました。ちなみに値が取れない場合もあるので存在チェックは必須です。

public class HttpResponseInitializer : ITelemetryInitializer
{
    public void Initialize(ITelemetry telemetry)
    {
        if (!(telemetry is DependencyTelemetry dependency))
        {
            return;
        }

        HttpResponseHeaders responseHeaders;

        if (dependency.TryGetOperationDetail("HttpResponse", out var details) && details is HttpResponseMessage response)
        {
            responseHeaders = response.Headers;
        }
        else if (dependency.TryGetOperationDetail("HttpResponseHeaders", out details) && details is HttpResponseHeaders headers)
        {
            responseHeaders = headers;
        }
        else
        {
            return;
        }

        foreach (var (key, value) in responseHeaders)
        {
            dependency.Properties.Add(key, value.FirstOrDefault());
        }
    }
}

適当に HTTP リクエストを投げてみると、ヘッダー情報が送信されていることが確認できます。

後は欲しい情報だけ選別して、適切なプロパティやメトリックとして追加するだけです。

レスポンスボディも送信する

先ほどはレスポンスヘッダーを送信してみましたが、一応レスポンスボディも読み取ることが出来るみたいなので、以下のようにすればエラー時のみレスポンスボディを送信という処理も書けます。

public class HttpResponseInitializer : ITelemetryInitializer
{
    public void Initialize(ITelemetry telemetry)
    {
        if (!(telemetry is DependencyTelemetry dependency))
        {
            return;
        }

        HttpResponseHeaders responseHeaders;

        if (dependency.TryGetOperationDetail("HttpResponse", out var details) && details is HttpResponseMessage response)
        {
            responseHeaders = response.Headers;

            if (!response.IsSuccessStatusCode)
            {
                var content = response.Content.ReadAsStringAsync().GetAwaiter().GetResult();

                dependency.Properties.Add("responseBody", content);
            }
        }
        else if (dependency.TryGetOperationDetail("HttpResponseHeaders", out details) && details is HttpResponseHeaders headers)
        {
            responseHeaders = headers;
        }
        else
        {
            return;
        }

        foreach (var (key, value) in responseHeaders)
        {
            dependency.Properties.Add(key, value.FirstOrDefault());
        }
    }
}

存在しない URL に対してリクエストを実行してみると、ちゃんとレスポンスボディが含まれています。

非同期周りの処理がどうしても怪しくなってしまうのと、データサイズが大きすぎる場合もあるので基本的にはお勧めは出来ないですが、一括で対応できるのは魅力的ではあります。

Cosmos DB でも利用する

Application Insights がデフォルトで解析できるのは HTTP と SQL だけなので、Cosmos DB を Direct モードかつ TCP で使っているとリクエストが取れないです。仕方ないので Gateway に切り替えて使う形になります。

Cosmos DB v3 の最新プレビューでは CosmosClientBuilder を使って設定する必要があるみたいです。前のプレビューから割と API が変更されているので注意。

services.AddSingleton(_ => new CosmosClientBuilder("AccountEndpoint=https://***.documents.azure.com:443/;AccountKey=***;")
                           .UseConnectionModeGateway()
                           .Build());

これで先ほど使った HTTP レスポンスヘッダーを送信するコードが動作します。実際に Application Insights で送信されていることが確認できます。

Cosmos DB はレスポンスヘッダーでいろんな情報が取れるようになってるので、これをさらに整形して Application Insights に送信すると扱いやすくなります。

消費された RUs を送信する

最初にやりたいことは RUs の確認だと思います。前に Application Insights SDK を使って手動で Custom Event として送信しましたが、今回の方法を使うとリクエストと紐づいた形になるので見やすくなります。

消費した RUs の値は x-ms-request-charge として返ってくるので、単純にその値をカスタムメトリックとして追加するだけです。簡単なコードですね。

public class CosmosRequestChargeInitializer : ITelemetryInitializer
{
    public void Initialize(ITelemetry telemetry)
    {
        if (!(telemetry is DependencyTelemetry dependency))
        {
            return;
        }

        if (dependency.Type != "Azure DocumentDB")
        {
            return;
        }

        HttpResponseHeaders responseHeaders;

        if (dependency.TryGetOperationDetail("HttpResponse", out var details) && details is HttpResponseMessage response)
        {
            responseHeaders = response.Headers;
        }
        else if (dependency.TryGetOperationDetail("HttpResponseHeaders", out details) && details is HttpResponseHeaders headers)
        {
            responseHeaders = headers;
        }
        else
        {
            return;
        }

        if (responseHeaders.TryGetValues("x-ms-request-charge", out var requestCharge))
        {
            dependency.Metrics.Add("RUs", double.Parse(requestCharge.First()));
        }
    }
}

これで消費した RUs が送信されていくので、Application Insights でグラフも描けるようになります。

Cosmos DB へのリクエストテレメトリに紐づけているので、ログエントリが増えることなく扱えます。

実行された SQL を付ける

実際に Cosmos DB を使った開発中には特定のクエリが極端に RUs を消費してしまって、その特定に時間がかかってしまったので実行した SQL も送信したいケースがありました。

今回のように ITelemetryInitializer を使うと実行した SQL も取得できますが、あまりお勧めできない書き方になってしまいます。どうしても必要な時ぐらいに留めておきたいです。

public class CosmosDependencyInitializer : ITelemetryInitializer
{
    public void Initialize(ITelemetry telemetry)
    {
        if (!(telemetry is DependencyTelemetry dependency))
        {
            return;
        }

        if (dependency.Type != "Azure DocumentDB")
        {
            return;
        }

        if (dependency.TryGetOperationDetail("HttpRequest", out var details) && details is HttpRequestMessage request)
        {
            if (request.Method == HttpMethod.Post && dependency.Name == "Query documents")
            {
                dynamic requestBody = JsonConvert.DeserializeObject(request.Content.ReadAsStringAsync().GetAwaiter().GetResult());

                dependency.Data = (string)requestBody.query;
            }
        }

        HttpResponseHeaders responseHeaders;

        if (dependency.TryGetOperationDetail("HttpResponse", out details) && details is HttpResponseMessage response)
        {
            responseHeaders = response.Headers;
        }
        else if (dependency.TryGetOperationDetail("HttpResponseHeaders", out details) && details is HttpResponseHeaders headers)
        {
            responseHeaders = headers;
        }
        else
        {
            return;
        }

        if (responseHeaders.TryGetValues("x-ms-request-charge", out var requestCharge))
        {
            dependency.Metrics.Add("RUs", double.Parse(requestCharge.First()));
        }
    }
}

実行された HTTP リクエストボディも取得して、中身の JSON をパースして SQL を取り出しています。

コードは怪しいですが、実行すると以下のように理想的な形でテレメトリを確認できます。

どのコレクションに対して、どのようなクエリが実行され、消費された RUs まで 1 つのログで確認できます。SQL を使った時と同じようなログになったので、使う機会があれば入れてみようかなと思います。