OpenTelemetry – Teil 2: So nutzen Sie OpenTelemetry in VCL

Fastly Kunden betreiben meist komplexe, aus vielen verbundenen Systemen bestehende Architekturen. Fastly ist dabei nur eine von vielen PaaS-, SaaS-, Serverless-, Frontend- und nativen App-Komponenten. Zu oft beleuchten Observability-Tools wie Logging immer nur einen kleinen Teil des Gesamtsystems. Das erschwert die Diagnose von Problemen, wenn eine Transaktion mehrere Systeme durchläuft (und das ist im Grunde genommen bei jeder Transaktion der Fall!).

Sie sollten Ihre gesamte Architektur als eine Maschine aus einem Guss visualisieren und herausfinden können, was in jeder einzelnen Komponente dieser Maschine vor sich geht und welche dieser Komponenten Transaktionen durchlaufen. Das war schon immer ein großes Problem, und OpenTelemetry bietet eine passende Lösung. Im ersten Teil dieses Blogposts haben wir bereits ausgeführt, warum uns OpenTelemetry so begeistert. In diesem Teil werden wir uns damit befassen, wie Sie OpenTelemetry Daten von VCL-basierten Fastly Services erhalten können.

Das OpenTelemetry Protokoll unter der Lupe

Die Integration von OpenTelemetry in VCL stellt eine etwas andere Herausforderung dar als die Nutzung in einer vollumfänglich ausgestatteten Universalsprache wie JavaScript oder Go. VCL (wie von Fastly in unserem Kernprodukt ausgeführt) unterstützt keine Abhängigkeiten, verfügt nur über eine eingeschränkte Standardbibliothek und kann keine beliebigen HTTP-Anfragen ausführen.

Unsere Echtzeit-Logging-Plattform eignet sich jedoch ideal für das Senden serieller Daten an einen externen Datenverarbeiter und funktioniert ganz gut mit OpenTelemetry Collector. Wir können zwar keine der sprachspezifischen SDKs und Bibliotheken von OpenTelemetry ausführen, aber wir können die relevanten Daten zu einem String im Format des OpenTelemetry Protokolls zusammenfügen und per Echtzeit-Logging übermitteln.

Das ist gar nicht so kompliziert, wie es klingt, sondern sogar eine gute Möglichkeit, um etwas Licht ins Dunkel von OpenTelemetry zu bringen. Bei einem Blick in die Protokollspezifikation finden wir die Definitionen von trace span und log event und können diese Elemente in VCL nachbauen.

In diesem Blog gehen wir von einem Fastly Service mit individuellem VCL und unserer empfohlenen VCL-Standardvorlage aus. Wir würden jedoch auch mit VCL-Snippets zum Ziel kommen, wenn uns das lieber wäre. Zu Anfang generieren wir anhand entsprechender Hilfsunterprogramme für OTel geeignete Timestamps und Identifier (platzieren Sie diese ganz am Anfang der individuellen VCL-Datei oder in einem VCL-Snippet namens „init“):

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 verwendet Nanosekunden als Maßeinheit für die Zeit, die höchstmögliche Auflösung in VCL hingegen sind Mikrosekunden (μs). Wir können aber einen Zeitstempel in Nanosekunden erzeugen, indem wir die in Mikrosekunden angegebene Zeit mit 1.000 multiplizieren.

Außerdem teilen alle OpenTelemetry Objekte eine gemeinsame Definition einer „Ressource“ (siehe Spezifikation). Damit können wir ein Unterprogramm erstellen, das den entsprechenden Output für uns erzeugt (VCL hat keine Möglichkeit zum Serialisieren von JSON-Dateien, Sie müssen die String-Verkettungen also manuell vornehmen):

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;
}

Dank der Semantikkonventionen von OpenTelemetry können wir auch eine Reihe von Eigenschaften definieren, die mit anderen Systemen, die OTel Daten ausgeben, vergleichbar sind und überall dort integriert werden können, wo OpenTelemetry nach einer KeyValueList verlangt:

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;
}

Damit uns das möglichst viel nützt, wäre es ratsam, uns in diesem Unterprogramm auf die Variablen zu beschränken, die auch in allen VCL-Unterprogrammen verfügbar sind. Der VCL-Compiler verhindert das Aufrufen eines nutzerdefinierten Unterprogramms an einer Stelle im Workflow, an der eine Variable möglicherweise nicht definiert ist. So habe ich z. B. in den Namespaces bereq, beresp und obj nirgendwo Variablen verwendet, die nicht in allen Bestandteilen des VCL-Workflows verfügbar sind.

Das können wir nun zusammenfügen und Spans in VCL aufzeichnen. Wenn Sie einen Span über die gesamte Lebensdauer einer Anfrage in einem Fastly POP aufzeichnen möchten, können Sie damit am Anfang von vcl_recv beginnen:

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");
}

Anschließend fügen wir am Ende von vcl_log Folgendes ein:

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"}
    {"} ] } ]"}
  {"} ] }"}
;

Hier kombinieren wir den Output von otel_attributes_general() mit einigen weiteren Attributen, die nur in vcl_log verfügbar oder für diesen konkreten Span von Relevanz sind. Auch der Output von otel_resource() wird verkettet, und zwar als Wert eines resource-Keys.

Ein OpenTelemetry Span ist eigentlich gar nicht so schrecklich kompliziert – letztendlich kann ein Span als ein JSON-Snippet dargestellt werden. Zudem ist das Format in der Spezifikation recht präzise dokumentiert. Das Fehlen der JSON-Funktionen für Serialisierung in VCL macht den Code etwas „unschön“, aber ich hatte meinen Spaß dabei, zu erforschen, wie OpenTelemetry wirklich funktioniert.

Datenübertragung

Ein weiterer Unterschied zwischen VCL und Compute Services besteht darin, dass VCL keine beliebigen Backend Requests ausführen kann. Wir müssen die OTel Daten also auf andere Weise extrahieren.

Unsere Echtzeit-Logging-Plattform ist auf hocheffizientes Sammeln, Bündeln und Dispatchen von extrem hohen Volumina an Log-Meldungen ausgelegt, und es wäre nicht schlecht, wenn wir das nutzen könnten. Wir bieten den von OTel bevorzugten Protocol Buffer/gRPC als Typ für Logging Endpoints (noch) nicht an, aber wir unterstützen beliebige HTTP POST-Endpoints, und OpenTelemetry Collector unterstützt OTLP over HTTP POST als Übernahmemechanismus. Es gibt dabei allerdings noch ein paar Probleme/Einschränkungen:

1. Um die Nutzung von Fastly als DDoS-Plattform zu verhindern, verlangen wir, dass als HTTP-Logging-Endpoints hinzugefügte Hosts eine einfache, an /.well-known/fastly/logging/challenge gesendete Challenge korrekt beantworten müssen, um „teilnehmen zu dürfen“.

2. Unser Logging-System bündelt mehrere Log Events zu einem einzigen HTTP-Anfrage-Körper mit Zeilenumbruch als Trennzeichen. Der OpenTelemetry Collector kann das nicht entbündeln und erwartet immer nur ein einziges Event pro Anfrage.

3. Für Dinge, die nur zu einem bestimmten Zeitpunkt passieren, unterstützt OpenTelemetry ein Benachrichtigungsformat für Logs. Zum Zeitpunkt des Verfassens dieses Blogposts befand sich dieses allerdings noch in der Testphase, und es gibt in OpenTelemetry auch kein Tool zum Anhängen von Logs an Spans, selbst wenn Span und Trace-ID in den Log-Ereignissen vorhanden sind. Jedoch beinhaltet die Spezifikation von „trace“ das Konzept der Span-Ereignisse. Diese Ereignisse sind den Logs sehr ähnlich und werden von vielen Tools wie Honeycomb, Jaeger und Zipkin unterstützt.

Ich habe mich dafür entschieden, alle diese Probleme mit einem Schlag zu lösen, und zwar mit einem Proxy vor dem OpenTelemetry Collector. Aufgabe dieses Proxys ist es, Ereignisse mit mehreren Zeilen zu entbündeln, Logs in Span-Ereignisse zu konvertieren und die Opt-in Challenge von Fastly zu beantworten. Ich habe eine Beispiel-App dazu geschrieben und auf Glitch hochgeladen. Außerdem ist das eine gute Möglichkeit, die von Fastly ankommenden Daten ganz ohne OTel Collector zu validieren.

Weitergabe von Trace-Kontext

Die Weitergabe von Trace-Kontext macht es möglich, dass in Backend-Systemen auftretende Spans als untergeordnete Elemente von Fastly Spans sichtbar gemacht werden können. Insbesondere gilt das für die Spezifikation W3C Trace Context, die den Header traceparent beschreibt. Im oben aufgeführten VCL-Code haben wir bereits eine Trace-ID und eine ID des übergeordneten Elements übernommen, falls diese Bestandteile der von Fastly empfangenen Anfrage waren. Fastly muss die ID des Trace und des aktuellen Spans bei Anfragen an Backends weitergeben, damit das Backend einen untergeordneten Span ausgeben kann, der sich auf Fastly als übergeordnetes Element bezieht.  

Das erfolgt in VCL durch Erstellen eines weiteren nutzerdefinierten Unterprogramms und Aufrufen dieses Unterprogramms in vcl_miss und 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; 
}

Die erste Zeile dieses Unterprogramms fügt den Header traceparent in die von Fastly gesendeten Anfragen ein. Bei dieser Gelegenheit können wir auch die Telemetrie-Header entfernen. Diese Header werden intern zum Speichern des Status in VCL verwendet und sollten nicht an den Origin-Server weitergeleitet werden.

Und ich habe noch eine weitere Tücke mit OpenTelemetry gefunden. Einige der von mir ausprobierten PaaS-Provider (z. B. Google App Engine) verändern tatsächlich den traceparent-Header, wahrscheinlich weil ihr eigenes Tracing-System einen Span erkennt. Das Problem ist, wenn Ihr Collector keinen Zugriff auf die Daten dieses Spans hat, werden Ihre Backend-Spans von Ihren Edge-Spans abgetrennt (die Spans gehören zwar noch zum selben Trace, die Verschachtelung geht aber verloren). Hoffentlich bekommen die Cloud-Provider das in den Griff. Bis dahin können Sie als Notlösung einen x-traceparent-Header senden, der nichts weiter als eine Kopie von traceparent ist.

Solange jede unabhängige Komponente Ihres Systems eingehende traceparent-Header lesen und entgegennehmen und jeder ausgehenden HTTP-Anfrage einen hinzufügen kann, kann OpenTelemetry ein ganzheitliches Bild vom Weg einer einzelnen Transaktion durch das gesamte System erstellen. Fastly ist nur ein Bestandteil Ihres Systems, und wir wissen natürlich, dass es da noch andere Bestandteile gibt. Wir inspizieren die Dinge daher so genau wie möglich und bieten Hilfe wo möglich. Falls Sie zu denjenigen gehören, die Fastly VCL-Services mit OpenTelemetry nutzen, lassen Sie uns bitte wissen, wie gut Sie damit klarkommen.

Alle vier Teile unserer OpenTelemetry Blogserie sind nun online:

• OpenTelemetry – Teil 1: Die Edge rückt näher

• OpenTelemetry – Teil 2: So nutzen Sie OpenTelemetry in VCL

• OpenTelemetry – Teil 3: So nutzen Sie OpenTelemetry in Compute

• OpenTelemetry – Teil 4: So instrumentieren Sie Fastly Fiddle