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 + tests/util/server/src/macros.rs | 1 + 12 files changed, 232 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') 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"); diff --git a/tests/util/server/src/macros.rs b/tests/util/server/src/macros.rs index fdbb977e9..e076583f1 100644 --- a/tests/util/server/src/macros.rs +++ b/tests/util/server/src/macros.rs @@ -33,6 +33,7 @@ macro_rules! timeout { use std::io::Write; eprintln!("Test {function} timed out after {timeout} seconds, aborting"); _ = std::io::stderr().flush(); + #[allow(clippy::disallowed_methods)] ::std::process::exit(1); } }); -- cgit v1.2.3