Zenn
📝

OpenTelemetry dotnetを触ってみた

2023/03/02に公開
.NET
C#
OpenTelemetry
tech

最近、オブザーバビリティ・エンジニアリングって本をよみまして、ちゃんとOpenTelemetryを触っとかなあかんなと思いまして、.NETで触ってみました。

https://www.oreilly.co.jp/books/9784814400126/

https://opentelemetry.io/

とりあえずトレースをだしてみる

まずは、トレースをだしてみるってことで、以下のNuGet参照を追加。

<PackageReference Include="OpenTelemetry" Version="1.4.0" />
<PackageReference Include="OpenTelemetry.Exporter.Console" Version="1.4.0" />
<PackageReference Include="OpenTelemetry.Extensions.Hosting" Version="1.4.0" />
<PackageReference Include="OpenTelemetry.Instrumentation.AspNetCore" Version="1.0.0-rc9.14" />

で、以下のように定義。

Action<ResourceBuilder> configureResource = r => r.AddService(
    serviceName: builder.Environment.ApplicationName,
    serviceVersion: "unknown",
    serviceInstanceId: Environment.MachineName);

builder.Services.AddOpenTelemetry()
    .ConfigureResource(configureResource)
    .WithTracing(tracingBuilder =>
    {
        tracingBuilder
            .AddSource(builder.Environment.ApplicationName)
            .AddAspNetCoreInstrumentation()
            .AddConsoleExporter();
    });

このコードは、サンプルコードから抜粋しました。

で、適当にエンドポイントを作って、

app.MapGet("/", () =>
{
    return "Hello!";
});

動かすと、以下のような内容がコンソールに出ました。

Activity.TraceId:            303401a59a8c2a0cd3e09f048654f45c
Activity.SpanId:             9819fac998acfd70
Activity.TraceFlags:         Recorded
Activity.ActivitySourceName: Microsoft.AspNetCore
Activity.DisplayName:        /
Activity.Kind:               Server
Activity.StartTime:          2023-03-02T12:31:31.8835068Z
Activity.Duration:           00:00:00.0010617
Activity.Tags:
    net.host.name: localhost
    net.host.port: 32768
    http.method: GET
    http.scheme: https
    http.target: /
    http.url: https://localhost:32768/
    http.flavor: 2.0
    http.user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36 Edg/110.0.1587.57
    http.status_code: 200
Resource associated with Activity:
    service.name: Api1
    service.version: unknown
    service.instance.id: 2e2eb45dc955

ちゃんと動いてるみたいですね。Durationとかが出てくれてるのがいいですね。

分散トレースしてみる

さっきはApi1ってプロジェクトをつくって試してました。次はサービスからサービス呼んだときにちゃんとトレースで紐づくかってのを見てみます。分散トレースってやつですね。

https://learn.microsoft.com/ja-jp/dotnet/core/diagnostics/distributed-tracing

もう一つApi2ってプロジェクトを作って、同じようなコードを入れます。で、Api1側のプロジェクトには以下の参照を追加。

<PackageReference Include="OpenTelemetry.Instrumentation.Http" Version="1.0.0-rc9.14" />

トレースの設定のところに以下を追加。

tracingBuilder
    .AddSource(builder.Environment.ApplicationName)
    .AddAspNetCoreInstrumentation()
    .AddHttpClientInstrumentation()  // 追加
    .AddConsoleExporter();

IHttpClientFactoryを使うのでいかも追加しておく必要があります。

builder.Services.AddHttpClient();

エンドポイントのコードは作ったApi2への呼び出しに変えます。

app.MapGet("", async (IHttpClientFactory httpClientFactory) =>
{
    var client = httpClientFactory.CreateClient();
    var res = await client.GetAsync("API2のエンドポイント");
    return await res.Content.ReadAsStringAsync();
});

動かすと、以下のような内容がコンソールに出ました。

Activity.TraceId:            66de2cf0da20a2c4d9f1aa94dd9b1569
Activity.SpanId:             fda9a9065c4510ad
Activity.TraceId:            66de2cf0da20a2c4d9f1aa94dd9b1569
Activity.TraceFlags:         Recorded
Activity.SpanId:             d0a9d019663d10e0
Activity.ParentSpanId:       fd943a5c12fa8d92
Activity.TraceFlags:         Recorded
Activity.ActivitySourceName: System.Net.Http
Activity.ParentSpanId:       fda9a9065c4510ad
Activity.DisplayName:        HTTP GET
Activity.ActivitySourceName: Microsoft.AspNetCore
Activity.Kind:               Client
Activity.DisplayName:        /
Activity.StartTime:          2023-03-02T12:46:42.1315495Z
Activity.Kind:               Server
Activity.Duration:           00:00:00.1461809
Activity.StartTime:          2023-03-02T12:46:42.2257641Z
Activity.Tags:
Activity.Duration:           00:00:00.0499019
    http.scheme: http
Activity.Tags:
    http.method: GET
    net.peer.name: api2
    net.host.name: api2
    http.url: http://api2:80/
    http.method: GET
    http.flavor: 1.1
    http.scheme: http
    http.status_code: 200
    http.target: /
Resource associated with Activity:
    service.name: Api1
    http.url: http://api2/
    service.version: unknown
    http.flavor: 1.1
    http.status_code: 200
    service.instance.id: 0febf98ffb8a

Activity.TraceId:            66de2cf0da20a2c4d9f1aa94dd9b1569
Activity.SpanId:             fd943a5c12fa8d92
Activity.TraceFlags:         Recorded
Activity.ActivitySourceName: Microsoft.AspNetCore
Activity.DisplayName:        /
Activity.Kind:               Server
Activity.StartTime:          2023-03-02T12:46:42.1147165Z
Activity.Duration:           00:00:00.1714342
Activity.Tags:
    net.host.name: localhost
    net.host.port: 50001
    http.method: GET
    http.scheme: https
    http.target: /
    http.url: https://localhost:50001/
    http.flavor: 2.0
    http.user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36 Edg/110.0.1587.57
    http.status_code: 200
Resource associated with Activity:
    service.name: Api1
    service.version: unknown
    service.instance.id: 0febf98ffb8a

出力されるタイミングは処理が終わったときなんで、Api2のほうが先にでて、Api1のほうが後にでるんですね。

なんか一つ目の出力されている項目が重複している(追記)

どうも一つ目の出力の項目(Activity.TraceIdとかActivity.SpanId)とかがよく見ると重複してますね。で差をみるとActivity.ActivitySourceNameにMicrosoft.AspNetCoreとSystem.Net.Httpって値がでてます。二つ目の出力のActivity.ActivitySourceNameはMicrosoft.AspNetCoreになっているので、System.Net.HttpはHttpClientを使った呼び出し部分がSpanに区切られてて、ほぼほぼ同時タイミングでMicrosoft.AspNetCoreの内容が出力されてしまってテレコになってる感じですね。

で、System.Net.Httpはなんで出力されているかっていうと、たぶん、AddHttpClientInstrumentation()してるからだと思うので、いったん消してみる。

tracingBuilder
    .AddSource(builder.Environment.ApplicationName)
    .AddAspNetCoreInstrumentation()
    // .AddHttpClientInstrumentation()  // やっぱりコメントアウト
    .AddConsoleExporter();

動かしてみる。

Activity.TraceId:            9a2bc7336413973c622226ae0b0be163
Activity.SpanId:             e9d05c7a53cc71d7
Activity.TraceFlags:         Recorded
Activity.ParentSpanId:       05f365358add02ca
Activity.ActivitySourceName: Microsoft.AspNetCore
info: System.Net.Http.HttpClient.Default.ClientHandler[101]
      Received HTTP response headers after 158.7272ms - 200
Activity.DisplayName:        /
Activity.Kind:               Server
Activity.StartTime:          2023-03-03T05:17:22.4883295Z
info: System.Net.Http.HttpClient.Default.LogicalHandler[101]
Activity.Duration:           00:00:00.0406333
      End processing HTTP request after 165.7368ms - 200
Activity.Tags:
    net.host.name: api2
    http.method: GET
    http.scheme: http
    http.target: /
    http.url: http://api2/
    http.flavor: 1.1
    http.status_code: 200
Resource associated with Activity:
    service.name: Api2
    service.version: unknown
    service.instance.id: f04942dc46cf

Activity.TraceId:            9a2bc7336413973c622226ae0b0be163
Activity.SpanId:             2a544b3e85c20e7e
Activity.TraceFlags:         Recorded
Activity.ActivitySourceName: Microsoft.AspNetCore
Activity.DisplayName:        /
Activity.Kind:               Server
Activity.StartTime:          2023-03-03T05:17:22.3644741Z
Activity.Duration:           00:00:00.1739884
Activity.Tags:
    net.host.name: localhost
    net.host.port: 50001
    http.method: GET
    http.scheme: https
    http.target: /
    http.url: https://localhost:50001/
    http.flavor: 2.0
    http.user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36 Edg/110.0.1587.57
    http.status_code: 200
Resource associated with Activity:
    service.name: Api1
    service.version: unknown
    service.instance.id: 3dc24192db7a

きれいに出ましたね。Activity.TraceIdは両方ともで同じ値になっています。どうやら、特に何もしなくてもHttpClientはtraceparentをヘッダーに乗せてくれるみたいですね。

コメントアウトしていた計装は戻しておきます。

tracingBuilder
    .AddSource(builder.Environment.ApplicationName)
    .AddAspNetCoreInstrumentation()
    .AddHttpClientInstrumentation()  // 復活
    .AddConsoleExporter();

Zipkinで見やすく見てみる

だらだらとテキストでコンソールに落とされても見にくいので、お手軽にDockerで立ち上げられるZipkinに出力してみました。

https://zipkin.io/

今回はdocker-compoeseで立ち上げます。

zipkin:
    image: ghcr.io/openzipkin/zipkin-slim:${TAG:-latest}
    container_name: zipkin
    hostname: zipkin
    environment:
        - STORAGE_TYPE=mem
    ports:
        - 9411:9411

Zipkinに出力するためのExporterをApi1とApi2に追加します。

<PackageReference Include="OpenTelemetry.Exporter.Zipkin" Version="1.4.0" />

設定も追加。

tracingBuilder
    .AddSource(builder.Environment.ApplicationName)
    .AddAspNetCoreInstrumentation()
    .AddHttpClientInstrumentation()
    .AddConsoleExporter()
    .AddZipkinExporter(zipkinConfig => // 追加
    {
        zipkinConfig.Endpoint = new Uri("http://zipkin:9411/api/v2/spans");
    });

で、動かしてZipkinの画面を見てみると、ちゃんとネストして見えますね！見やすい！

Zipkin

SQL Serverへのアクセスも落としてみる

SQL Serverへのアクセスも含められるみたいなので、含めてみます。今回はSQL Serverにつなぐので、そのライブラリも一緒に参照します。
Api2のほうに追加します。

<PackageReference Include="OpenTelemetry.Instrumentation.SqlClient" Version="1.0.0-rc9.14" />
<PackageReference Include="Microsoft.Data.SqlClient" Version="5.1.0" />

設定も追加。

tracingBuilder
    .AddSource(builder.Environment.ApplicationName)
    .AddAspNetCoreInstrumentation()
    .AddSqlClientInstrumentation(sqlConfig => // 追加
    {
        sqlConfig.SetDbStatementForText = true;　// SQL文を出力するように指定してみる
    })
    .AddConsoleExporter()
    .AddZipkinExporter(zipkinConfig =>
    {
        zipkinConfig.Endpoint = new Uri("http://zipkin:9411/api/v2/spans");
    });

データベース作ったりとかテーブル作ったりとかはメンドクサイので、とりあえずmasterデータベースにつないで、足し算のSELECTを流します。

app.MapGet("", async () =>
{
    using var connection = new SqlConnection("Data Source=sqldb;Initial Catalog=master;User ID=xxxx;Passwordxxxx;TrustServerCertificate=True");
    using var command = connection.CreateCommand();
    command.CommandText = "SELECT 1 + @val";
    command.CommandType = System.Data.CommandType.Text;
    command.Parameters.Add(new SqlParameter("@val", 1));
    await connection.OpenAsync();
    var result = await command.ExecuteScalarAsync();
    return $"hello api2, result = {result}";
});

で、動かして確認するとちゃんとDBの操作も、実行されたSQL文もでてますね。パラメーターの値まではでないようですが、それでちゃうとセキュリティ的にまずいこともあるので、問題ないでしょう。

DB Access

イベントを出力してみる

イベントも出力できる。これはOpenTelemetryのライブラリではなくって、.NET側のActivityを利用するようです。

app.MapGet("", async (IHttpClientFactory httpClientFactory) =>
{
    var client = httpClientFactory.CreateClient();

    Activity.Current?.AddEvent(new("Start api2 request"));

    var res = await client.GetAsync("http://api2:80/");

    Activity.Current?.AddEvent(new("Complete api2 request"));

    return await res.Content.ReadAsStringAsync();
});

ちゃんと、Api2へのリクエストの前後で出力されていますね。ちょっと見にくいですが。。。

Event

もうこれでいいんじゃないか

きほん、監査ログとかのような特定のログじゃない、トレース系はこれでいいんじゃないかと思う。自分でILoggerとか使って書く必要なさそう。

まぁ、実際アプリケーションに組み込むってなったらいろいろある

  • Zipkinみたいなの使えへんくってコンソールに出すときに複数行はこまるとか、
  • ユーザーIDだしたいとか、
  • ビジネスロジックはサービスクラスに分けてるから、そこでSpanつくりたいとか

などなど。

ざっと見た感じ、そこらへんも普通にできそうな感じです。あとはメトリクスとかログを見てみる感じですかね。

Discussion