OpenTelemetry 第2回 : VCL で OpenTelemetry を使用する

Fastly は、OpenTelemetry に対して高い期待を抱いています。コアクラウドプロバイダーで実行中のアプリケーションを観測するのと同様に、Fastly のサービスを観測し、エンドユーザーの体験をエンドツーエンドでマッピングすることで全体像を確認できるようにしたいと考えています。VCL サービスは OpenTelemetry データを出力し、その全体像の一部を構成することができます。

Fastly のお客様の多くが、相互に接続した多数のシステムで構成された複雑なアーキテクチャを採用しています。そのような環境において Fastly は、PaaS、SaaS、サーバーレス、フロントエンド、ネイティブアプリケーションといったさまざまなコンポーネントの中のひとつとして使用されています。通常、ログなどの可観測性ツールでは一度にシステムの一部分しか確認できないため、トランザクションが複数のシステムに及ぶ場合 (ほぼすべてのトランザクションがそうですが)、問題の診断が困難になります。

アーキテクチャ全体をひとつのシームレスなマシンとして可視化し、システム全体というコンテキストにおいて各部分で何が起こっているのか、また、ある場所から別の場所へのトランザクションの流れがどのように生じているのかを把握できるようにする必要があります。これは常に大きな課題でしたが、OpenTelemetry がその解決に役立ちます。このブログシリーズの第1回では、OpenTelemetry のメリットについてご説明しました。今回は、VCL を実行する Fastly サービスから OpenTelemetry データを出力する方法についてご説明します。

OpenTelemetry プロトコルの仕組み

OpenTelemetry を VCL に統合することは、JavaScript や Go などの、機能が豊富で汎用的な言語で OpenTelemetry を使用することとは少し異なります。(Fastly のコア配信プロダクト内で Fastly によって実行される) VCL は依存関係をサポートしておらず、標準ライブラリも限られており、任意の HTTP リクエストを実行できません。

しかし、Fastly のリアルタイム・ログ・プラットフォームは、シリアル化したデータを外部のプロセッサに送信するのに適しており、OpenTelemetry Collector とも問題なく連携します。そのため、OpenTelemetry の言語固有の SDK やライブラリは実行できませんが、該当データを OpenTelemetry プロトコル形式で文字列に並べ、リアルタイムログ機能を使用して出力することができます。

大変な作業のように聞こえるかもしれませんが、実際はそれほどでもなく、OpenTelemetry について理解を深めることができる優れた方法です。プロトコルの仕様を見ると、トレーススパンとログイベントの定義が確認でき、それらを VCL で構築できます。

このブログ記事の目的から、読者の皆さんの多くはカスタム VCL を使って Fastly のサービスを使用しており、最初は Fastly 推奨の VCL ボイラープレートをご利用いただいた方も多いと思いますが、お好みで VCL スニペットを使用することもできます。では、いくつかのユーティリティサブルーチンから開始し、OTel フレンドリーなタイムスタンプと識別子 (カスタム VCL ファイルの上部または「init」VCL スニペット内に配置) を生成してみましょう。

sub time_now_ns STRING {
  declare local var.time_now INTEGER;
  set var.time_now = std.atoi(time.start.usec);
  set var.time_now += std.atoi(time.elapsed.usec);
  set var.time_now *= 1000;
  return var.time_now;
}
sub random_8bit_identifier STRING {
  declare local var.id STRING;
  set var.id = randomstr(16, "0123456789abcdef");
  return var.id;
}
sub random_16bit_identifier STRING {
  declare local var.id STRING;
  set var.id = randomstr(32, "0123456789abcdef");
  return var.id;
}

OpenTelemetry の時間の単位はナノ秒で、VCL で使用可能な最高解像度はマイクロ秒 (μ秒) です。しかし、マイクロ秒時間に1,000を掛けることでナノ秒のタイムスタンプを作成できます。

次に、すべての OpenTelemetry オブジェクトには「リソース」の共通定義があります (仕様を参照)。そのため、サブルーチンを作成してそれを出力できます (VCL には JSON をシリアル化する方法がないため、少し手間がかかりますが文字列の連結を行う必要があります)。

sub otel_resource STRING {
  declare local var.str STRING;
  set var.str = {"{ "attributes": [ "}
    {"{ "key": "service.name",           "value": { "stringValue": "Fastly www"    } }, "}
    {"{ "key": "telemetry.sdk.language", "value": { "stringValue": "vcl"           } }, "}
    {"{ "key": "telemetry.sdk.name",     "value": { "stringValue": "opentelemetry" } }, "}
    {"{ "key": "telemetry.sdk.version",  "value": { "stringValue": "1.0.1"         } }, "}
    {"{ "key": "host.name",              "value": { "stringValue": ""} server.identity {"" } }"}
  {"], "droppedAttributesCount": 0 }"};
  return var.str;
}

OpenTelemetry のセマンティクスの規則によって、OTel データを出力する他のシステムと同等かつ、OpenTelemetry で KeyValueList が必要となる、あらゆる場所でのスプライスに適している再利用可能な一連のプロパティを定義することもできます。

sub otel_attributes_general STRING {
  declare local var.data STRING;
  set var.data = ""
    {"{ "key": "http.method",    "value": { "stringValue": ""} req.method {"" } },"}
    {"{ "key": "http.target",    "value": { "stringValue": ""} req.url {"" } },"}
    {"{ "key": "http.host",      "value": { "stringValue": ""} req.http.host {"" } },"}
    {"{ "key": "http.protocol",  "value": { "stringValue": ""} req.protocol {"" } },"}
    {"{ "key": "http.client_ip", "value": { "stringValue": ""} client.ip {"" } },"}

    {"{ "key": "fastly.restarts",     "value": { "stringValue": ""} req.restarts {"" } },"}
    {"{ "key": "fastly.visits_this_service", "value": { "stringValue": ""} fastly.ff.visits_this_service {"" } },"}
    {"{ "key": "fastly.server_role",  "value": { "stringValue": ""} req.http.x-trace-server-role {"" } },"}
    {"{ "key": "fastly.server_ip",    "value": { "stringValue": ""} server.ip {"" } },"}
    {"{ "key": "fastly.server_id",    "value": { "stringValue": ""} server.identity {"" } },"}
    {"{ "key": "fastly.server_role",  "value": { "stringValue": ""} req.http.x-trace-server-role {"" } },"}
    {"{ "key": "fastly.vcl_version",  "value": { "stringValue": ""} req.vcl.version {"" } },"}
    {"{ "key": "fastly.pop",          "value": { "stringValue": ""} server.datacenter {"" } },"}
    {"{ "key": "fastly.workspace.overflowed",  "value": { "stringValue": ""} workspace.overflowed {"" } },"}
    {"{ "key": "fastly.workspace.bytes_total", "value": { "stringValue": ""} workspace.bytes_total {"" } },"}
    {"{ "key": "fastly.workspace.bytes_free",  "value": { "stringValue": ""} workspace.bytes_free {"" } },"}
  ;
  return var.data;
}

この利便性を最大限に高めるため、このサブルーチンで使用される変数を、すべての VCL サブルーチンで使用可能なもののみに制限することをお勧めします。VCL コンパイラは、変数が定義されない可能性があるワークフローのロケーションからカスタムサブルーチンを呼び出すことを防ぎます。例えば、ここでは VCL ワークフローのすべての箇所で使用することのできない bereq、beresp、obj の名前空間の変数は使用していません。

これで、VCL でスパンを記録するためにまとめることができます。Fastly POP 内のリクエストのライフタイム全体にわたるスパンを記録する場合は、vcl_recv の始めに以下を使用します。

if (req.restarts == 0) {
  set req.http.x-trace-vcl-span-id = random_8bit_identifier();
  if (req.http.traceparent ~ "^\d+-(\w+)-(\w+)-\d+$") {
    set req.http.x-trace-id = re.group.1;
    set req.http.x-trace-parent-span-id = re.group.2;
  } else {
    set req.http.x-trace-id = random_16bit_identifier();
  }
  set req.http.x-trace-server-role = if (fastly.ff.visits_this_service == 0, "edge", "shield");
}

また、vcl_log の末尾に以下を使用します。

declare local var.otel_resource STRING;
declare local var.otel_attribs STRING;
declare local var.time_start_ns STRING;
declare local var.time_now_ns STRING;
set var.time_start_ns = time.start.usec "000";
set var.time_now_ns = time_now_ns();
set var.otel_resource = otel_resource();
set var.otel_attribs = otel_attributes_general();
log "syslog " req.service_id " otel_collector_http :: "
  {"{ "resourceSpans": [ { "}
    {""resource": "} var.otel_resource {", "}
    {""instrumentationLibrarySpans": [ { "spans": [ { "}
      {""traceId": ""} req.http.x-trace-id {"", "}
      {""spanId": ""} req.http.x-trace-vcl-span-id {"", "}
      if(req.http.x-trace-parent-span-id,
        {""parentSpanId": ""} req.http.x-trace-parent-span-id {"", "},
      "")
      {""name": "Fastly request processing", "}
      {""kind": 1, "}
      {""startTimeUnixNano": "} var.time_start_ns {", "}
      {""endTimeUnixNano": "} var.time_now_ns {", "}
      {""attributes": [ "}
        var.otel_attribs
        {"{ "key": "http.user_agent", "value": { "stringValue": ""} req.http.User-Agent {"" } }, "}
        {"{ "key": "http.status_code", "value": { "stringValue": ""} resp.status {"" } }"}
      {"], "}
      {""status": { "code":"} if (fastly_info.state ~ "ERROR", "2", "0") {" }, "}
      {""links": [], "}
      {""droppedLinksCount": 0"}
    {"} ] } ]"}
  {"} ] }"}
;

ここでは otel_attributes_general() の出力を、vcl_log のみで使用可能な、またはこの特定のスパンに該当する追加の属性と組み合わせています。また、otel_resource() の出力は、resource キーの値として連結されます。

OpenTelemetry のスパンは、実はそれほど複雑ではありません。最終的に JSON として表示され、仕様ではかなり正確に形式について説明されています。VCL には JSON をシリアル化する機能がないため、コードは若干複雑になりますが、OpenTelemetry が実際にどのように機能するのかよく理解することができます。

データの送信

VCL と Compute サービスのもうひとつの違いは、VCL では任意のバックエンドリクエストを実行できないという点です。つまり、OTel データを抽出する別の方法が必要です。

Fastly のリアルタイム・ログ・プラットフォームでは、膨大な量のログメッセージの収集、バッチ化、送信を非常に効率的に実行できるので、活用することをお勧めします。Fastly は現時点では OTel 推奨の protobuf/gRPC をログエンドポイントタイプとして提供していませんが、任意の HTTP POST エンドポイントをサポートしており、OpenTelemetry Collector は取り込みのメカニズムとして HTTP POST を介した OTLP をサポートしています。ただし、それでも問題や制限がいくつか存在します。

Fastly は、DDoS プラットフォームとして使用されることを防ぐため、HTTP ログエンドポイントとして追加されるホストが、/.well-known/fastly/logging/challenge に送信されるシンプルなチャレンジに応答することで「オプトイン」することを求めています。
Fastly のログシステムは、複数のログイベントをバッチ化し、改行処理で区切られた単一の HTTP リクエストボディにまとめます。OpenTelemetry Collector はこれらのバッチを解除することはできず、リクエストごとに1件のみのイベントがあると想定します。
ある時点で単発的に起こるイベントに対して、OpenTelemetry はログでメッセージ形式をサポートしています。現時点ではこれは試験的に行われており、スパンとトレース ID がログイベントに含まれていたとしても、ログをスパンにアタッチできる OpenTelemetry のツールはありません。ただし、トレースの仕様にはスパンイベントのコンセプトが含まれています。これはログによく似ていて、Honeycomb、Jaeger、Zipkin など多くのツールでサポートされています。

私は OpenTelemetry Collector の前にあるプロキシを使用して、これらの問題すべてを一度に解決することにしました。このプロキシの役割は、複数行のイベントのバッチ解除と、ログのスパンイベントへの変換、Fastly のオプトインチャレンジへの応答です。それらを行うサンプルアプリケーションを Glitch で作成しました。これは、OpenTelemetry Collector を使用せずに Fastly から送信されるデータを検証するのにも役立ちます。

トレースコンテキストの伝播

トレースコンテキストの伝播によって、バックエンドシステムで発生するスパンを同じトレース内の Fastly スパンの子として確認することができます。具体的には、traceparent ヘッダーについて説明している W3C Trace Context 仕様です。上記の VCL では、トレース ID と親スパン ID が、Fastly の受信したリクエストに含まれている場合、すでにそれらを適用しています。また、Fastly がバックエンドにリクエストを送信する際、トレースと現在のスパンの ID を転送し、バックエンドが Fastly スパンを親として参照する子スパンを出力できるようにする必要があります。

これは VCL で別のカスタムサブルーチンを作成し、vcl_miss や vcl_pass から呼び出すことで実行できます。

sub telem_start_backend_fetch {
  set bereq.http.traceparent = "00-" req.http.x-trace-id + "-" + req.http.x-trace-vcl-span-id "-01";
    
  # Avoid leaking internal headers to backends
  unset bereq.http.x-trace-id;
  unset bereq.http.x-trace-parent-span-id;
  unset bereq.http.x-trace-server-role;

  # Leapfrog cloud service infra that creates 'ghost spans'
  set bereq.http.x-traceparent = bereq.http.traceparent; 
}

このサブルーチンの1行目では、traceparent ヘッダーが Fastly から送信されるリクエストに追加されます。また、この機会を活用して、VCL でステートを保存するために内部で使用されているテレメトリヘッダーを削除し、オリジンへの転送を回避することもできます。

最後に、OpenTelemetry に関してもうひとつ問題があることがわかりました。試した複数の PaaS プロバイダー (Google の App Engine など) では traceparent ヘッダーを実際に変更しています。これはおそらく、独自のトレースシステムがスパンを記録しているためです。問題は、コレクターがそのスパンのデータにアクセスできない場合、バックエンドスパンがエッジスパンから切り離されるということです (少なくとも同じトレースに属しているものの、ネストに不具合が生じます)。今後、クラウドプロバイダーがこの問題を解決してくれると良いのですが、それまでは traceparent ヘッダーのコピーである x-traceparent ヘッダーを送信する回避策を利用できます。

システムの独立したすべてのコンポーネントが受信した traceparent ヘッダーを読み取り、実行し、送信される各 HTTP リクエストにこのヘッダーを追加できる限り、OpenTelemetry はシステム全体を移動する、単一のトランザクションを示す包括的なストーリーを作成できます。Fastly はお客様のシステムの一部であり、システムにはその他にもさまざまなコンポーネントが含まれていることを理解しています。そのため、可能な限り検査やデバッグがしやすいようにしたいと考えています。OpenTelemetry を使用して Fastly VCL サービスのインストルメント化を行う際は、ぜひ結果をお知らせください。

OpenTelemetry に関する全4回にわたるブログシリーズの記事をぜひご覧ください。

OpenTelemetry 第2回 : VCL で OpenTelemetry を使用する

OpenTelemetry プロトコルの仕組み

データの送信

トレースコンテキストの伝播

興味がおありですか？

Fastly を試してみませんか ?