OpenTelemetry (II): uso de OpenTelemetry en VCL

Los clientes de Fastly suelen tener complejas arquitecturas compuestas por múltiples sistemas interconectados, y Fastly es un elemento más de entre PaaS, SaaS, frontend sin servidores y aplicaciones nativas. Sin embargo, las herramientas de observabilidad, como los registros, a menudo carecen de una visión de conjunto del sistema. Esto dificulta el diagnóstico de problemas cuando una transacción ha transitado por varios sistemas, lo que ocurre muy a menudo.

Deberías poder visualizar tu arquitectura en su totalidad y saber qué ocurre en cada sección, es decir, cómo fluyen las transacciones de un extremo a otro. Esta ha sido siempre una cuestión trascendental, y ahora OpenTelemetry puede ayudarte a resolverla. En la primera parte de esta serie de artículos, te explicamos qué es lo que nos encanta de OpenTelemetry. En este artículo analizaremos cómo puedes emitir datos de OpenTelemetry desde servicios de Fastly que ejecutan VCL.

El protocolo OpenTelemetry, al detalle

Integrar OpenTelemetry en VCL es un reto que difiere bastante de su uso en un lenguaje general y completo como JavaScript o Go. VCL (lenguaje que en Fastly ejecutamos dentro de nuestro principal producto de distribución) no admite dependencias, tiene una biblioteca de serie muy limitada y no puede realizar peticiones HTTP arbitrarias.

Sin embargo, nuestra plataforma de registro en tiempo real es perfecta para enviar datos serializados a un procesador externo y funciona bien con OpenTelemetry Collector. Así que, aunque no podemos ejecutar los SDK ni las bibliotecas de OpenTelemetry, que son específicos del lenguaje, podemos reconstruir los datos pertinentes, formar una cadena que tenga el formato del protocolo OpenTelemetry y emitirla con el registro en tiempo real.

Esto no debería dar tanto respeto y, de hecho, es una forma estupenda de perderle el miedo a OpenTelemetry. Si analizamos la especificación del protocolo, observamos que se define lo que es un trace span (intervalo de seguimiento) y un log event (evento de registro). A partir de ahí, podemos programarlos en VCL.

Suponemos que tienes un servicio de Fastly con VCL personalizado y que has empezado con nuestro VCL estándar recomendado, aunque llegarías al mismo punto con fragmentos de VCL si lo prefieres. Empieza con varias subrutinas de utilidad para generar marcas de tiempo e identificadores compatibles con OpenTelemetry: colócalos al principio de tu archivo de VCL personalizado o en un fragmento de VCL del tipo «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;
}

La unidad de tiempo de OpenTelemetry es el nanosegundo (ns), mientras que la medida más alta disponible en VCL es el microsegundo (μs). No pasa nada: podemos crear una marca de tiempo de nanosegundo multiplicando el tiempo en microsegundos por 1000.

Lo siguiente que debemos saber es que todos los objetos de OpenTelemetry comparten una misma definición de «resource» (recurso) (consulta las especificaciones aquí). Ya podemos dar instrucciones a una subrutina para que genere eso mismo, pero prepárate para concatenar cadenas, ya que no se puede serializar JSON con VCL:

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

Gracias a las convenciones semánticas de OpenTelemetry, podemos definir también bastantes propiedades reutilizables que se parecen a las de otros sistemas que generan datos de OpenTelemetry y que permiten insertar código donde OpenTelemetry quiera una 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;
}

Para agilizar todo el proceso, conviene limitar las variables utilizadas en esta subrutina a las disponibles en todas las subrutinas VCL. Por lo general, el compilador de VCL impide que hagas una llamada a una subrutina personalizada desde un lugar del flujo de trabajo en el que no se haya definido una variable. Por eso no hemos utilizado variables en los espacios de nombres bereq, beresp u obj, que no están disponibles en todas las partes del flujo de trabajo de VCL.

Ya podemos implementar nuestra propuesta para registrar intervalos en VCL. Si te interesa registrar un intervalo que abarque toda la vida útil de una petición dentro de un POP de Fastly, podrías empezar con este fragmento al principio de 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");
}

Luego, añade este otro fragmento al final de 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"}
    {"} ] } ]"}
  {"} ] }"}
;

Lo que hacemos con estas adiciones es combinar la salida de otel_attributes_general() con otros atributos que solo están disponibles en vcl_log o que están relacionados con este intervalo en concreto. La salida de otel_resource() también queda concatenada como valor de la clave resource.

Los intervalos de OpenTelemetry son fáciles de entender, siempre se pueden representar en forma de código JSON, y la especificación describe el formato de manera precisa. Aunque a VCL le faltan funciones para serializar el código JSON y eso se traduce en un código poco aseado, disfrutamos aprendiendo cómo funciona OpenTelemetry.

Transferencia de datos

Otro aspecto que diferencia a los servicios VCL de los servicios Compute es que VCL no puede realizar peticiones de backend arbitrarias. Es decir, necesitamos otra forma de extraer los datos de OpenTelemetry.

Nuestra plataforma de registro en tiempo real está diseñada para recopilar, procesar por lotes y enviar volúmenes extremadamente altos de mensajes de registro con eficacia. ¡Aprovechemos esta ventaja! Aunque como tipo de punto de conexión de registro no ofrecemos (aún) protobuf/gRPC (el ideal para OpenTelemetry), sí que admitimos puntos de conexión HTTP POST arbitrarios. Además, OpenTelemetry Collector admite OTLP mediante HTTP POST como mecanismo de ingesta. Aun así, seguimos teniendo algunos problemas o limitaciones.

1. Por ejemplo, se podría utilizar Fastly como base para ejecutar ataques de DDoS. Para impedirlo, los hosts que añadas como puntos de conexión de registro HTTP deben «confirmar su participación» respondiendo a un desafío sencillo que enviamos a /.well-known/fastly/logging/challenge.

2. Nuestro sistema de registros suele procesar por lotes varios eventos de registro en un solo cuerpo de petición HTTP de nueva línea y delimitado. OpenTelemetry Collector no puede deshacer esos lotes, por lo que espera recibir un evento por cada petición.

3. OpenTelemetry admite un formato de mensajes para registros, función ideal para registrar eventos que suceden en un único momento. Ahora mismo, la función está en fase de pruebas, por lo que ninguna de las herramientas de OpenTelemetry puede vincular registros a intervalos, aunque los eventos de registro incluyan identificadores de intervalo y de seguimiento. Sin embargo, las especificaciones de seguimiento recogen el concepto de span events (eventos de intervalo), que se parece mucho a los registros y es compatible con multitud de herramientas, como Honeycomb, Jaeger y Zipkin.

Me propuse resolver todos estos problemas al mismo tiempo disponiendo un proxy delante de OpenTelemetry Collector, cuya función es deshacer los lotes de eventos multilínea, convertir registros en eventos de intervalo y responder al desafío de participación que plantea Fastly. Programé una aplicación de muestra que llevaba a cabo todas estas tareas y la publicamos en Glitch, que además es una forma cómoda de validar los datos procedentes de Fastly sin tener que utilizar OpenTelemetry Collector.

Propagación del contexto de seguimiento

Hay un truco para ver los intervalos que suceden en los sistemas backend como elementos secundarios de los intervalos de Fastly dentro de un mismo seguimiento: se llama propagación del contexto de seguimiento, y se trata en concreto de la especificación W3C Trace Context, que describe el encabezado traceparent. En el código VCL anterior ya adoptamos un identificador de seguimiento y un identificador de intervalo principal si van incluidos en la petición que recibe Fastly; Fastly, a su vez, también debe reenviar el identificador del seguimiento y del intervalo actual al realizar peticiones a backends para que estos puedan emitir un intervalo secundario que haga referencia al intervalo de Fastly como principal.  

Todo ello se puede ejecutar en VCL creando otra subrutina personalizada y haciéndole una llamada desde vcl_miss y vcl_pass:

sub telem_start_backend_fetch {
  set bereq.http.traceparent = "00-" req.http.x-trace-id + "-" + req.http.x-trace-fetch-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; 
}

La primera línea de esta subrutina añade el encabezado traceparent a las peticiones que salen de Fastly. También podemos aprovechar para suprimir los encabezados de telemetría que se usan con fines internos para guardar el estado en VCL, con lo que evitamos que se reenvíen al origen.

No obstante, gracias a OpenTelemetry descubrí una cosita más: varios proveedores de PaaS (como App Engine de Google) mutan el encabezado traceparent, probablemente cuando su propio sistema de seguimiento registra un intervalo. El problema es que, si tu recopilador no accede a los datos de ese intervalo, los intervalos del backend se desvinculan de los intervalos del edge; aunque estos, por lo menos, pertenecen al mismo seguimiento, los anidamientos se rompen. Esperemos que los proveedores de la nube solventen este problema. Hasta entonces, os sugiero que utilicéis nuestra solución alternativa: enviar un encabezado x-traceparent que en realidad es una copia del encabezado traceparent.

Si todos los componentes independientes de tu sistema son capaces de leer y respetar encabezados traceparent entrantes, y de añadir uno a todas las peticiones HTTP salientes, OpenTelemetry podrá crear un historial holístico de cada transacción que describa gráficamente su paso por todo el sistema. Como Fastly no es el único componente de tu sistema, lo que nos interesa es estar tan abiertos a las inspecciones y a las depuraciones como sea posible. Si tratas de instrumentar un servicio VCL de Fastly mediante OpenTelemetry, cuéntanos cómo te ha ido; estaremos encantados de leerte.

Ya están publicadas las cuatro partes de nuestra serie de artículos sobre OpenTelemetry:

• OpenTelemetry (I): un edge cada vez menos distante

• OpenTelemetry (II): uso de OpenTelemetry en VCL

• OpenTelemetry (III): uso de OpenTelemetry en Compute

• OpenTelemetry (IV): instrumentación de Fastly Fiddle