From aa546189be730163ee5370029e4dfdb3b454ab96 Mon Sep 17 00:00:00 2001 From: snek Date: Wed, 13 Nov 2024 11:38:46 +0100 Subject: feat: OpenTelemetry Tracing API and Exporting (#26710) Initial import of OTEL code supporting tracing. Metrics soon to come. Implements APIs for https://jsr.io/@deno/otel so that code using OpenTelemetry.js just works tm. There is still a lot of work to do with configuration and adding built-in tracing to core APIs, which will come in followup PRs. --------- Co-authored-by: Luca Casonato --- tests/specs/cli/otel_basic/__test__.jsonc | 4 ++ tests/specs/cli/otel_basic/child.ts | 20 ++++++++ tests/specs/cli/otel_basic/deno.json | 4 ++ tests/specs/cli/otel_basic/main.ts | 76 +++++++++++++++++++++++++++++++ 4 files changed, 104 insertions(+) create mode 100644 tests/specs/cli/otel_basic/__test__.jsonc create mode 100644 tests/specs/cli/otel_basic/child.ts create mode 100644 tests/specs/cli/otel_basic/deno.json create mode 100644 tests/specs/cli/otel_basic/main.ts (limited to 'tests/specs/cli') diff --git a/tests/specs/cli/otel_basic/__test__.jsonc b/tests/specs/cli/otel_basic/__test__.jsonc new file mode 100644 index 000000000..a9d4fff04 --- /dev/null +++ b/tests/specs/cli/otel_basic/__test__.jsonc @@ -0,0 +1,4 @@ +{ + "args": "run -A main.ts", + "output": "processed\n" +} diff --git a/tests/specs/cli/otel_basic/child.ts b/tests/specs/cli/otel_basic/child.ts new file mode 100644 index 000000000..72cffd9f0 --- /dev/null +++ b/tests/specs/cli/otel_basic/child.ts @@ -0,0 +1,20 @@ +// Copyright 2018-2024 the Deno authors. All rights reserved. MIT license. + +async function inner() { + using _span = new Deno.tracing.Span("inner span"); + console.log("log 1"); + await 1; + console.log("log 2"); +} + +Deno.serve({ + port: 0, + onListen({ port }) { + console.log(port.toString()); + }, + handler: async (_req) => { + using _span = new Deno.tracing.Span("outer span"); + await inner(); + return new Response(null, { status: 200 }); + }, +}); diff --git a/tests/specs/cli/otel_basic/deno.json b/tests/specs/cli/otel_basic/deno.json new file mode 100644 index 000000000..105514e13 --- /dev/null +++ b/tests/specs/cli/otel_basic/deno.json @@ -0,0 +1,4 @@ +{ + "lock": false, + "importMap": "../../../../import_map.json" +} diff --git a/tests/specs/cli/otel_basic/main.ts b/tests/specs/cli/otel_basic/main.ts new file mode 100644 index 000000000..66ef5c79c --- /dev/null +++ b/tests/specs/cli/otel_basic/main.ts @@ -0,0 +1,76 @@ +// Copyright 2018-2024 the Deno authors. All rights reserved. MIT license. + +import { assert, assertEquals } from "@std/assert"; +import { TextLineStream } from "@std/streams/text-line-stream"; + +const logs = []; +const spans = []; +let child: Deno.ChildProcess; + +Deno.serve( + { + port: 0, + async onListen({ port }) { + const command = new Deno.Command(Deno.execPath(), { + args: ["run", "-A", "--unstable-otel", "child.ts"], + env: { + OTEL_EXPORTER_OTLP_PROTOCOL: "http/json", + OTEL_EXPORTER_OTLP_ENDPOINT: `http://localhost:${port}`, + OTEL_BSP_SCHEDULE_DELAY: "10", + OTEL_BLRP_SCHEDULE_DELAY: "10", + }, + stdin: "piped", + stdout: "piped", + stderr: "inherit", + }); + child = command.spawn(); + const lines = child.stdout + .pipeThrough(new TextDecoderStream()) + .pipeThrough(new TextLineStream()) + .getReader(); + const line = await lines.read(); + await fetch(`http://localhost:${line.value}/`); + }, + async handler(req) { + try { + const body = await req.json(); + if (body.resourceLogs) { + logs.push(...body.resourceLogs[0].scopeLogs[0].logRecords); + } + if (body.resourceSpans) { + spans.push(...body.resourceSpans[0].scopeSpans[0].spans); + } + + if (logs.length > 2 && spans.length > 1) { + child.kill(); + + const inner = spans.find((s) => s.name === "inner span"); + const outer = spans.find((s) => s.name === "outer span"); + + assertEquals(inner.traceId, outer.traceId); + assertEquals(inner.parentSpanId, outer.spanId); + + assertEquals(logs[1].body.stringValue, "log 1\n"); + assertEquals(logs[1].traceId, inner.traceId); + assertEquals(logs[1].spanId, inner.spanId); + + assertEquals(logs[2].body.stringValue, "log 2\n"); + assertEquals(logs[2].traceId, inner.traceId); + assertEquals(logs[2].spanId, inner.spanId); + + console.log("processed"); + Deno.exit(0); + } + + return Response.json({ partialSuccess: {} }, { status: 200 }); + } catch (e) { + console.error(e); + Deno.exit(1); + } + }, + }, +); + +setTimeout(() => { + assert(false, "test did not finish in time"); +}, 10e3); -- cgit v1.2.3 From 4e899d48cffa95617266dd8f9aef54603a87ad82 Mon Sep 17 00:00:00 2001 From: snek Date: Thu, 14 Nov 2024 13:16:28 +0100 Subject: fix: otel resiliency (#26857) Improving the breadth of collected data, and ensuring that the collected data is more likely to be successfully reported. - Use `log` crate in more places - Hook up `log` crate to otel - Switch to process-wide otel processors - Handle places that use `process::exit` Also adds a more robust testing framework, with a deterministic tracing setting. Refs: https://github.com/denoland/deno/issues/26852 --- tests/specs/cli/otel_basic/__test__.jsonc | 32 ++++++++++- tests/specs/cli/otel_basic/basic.out | 76 ++++++++++++++++++++++++++ tests/specs/cli/otel_basic/basic.ts | 24 +++++++++ tests/specs/cli/otel_basic/child.ts | 20 ------- tests/specs/cli/otel_basic/deno_dot_exit.out | 19 +++++++ tests/specs/cli/otel_basic/deno_dot_exit.ts | 2 + tests/specs/cli/otel_basic/main.ts | 80 ++++++++-------------------- tests/specs/cli/otel_basic/natural_exit.out | 19 +++++++ tests/specs/cli/otel_basic/natural_exit.ts | 1 + tests/specs/cli/otel_basic/uncaught.out | 37 +++++++++++++ tests/specs/cli/otel_basic/uncaught.ts | 2 + 11 files changed, 231 insertions(+), 81 deletions(-) create mode 100644 tests/specs/cli/otel_basic/basic.out create mode 100644 tests/specs/cli/otel_basic/basic.ts delete mode 100644 tests/specs/cli/otel_basic/child.ts create mode 100644 tests/specs/cli/otel_basic/deno_dot_exit.out create mode 100644 tests/specs/cli/otel_basic/deno_dot_exit.ts create mode 100644 tests/specs/cli/otel_basic/natural_exit.out create mode 100644 tests/specs/cli/otel_basic/natural_exit.ts create mode 100644 tests/specs/cli/otel_basic/uncaught.out create mode 100644 tests/specs/cli/otel_basic/uncaught.ts (limited to 'tests/specs/cli') diff --git a/tests/specs/cli/otel_basic/__test__.jsonc b/tests/specs/cli/otel_basic/__test__.jsonc index a9d4fff04..5a27e9262 100644 --- a/tests/specs/cli/otel_basic/__test__.jsonc +++ b/tests/specs/cli/otel_basic/__test__.jsonc @@ -1,4 +1,32 @@ { - "args": "run -A main.ts", - "output": "processed\n" + "steps": [ + { + "args": "run -A main.ts basic.ts", + "envs": { + "DENO_UNSTABLE_OTEL_DETERMINISTIC": "1" + }, + "output": "basic.out" + }, + { + "args": "run -A main.ts natural_exit.ts", + "envs": { + "DENO_UNSTABLE_OTEL_DETERMINISTIC": "1" + }, + "output": "natural_exit.out" + }, + { + "args": "run -A main.ts deno_dot_exit.ts", + "envs": { + "DENO_UNSTABLE_OTEL_DETERMINISTIC": "1" + }, + "output": "deno_dot_exit.out" + }, + { + "args": "run -A main.ts uncaught.ts", + "envs": { + "DENO_UNSTABLE_OTEL_DETERMINISTIC": "1" + }, + "output": "uncaught.out" + } + ] } diff --git a/tests/specs/cli/otel_basic/basic.out b/tests/specs/cli/otel_basic/basic.out new file mode 100644 index 000000000..3f0554f96 --- /dev/null +++ b/tests/specs/cli/otel_basic/basic.out @@ -0,0 +1,76 @@ +{ + "spans": [ + { + "traceId": "00000000000000000000000000000002", + "spanId": "0000000000000003", + "traceState": "", + "parentSpanId": "0000000000000001", + "flags": 1, + "name": "inner span", + "kind": 1, + "startTimeUnixNano": "[WILDCARD]", + "endTimeUnixNano": "[WILDCARD]", + "attributes": [], + "droppedAttributesCount": 0, + "events": [], + "droppedEventsCount": 0, + "links": [], + "droppedLinksCount": 0, + "status": { + "message": "", + "code": 0 + } + }, + { + "traceId": "00000000000000000000000000000002", + "spanId": "0000000000000001", + "traceState": "", + "parentSpanId": "", + "flags": 1, + "name": "outer span", + "kind": 1, + "startTimeUnixNano": "[WILDCARD]", + "endTimeUnixNano": "[WILDCARD]", + "attributes": [], + "droppedAttributesCount": 0, + "events": [], + "droppedEventsCount": 0, + "links": [], + "droppedLinksCount": 0, + "status": { + "message": "", + "code": 0 + } + } + ], + "logs": [ + { + "timeUnixNano": "0", + "observedTimeUnixNano": "[WILDCARD]", + "severityNumber": 9, + "severityText": "INFO", + "body": { + "stringValue": "log 1\n" + }, + "attributes": [], + "droppedAttributesCount": 0, + "flags": 1, + "traceId": "00000000000000000000000000000002", + "spanId": "0000000000000003" + }, + { + "timeUnixNano": "0", + "observedTimeUnixNano": "[WILDCARD]", + "severityNumber": 9, + "severityText": "INFO", + "body": { + "stringValue": "log 2\n" + }, + "attributes": [], + "droppedAttributesCount": 0, + "flags": 1, + "traceId": "00000000000000000000000000000002", + "spanId": "0000000000000003" + } + ] +} diff --git a/tests/specs/cli/otel_basic/basic.ts b/tests/specs/cli/otel_basic/basic.ts new file mode 100644 index 000000000..5a178794a --- /dev/null +++ b/tests/specs/cli/otel_basic/basic.ts @@ -0,0 +1,24 @@ +// Copyright 2018-2024 the Deno authors. All rights reserved. MIT license. + +async function inner() { + using _span = new Deno.tracing.Span("inner span"); + console.log("log 1"); + await 1; + console.log("log 2"); +} + +const server = Deno.serve({ + port: 0, + async onListen({ port }) { + try { + await fetch(`http://localhost:${port}`); + } finally { + server.shutdown(); + } + }, + handler: async (_req) => { + using _span = new Deno.tracing.Span("outer span"); + await inner(); + return new Response(null, { status: 200 }); + }, +}); diff --git a/tests/specs/cli/otel_basic/child.ts b/tests/specs/cli/otel_basic/child.ts deleted file mode 100644 index 72cffd9f0..000000000 --- a/tests/specs/cli/otel_basic/child.ts +++ /dev/null @@ -1,20 +0,0 @@ -// Copyright 2018-2024 the Deno authors. All rights reserved. MIT license. - -async function inner() { - using _span = new Deno.tracing.Span("inner span"); - console.log("log 1"); - await 1; - console.log("log 2"); -} - -Deno.serve({ - port: 0, - onListen({ port }) { - console.log(port.toString()); - }, - handler: async (_req) => { - using _span = new Deno.tracing.Span("outer span"); - await inner(); - return new Response(null, { status: 200 }); - }, -}); diff --git a/tests/specs/cli/otel_basic/deno_dot_exit.out b/tests/specs/cli/otel_basic/deno_dot_exit.out new file mode 100644 index 000000000..98a41cf60 --- /dev/null +++ b/tests/specs/cli/otel_basic/deno_dot_exit.out @@ -0,0 +1,19 @@ +{ + "spans": [], + "logs": [ + { + "timeUnixNano": "0", + "observedTimeUnixNano": "[WILDCARD]", + "severityNumber": 9, + "severityText": "INFO", + "body": { + "stringValue": "log 1\n" + }, + "attributes": [], + "droppedAttributesCount": 0, + "flags": 0, + "traceId": "", + "spanId": "" + } + ] +} diff --git a/tests/specs/cli/otel_basic/deno_dot_exit.ts b/tests/specs/cli/otel_basic/deno_dot_exit.ts new file mode 100644 index 000000000..73540fd9e --- /dev/null +++ b/tests/specs/cli/otel_basic/deno_dot_exit.ts @@ -0,0 +1,2 @@ +console.log("log 1"); +Deno.exit(0); diff --git a/tests/specs/cli/otel_basic/main.ts b/tests/specs/cli/otel_basic/main.ts index 66ef5c79c..6c49462a0 100644 --- a/tests/specs/cli/otel_basic/main.ts +++ b/tests/specs/cli/otel_basic/main.ts @@ -1,76 +1,38 @@ // Copyright 2018-2024 the Deno authors. All rights reserved. MIT license. -import { assert, assertEquals } from "@std/assert"; -import { TextLineStream } from "@std/streams/text-line-stream"; +const data = { + spans: [], + logs: [], +}; -const logs = []; -const spans = []; -let child: Deno.ChildProcess; - -Deno.serve( +const server = Deno.serve( { port: 0, - async onListen({ port }) { + onListen({ port }) { const command = new Deno.Command(Deno.execPath(), { - args: ["run", "-A", "--unstable-otel", "child.ts"], + args: ["run", "-A", "--unstable-otel", Deno.args[0]], env: { OTEL_EXPORTER_OTLP_PROTOCOL: "http/json", OTEL_EXPORTER_OTLP_ENDPOINT: `http://localhost:${port}`, - OTEL_BSP_SCHEDULE_DELAY: "10", - OTEL_BLRP_SCHEDULE_DELAY: "10", }, - stdin: "piped", - stdout: "piped", - stderr: "inherit", + stdout: "null", + }); + const child = command.spawn(); + child.output().then(() => { + server.shutdown(); + + console.log(JSON.stringify(data, null, 2)); }); - child = command.spawn(); - const lines = child.stdout - .pipeThrough(new TextDecoderStream()) - .pipeThrough(new TextLineStream()) - .getReader(); - const line = await lines.read(); - await fetch(`http://localhost:${line.value}/`); }, async handler(req) { - try { - const body = await req.json(); - if (body.resourceLogs) { - logs.push(...body.resourceLogs[0].scopeLogs[0].logRecords); - } - if (body.resourceSpans) { - spans.push(...body.resourceSpans[0].scopeSpans[0].spans); - } - - if (logs.length > 2 && spans.length > 1) { - child.kill(); - - const inner = spans.find((s) => s.name === "inner span"); - const outer = spans.find((s) => s.name === "outer span"); - - assertEquals(inner.traceId, outer.traceId); - assertEquals(inner.parentSpanId, outer.spanId); - - assertEquals(logs[1].body.stringValue, "log 1\n"); - assertEquals(logs[1].traceId, inner.traceId); - assertEquals(logs[1].spanId, inner.spanId); - - assertEquals(logs[2].body.stringValue, "log 2\n"); - assertEquals(logs[2].traceId, inner.traceId); - assertEquals(logs[2].spanId, inner.spanId); - - console.log("processed"); - Deno.exit(0); - } - - return Response.json({ partialSuccess: {} }, { status: 200 }); - } catch (e) { - console.error(e); - Deno.exit(1); + const body = await req.json(); + if (body.resourceLogs) { + data.logs.push(...body.resourceLogs[0].scopeLogs[0].logRecords); + } + if (body.resourceSpans) { + data.spans.push(...body.resourceSpans[0].scopeSpans[0].spans); } + return Response.json({ partialSuccess: {} }, { status: 200 }); }, }, ); - -setTimeout(() => { - assert(false, "test did not finish in time"); -}, 10e3); diff --git a/tests/specs/cli/otel_basic/natural_exit.out b/tests/specs/cli/otel_basic/natural_exit.out new file mode 100644 index 000000000..98a41cf60 --- /dev/null +++ b/tests/specs/cli/otel_basic/natural_exit.out @@ -0,0 +1,19 @@ +{ + "spans": [], + "logs": [ + { + "timeUnixNano": "0", + "observedTimeUnixNano": "[WILDCARD]", + "severityNumber": 9, + "severityText": "INFO", + "body": { + "stringValue": "log 1\n" + }, + "attributes": [], + "droppedAttributesCount": 0, + "flags": 0, + "traceId": "", + "spanId": "" + } + ] +} diff --git a/tests/specs/cli/otel_basic/natural_exit.ts b/tests/specs/cli/otel_basic/natural_exit.ts new file mode 100644 index 000000000..d40478252 --- /dev/null +++ b/tests/specs/cli/otel_basic/natural_exit.ts @@ -0,0 +1 @@ +console.log("log 1"); diff --git a/tests/specs/cli/otel_basic/uncaught.out b/tests/specs/cli/otel_basic/uncaught.out new file mode 100644 index 000000000..a5a886bfe --- /dev/null +++ b/tests/specs/cli/otel_basic/uncaught.out @@ -0,0 +1,37 @@ +error: Uncaught (in promise) Error: uncaught +throw new Error("uncaught"); + ^ + at file:///[WILDCARD]/tests/specs/cli/otel_basic/uncaught.ts:2:7 +{ + "spans": [], + "logs": [ + { + "timeUnixNano": "0", + "observedTimeUnixNano": "[WILDCARD]", + "severityNumber": 9, + "severityText": "INFO", + "body": { + "stringValue": "log 1\n" + }, + "attributes": [], + "droppedAttributesCount": 0, + "flags": 0, + "traceId": "", + "spanId": "" + }, + { + "timeUnixNano": "0", + "observedTimeUnixNano": "[WILDCARD]", + "severityNumber": 17, + "severityText": "ERROR", + "body": { + "stringValue": "error: Uncaught (in promise) Error: uncaught\nthrow new Error(\"uncaught\");\n ^\n at file:///[WILDCARD]/tests/specs/cli/otel_basic/uncaught.ts:2:7" + }, + "attributes": [], + "droppedAttributesCount": 0, + "flags": 0, + "traceId": "", + "spanId": "" + } + ] +} diff --git a/tests/specs/cli/otel_basic/uncaught.ts b/tests/specs/cli/otel_basic/uncaught.ts new file mode 100644 index 000000000..eca7c05cb --- /dev/null +++ b/tests/specs/cli/otel_basic/uncaught.ts @@ -0,0 +1,2 @@ +console.log("log 1"); +throw new Error("uncaught"); -- cgit v1.2.3 From 594a99817cbe44553b2c288578fbba8e1e9c1907 Mon Sep 17 00:00:00 2001 From: Luca Casonato Date: Tue, 19 Nov 2024 00:55:22 +0100 Subject: feat(runtime): remove public OTEL trace API (#26854) This PR removes the public Deno.tracing.Span API. We are not confident we can ship an API that is better than the `@opentelemetry/api` API, because V8 CPED does not support us using `using` to manage span context. If this changes, we can revisit this decision. For now, users wanting custom spans can instrument their code using the `@opentelemetry/api` API and `@deno/otel`. This PR also speeds up the OTEL trace generation by a 30% by using Uint8Array instead of strings for the trace ID and span ID. --- tests/specs/cli/otel_basic/basic.out | 18 +++++++++--------- tests/specs/cli/otel_basic/basic.ts | 24 +++++++++++++++++------- tests/specs/cli/otel_basic/main.ts | 2 +- 3 files changed, 27 insertions(+), 17 deletions(-) (limited to 'tests/specs/cli') diff --git a/tests/specs/cli/otel_basic/basic.out b/tests/specs/cli/otel_basic/basic.out index 3f0554f96..3745cb7f3 100644 --- a/tests/specs/cli/otel_basic/basic.out +++ b/tests/specs/cli/otel_basic/basic.out @@ -1,10 +1,10 @@ { "spans": [ { - "traceId": "00000000000000000000000000000002", - "spanId": "0000000000000003", + "traceId": "10000000000000000000000000000002", + "spanId": "1000000000000003", "traceState": "", - "parentSpanId": "0000000000000001", + "parentSpanId": "1000000000000001", "flags": 1, "name": "inner span", "kind": 1, @@ -22,8 +22,8 @@ } }, { - "traceId": "00000000000000000000000000000002", - "spanId": "0000000000000001", + "traceId": "10000000000000000000000000000002", + "spanId": "1000000000000001", "traceState": "", "parentSpanId": "", "flags": 1, @@ -55,8 +55,8 @@ "attributes": [], "droppedAttributesCount": 0, "flags": 1, - "traceId": "00000000000000000000000000000002", - "spanId": "0000000000000003" + "traceId": "10000000000000000000000000000002", + "spanId": "1000000000000003" }, { "timeUnixNano": "0", @@ -69,8 +69,8 @@ "attributes": [], "droppedAttributesCount": 0, "flags": 1, - "traceId": "00000000000000000000000000000002", - "spanId": "0000000000000003" + "traceId": "10000000000000000000000000000002", + "spanId": "1000000000000003" } ] } diff --git a/tests/specs/cli/otel_basic/basic.ts b/tests/specs/cli/otel_basic/basic.ts index 5a178794a..5c4ae43cd 100644 --- a/tests/specs/cli/otel_basic/basic.ts +++ b/tests/specs/cli/otel_basic/basic.ts @@ -1,10 +1,17 @@ // Copyright 2018-2024 the Deno authors. All rights reserved. MIT license. +import { trace } from "npm:@opentelemetry/api@1.9.0"; +import "jsr:@deno/otel@0.0.2/register"; + +const tracer = trace.getTracer("example-tracer"); + async function inner() { - using _span = new Deno.tracing.Span("inner span"); - console.log("log 1"); - await 1; - console.log("log 2"); + await tracer.startActiveSpan("inner span", async (span) => { + console.log("log 1"); + await 1; + console.log("log 2"); + span.end(); + }); } const server = Deno.serve({ @@ -17,8 +24,11 @@ const server = Deno.serve({ } }, handler: async (_req) => { - using _span = new Deno.tracing.Span("outer span"); - await inner(); - return new Response(null, { status: 200 }); + return await tracer.startActiveSpan("outer span", async (span) => { + await inner(); + const resp = new Response(null, { status: 200 }); + span.end(); + return resp; + }); }, }); diff --git a/tests/specs/cli/otel_basic/main.ts b/tests/specs/cli/otel_basic/main.ts index 6c49462a0..5415a7437 100644 --- a/tests/specs/cli/otel_basic/main.ts +++ b/tests/specs/cli/otel_basic/main.ts @@ -10,7 +10,7 @@ const server = Deno.serve( port: 0, onListen({ port }) { const command = new Deno.Command(Deno.execPath(), { - args: ["run", "-A", "--unstable-otel", Deno.args[0]], + args: ["run", "-A", "-q", "--unstable-otel", Deno.args[0]], env: { OTEL_EXPORTER_OTLP_PROTOCOL: "http/json", OTEL_EXPORTER_OTLP_ENDPOINT: `http://localhost:${port}`, -- cgit v1.2.3