OpenTelemetry .NETを理解する (4) Spanに情報を追加する

今回は、第2回目で計装したコードを基に、計測したSpanに情報を追加してみます。

tech.tanaka733.net

以下のコードを出発点にします。

app.MapGet("/weatherforecast", (ILogger<Program> logger, HttpContext context) =>
{
    var forecast = Enumerable.Range(1, 5).Select(index =>
       new WeatherForecast
       (
           DateTime.Now.AddDays(index),
           Random.Shared.Next(-20, 55),
           summaries[Random.Shared.Next(summaries.Length)]
       ))
        .ToArray();
    try
    {
        throw new Exception("error!!!!");
    }
    catch (Exception e)
    {
        logger.LogError(e, "error happened");
    }
    logger.LogInformation("Response1 length: {Length}", forecast.Length);
    return forecast;
})
.WithName("GetWeatherForecast");

今回の操作はOpenTelemetry .NETのドキュメントではここに記述されています。

opentelemetry.io

SpanとActivity

.NET には従来 System.Diagnostics.Activityという診断のために利用できるクラスがあります。

docs.microsoft.com

OpenTelemetry .NETでは（他の言語のOpenTelemetry実装と異なり）この言語備え付けの Activityを内部で利用しており、Activityを操作することでOpenTelemetryの計測も操作できるようになっています。この記事ではActivityクラスを使って操作する方法を紹介します。OpenTelemetryの仕様にもとづいたAPIで操作する方法もあり、そちらはOpenTelemetry Tracing Shimとして紹介されています。

Manual Instrumentation | OpenTelemetry

かんたんにいうと、ActivityとSpanは「計測するために区切られたある作業の単位」という同じ概念を表しています。

現在のSpanを取得する

第2回で紹介したASP.NET Coreで自動計装を適用している場合、Spanに情報を追加するためにはまず現在記録しているSpanを取得する必要があります。これはActivity.Currentプロパティで取得することが可能です。なお、計測していない場合などにnullが返る可能性があります。

app.MapGet("/weatherforecast", (ILogger<Program> logger, HttpContext context) =>
{
    var activity = Activity.Current;
    //以下略
}

タグを追加する

OpenTelemetryのSpanにはタグとよばれるキー・値のペアを追加することができます。タグの重要性については先日のObservability Conferenceの資料にも書いています。

tech.tanaka733.net

タグはActivity.SetTagメソッドで追加できます。

app.MapGet("/weatherforecast", (ILogger<Program> logger, HttpContext context) =>
{
    var activity = Activity.Current;
    activity?.SetTag("operation.value", 1);
    activity?.SetTag("operation.name", "Saying hello!");
    //以下略
}

イベントを追加する

Spanにイベントを追加することができます。イベントはTimestampと文字列情報およびキー値のペアを持つことができます。これはActivity.AddEventにActivityEventオブジェクトを渡して追加できます。ActivityEventのコンストラクタでこれらの情報を指定しますが、Timestampはデフォルトで現在時刻になるので、通常は指定しないことになります。

app.MapGet("/weatherforecast", (ILogger<Program> logger, HttpContext context) =>
{
    var activity = Activity.Current;
    activity?.SetTag("operation.value", 1);
    activity?.SetTag("operation.name", "Saying hello!");

    var spanTags = new ActivityTagsCollection(new KeyValuePair<string, object?>[]
        {
            new ("mode", "normal"),
            new ("speed", 10),
        });
    activity?.AddEvent(new ActivityEvent("Start", tags: spanTags));

    var forecast = Enumerable.Range(1, 5).Select(index =>
       new WeatherForecast
       (
           DateTime.Now.AddDays(index),
           Random.Shared.Next(-20, 55),
           summaries[Random.Shared.Next(summaries.Length)]
       ))
        .ToArray();
    
    activity?.AddEvent(new ActivityEvent("End"));
    logger.LogInformation("Response1 length: {Length}", forecast.Length);
    return forecast;
})
.WithName("GetWeatherForecast");

Spanの状態を設定する

これもObservability Conferenceにて発表したことにつながりますが、処理の中で異常な状態になった（通常例外が発生した）のであれば、Spanの状態もエラーとマークすべきです。これにより分析が可能になります。Activity.SetStatusというメソッドがあるのでこれで設定できるはずなのですが、現時点ではまだこのAPIを呼び出してもOpenTelemetry側のSpanの状態がマークされません。

try
    {
        throw new Exception("error!!!!");
    }
    catch (Exception e)
    {
        //これは現時点ではOpenTelemetry側に作用しない
        activity?.SetStatus(ActivityStatusCode.Error, "error happened.");
        
        logger.LogError(e, "error happened");
    }

この問題は以下のIssueで議論されています。

github.com

現時点ではotel.status_codeとotel.status_descriptionを使って手動でタグとして設定します。また、例外オブジェクトを記録したい場合、Activity.RecordExceptionを使うと例外オブジェクトを格納したイベントを追加してくれます。したがってcatch節に書くであろうコードはこうなります。

    try
    {
        throw new Exception("error!!!!");
    }
    catch (Exception e)
    {
        activity?.SetTag("otel.status_code", "ERROR");
        activity?.SetTag("otel.status_description", "error happened.");
        activity.RecordException(e);
        logger.LogError(e, "error happened");
    }

まとめ

以上でコードはこのようになります。

app.MapGet("/weatherforecast", (ILogger<Program> logger, HttpContext context) =>
{
    var activity = Activity.Current;
    activity?.SetTag("operation.value", 1);
    activity?.SetTag("operation.name", "Saying hello!");

    var spanTags = new ActivityTagsCollection(new []
        {
            new KeyValuePair<string, object?>("mode", "normal"),
            new KeyValuePair<string, object?>("speed", 10),
        });
    activity?.AddEvent(new ActivityEvent("Start", tags: spanTags));
    var forecast = Enumerable.Range(1, 5).Select(index =>
       new WeatherForecast
       (
           DateTime.Now.AddDays(index),
           Random.Shared.Next(-20, 55),
           summaries[Random.Shared.Next(summaries.Length)]
       ))
        .ToArray();
    try
    {
        throw new Exception("error!!!!");
    }
    catch (Exception e)
    {
        // このコードは https://github.com/open-telemetry/opentelemetry-dotnet/issues/2569 によりOpenTelemetry側に作用しない
        //activity?.SetStatus(ActivityStatusCode.Error, "error happened.");
        activity?.SetTag("otel.status_code", "ERROR");
        activity?.SetTag("otel.status_description", "error happened.");
        activity.RecordException(e);
        logger.LogError(e, "error happened");
    }
    activity?.AddEvent(new ActivityEvent("End"));
    logger.LogInformation("Response1 length: {Length}", forecast.Length);
    return forecast;
})
.WithName("GetWeatherForecast");