| 1 | import { assert, describe, expect, it } from "@effect/vitest"; |
| 2 | import * as NodeServices from "@effect/platform-node/NodeServices"; |
| 3 | import * as Arr from "effect/Array"; |
| 4 | import * as Cause from "effect/Cause"; |
| 5 | import * as Effect from "effect/Effect"; |
| 6 | import * as Deferred from "effect/Deferred"; |
| 7 | import * as Fiber from "effect/Fiber"; |
| 8 | import * as Exit from "effect/Exit"; |
| 9 | import * as FileSystem from "effect/FileSystem"; |
| 10 | import * as Layer from "effect/Layer"; |
| 11 | import * as Logger from "effect/Logger"; |
| 12 | import * as Order from "effect/Order"; |
| 13 | import * as Path from "effect/Path"; |
| 14 | import * as Ref from "effect/Ref"; |
| 15 | import * as References from "effect/References"; |
| 16 | import * as Schema from "effect/Schema"; |
| 17 | import * as Tracer from "effect/Tracer"; |
| 18 | import * as TestClock from "effect/testing/TestClock"; |
| 19 | import { vi } from "vite-plus/test"; |
| 20 | |
| 21 | import { |
| 22 | causeErrorTag, |
| 23 | compactTraceAttributes, |
| 24 | decodeOtlpTraceRecords, |
| 25 | errorTag, |
| 26 | makeLocalFileTracer, |
| 27 | makeTraceSink, |
| 28 | type EffectTraceRecord, |
| 29 | type TraceRecord, |
| 30 | type TraceSinkFlushStats, |
| 31 | OtlpHeadersFromString, |
| 32 | truncateTraceAttributes, |
| 33 | } from "./observability.ts"; |
| 34 | |
| 35 | describe("errorTag", () => { |
| 36 | it("reports structural tags without retaining arbitrary values", () => { |
| 37 | assert.equal(errorTag({ _tag: "AcpRequestError" }), "AcpRequestError"); |
| 38 | assert.equal(errorTag(new TypeError("secret-token-value")), "TypeError"); |
| 39 | assert.equal(errorTag({ _tag: "secret token value" }), "TaggedError"); |
| 40 | }); |
| 41 | }); |
| 42 | |
| 43 | describe("causeErrorTag", () => { |
| 44 | it("reports the tagged failure value instead of the Cause reason wrapper", () => { |
| 45 | assert.equal( |
| 46 | causeErrorTag(Cause.fail({ _tag: "ServerAuthInvalidCredentialError" })), |
| 47 | "ServerAuthInvalidCredentialError", |
| 48 | ); |
| 49 | }); |
| 50 | |
| 51 | it("reports structural cause kinds when no typed failure exists", () => { |
| 52 | assert.equal(causeErrorTag(Cause.die(new Error("unexpected"))), "Die"); |
| 53 | assert.equal(causeErrorTag(Cause.interrupt()), "Interrupt"); |
| 54 | }); |
| 55 | }); |
| 56 | |
| 57 | const TraceRecordLine = Schema.Struct({ |
| 58 | name: Schema.String, |
| 59 | spanId: Schema.String, |
| 60 | parentSpanId: Schema.optional(Schema.String), |
| 61 | attributes: Schema.Record(Schema.String, Schema.Unknown), |
| 62 | events: Schema.Array( |
| 63 | Schema.Struct({ |
| 64 | name: Schema.String, |
| 65 | attributes: Schema.Record(Schema.String, Schema.Unknown), |
| 66 | }), |
| 67 | ), |
| 68 | exit: Schema.optional( |
| 69 | Schema.Struct({ |
| 70 | _tag: Schema.String, |
| 71 | }), |
| 72 | ), |
| 73 | }); |
| 74 | |
| 75 | const decodeTraceRecordLine = Schema.decodeUnknownSync(Schema.fromJsonString(TraceRecordLine)); |
| 76 | |
| 77 | const makeRecord = (name: string, suffix = ""): TraceRecord => ({ |
| 78 | type: "effect-span", |
| 79 | name, |
| 80 | traceId: `trace-${name}-${suffix}`, |
| 81 | spanId: `span-${name}-${suffix}`, |
| 82 | sampled: true, |
| 83 | kind: "internal", |
| 84 | startTimeUnixNano: "1", |
| 85 | endTimeUnixNano: "2", |
| 86 | durationMs: 1, |
| 87 | attributes: { |
| 88 | payload: suffix, |
| 89 | }, |
| 90 | events: [], |
| 91 | links: [], |
| 92 | exit: { |
| 93 | _tag: "Success", |
| 94 | }, |
| 95 | }); |
| 96 | |
| 97 | const readTraceRecords = Effect.fn("readTraceRecords")(function* (tracePath: string) { |
| 98 | const fileSystem = yield* FileSystem.FileSystem; |
| 99 | return (yield* fileSystem.readFileString(tracePath)) |
| 100 | .trim() |
| 101 | .split("\n") |
| 102 | .filter((line) => line.length > 0) |
| 103 | .map((line) => decodeTraceRecordLine(line)); |
| 104 | }); |
| 105 | |
| 106 | const layerTest = (tracePath: string) => |
| 107 | Layer.mergeAll( |
| 108 | Layer.effect( |
| 109 | Tracer.Tracer, |
| 110 | makeLocalFileTracer({ |
| 111 | filePath: tracePath, |
| 112 | maxBytes: 1024 * 1024, |
| 113 | maxFiles: 2, |
| 114 | batchWindowMs: 10_000, |
| 115 | }), |
| 116 | ), |
| 117 | Logger.layer([Logger.tracerLogger], { mergeWithExisting: false }), |
| 118 | Layer.succeed(References.MinimumLogLevel, "Info"), |
| 119 | ); |
| 120 | |
| 121 | const nodeServicesIt = it.layer(NodeServices.layer); |
| 122 | |
| 123 | describe("truncateTraceAttributes", () => { |
| 124 | it("clamps oversized strings at any depth without mutating the input", () => { |
| 125 | const stack = "s".repeat(2_000); |
| 126 | const attributes = { |
| 127 | "db.query.text": "q".repeat(2_000), |
| 128 | short: "ok", |
| 129 | error: { name: "Error", stack, nested: ["a".repeat(2_000)] }, |
| 130 | }; |
| 131 | const truncated = truncateTraceAttributes(attributes); |
| 132 | |
| 133 | assert.equal((truncated["db.query.text"] as string).length, 200 + "…[truncated]".length); |
| 134 | assert.equal(truncated["short"], "ok"); |
| 135 | const error = truncated["error"] as { stack: string; nested: Array<string> }; |
| 136 | assert.equal(error.stack.length, 500 + "…[truncated]".length); |
| 137 | assert.equal(error.nested[0]?.length, 500 + "…[truncated]".length); |
| 138 | // Input is untouched: the live span's attributes are shared. |
| 139 | assert.equal(attributes.error.stack, stack); |
| 140 | }); |
| 141 | |
| 142 | it("returns the same reference when nothing exceeds the limits", () => { |
| 143 | const attributes = { short: "ok", nested: { fine: "also ok" } }; |
| 144 | assert.equal(truncateTraceAttributes(attributes), attributes); |
| 145 | }); |
| 146 | }); |
| 147 | |
| 148 | describe("decodeOtlpTraceRecords", () => { |
| 149 | it("clamps oversized renderer span and event attributes", () => { |
| 150 | const long = "x".repeat(2_000); |
| 151 | const clamped = `${"x".repeat(500)}…[truncated]`; |
| 152 | const [record] = decodeOtlpTraceRecords({ |
| 153 | resourceSpans: [ |
| 154 | { |
| 155 | resource: { attributes: [], droppedAttributesCount: 0 }, |
| 156 | scopeSpans: [ |
| 157 | { |
| 158 | scope: { name: "effect" }, |
| 159 | spans: [ |
| 160 | { |
| 161 | traceId: "11111111111111111111111111111111", |
| 162 | spanId: "2222222222222222", |
| 163 | parentSpanId: undefined, |
| 164 | name: "client.span", |
| 165 | kind: 1, |
| 166 | startTimeUnixNano: "1000000", |
| 167 | endTimeUnixNano: "2000000", |
| 168 | attributes: [{ key: "payload", value: { stringValue: long } }], |
| 169 | droppedAttributesCount: 0, |
| 170 | events: [ |
| 171 | { |
| 172 | name: "log", |
| 173 | timeUnixNano: "1500000", |
| 174 | attributes: [{ key: "effect.cause", value: { stringValue: long } }], |
| 175 | droppedAttributesCount: 0, |
| 176 | }, |
| 177 | ], |
| 178 | droppedEventsCount: 0, |
| 179 | status: { code: 1 }, |
| 180 | links: [], |
| 181 | droppedLinksCount: 0, |
| 182 | }, |
| 183 | ], |
| 184 | }, |
| 185 | ], |
| 186 | }, |
| 187 | ], |
| 188 | }); |
| 189 | |
| 190 | assert.equal(record?.attributes["payload"], clamped); |
| 191 | assert.equal(record?.events[0]?.attributes["effect.cause"], clamped); |
| 192 | }); |
| 193 | }); |
| 194 | |
| 195 | describe("observability", () => { |
| 196 | it.effect( |
| 197 | "preserves successful results without retaining them in sampled or unsampled spans", |
| 198 | () => |
| 199 | Effect.gen(function* () { |
| 200 | for (const sampled of [true, false]) { |
| 201 | const delegates: Array<Tracer.Span> = []; |
| 202 | const records: Array<EffectTraceRecord> = []; |
| 203 | const tracer = yield* makeLocalFileTracer({ |
| 204 | filePath: "unused", |
| 205 | maxBytes: 1024, |
| 206 | maxFiles: 1, |
| 207 | batchWindowMs: 10_000, |
| 208 | sink: { |
| 209 | filePath: "unused", |
| 210 | push: (record) => { |
| 211 | if (record.type === "effect-span") records.push(record); |
| 212 | }, |
| 213 | flush: Effect.void, |
| 214 | close: () => Effect.void, |
| 215 | }, |
| 216 | delegate: Tracer.make({ |
| 217 | span: (options) => { |
| 218 | const span = new Tracer.NativeSpan({ ...options, sampled }); |
| 219 | delegates.push(span); |
| 220 | return span; |
| 221 | }, |
| 222 | }), |
| 223 | }); |
| 224 | const payload = { turnItems: [{ output: [{ text: "synthetic-result" }] }] }; |
| 225 | let span: Tracer.Span | undefined; |
| 226 | const result = yield* Effect.gen(function* () { |
| 227 | span = yield* Effect.currentSpan; |
| 228 | return payload; |
| 229 | }).pipe( |
| 230 | Effect.withSpan("read-thread-projection"), |
| 231 | Effect.provideService(Tracer.Tracer, tracer), |
| 232 | ); |
| 233 | assert.strictEqual(result, payload); |
| 234 | assert.isDefined(span); |
| 235 | for (const completed of [span!, ...delegates]) { |
| 236 | assert.equal(completed.status._tag, "Ended"); |
| 237 | if (completed.status._tag === "Ended") { |
| 238 | assert.deepStrictEqual(completed.status.exit, Exit.void); |
| 239 | } |
| 240 | } |
| 241 | assert.deepStrictEqual( |
| 242 | records.map((record) => record.exit), |
| 243 | sampled ? [{ _tag: "Success" }] : [], |
| 244 | ); |
| 245 | } |
| 246 | }).pipe(Effect.provide(NodeServices.layer)), |
| 247 | ); |
| 248 | |
| 249 | it.effect("preserves failure and interruption causes in spans and exported traces", () => |
| 250 | Effect.gen(function* () { |
| 251 | for (const cause of [Cause.fail({ _tag: "SyntheticFailure" }), Cause.interrupt()]) { |
| 252 | const delegates: Array<Tracer.Span> = []; |
| 253 | const records: Array<EffectTraceRecord> = []; |
| 254 | const tracer = yield* makeLocalFileTracer({ |
| 255 | filePath: "unused", |
| 256 | maxBytes: 1024, |
| 257 | maxFiles: 1, |
| 258 | batchWindowMs: 10_000, |
| 259 | sink: { |
| 260 | filePath: "unused", |
| 261 | push: (record) => { |
| 262 | if (record.type === "effect-span") records.push(record); |
| 263 | }, |
| 264 | flush: Effect.void, |
| 265 | close: () => Effect.void, |
| 266 | }, |
| 267 | delegate: Tracer.make({ |
| 268 | span: (options) => { |
| 269 | const span = new Tracer.NativeSpan(options); |
| 270 | delegates.push(span); |
| 271 | return span; |
| 272 | }, |
| 273 | }), |
| 274 | }); |
| 275 | let span: Tracer.Span | undefined; |
| 276 | const result = yield* Effect.gen(function* () { |
| 277 | span = yield* Effect.currentSpan; |
| 278 | return yield* Effect.failCause(cause); |
| 279 | }).pipe( |
| 280 | Effect.withSpan("failed-operation"), |
| 281 | Effect.provideService(Tracer.Tracer, tracer), |
| 282 | Effect.exit, |
| 283 | ); |
| 284 | assert.isTrue(Exit.isFailure(result)); |
| 285 | assert.isDefined(span); |
| 286 | for (const completed of [span!, ...delegates]) { |
| 287 | assert.equal(completed.status._tag, "Ended"); |
| 288 | if (completed.status._tag === "Ended") { |
| 289 | assert.strictEqual(completed.status.exit, result); |
| 290 | } |
| 291 | } |
| 292 | assert.equal(records[0]?.exit._tag, Cause.hasInterrupts(cause) ? "Interrupted" : "Failure"); |
| 293 | } |
| 294 | }).pipe(Effect.provide(NodeServices.layer)), |
| 295 | ); |
| 296 | |
| 297 | it("normalizes circular arrays, maps, and sets without recursing forever", () => { |
| 298 | const array: Array<unknown> = ["alpha"]; |
| 299 | array.push(array); |
| 300 | |
| 301 | const map = new Map<string, unknown>(); |
| 302 | map.set("self", map); |
| 303 | |
| 304 | const set = new Set<unknown>(); |
| 305 | set.add(set); |
| 306 | |
| 307 | assert.deepStrictEqual( |
| 308 | compactTraceAttributes({ |
| 309 | array, |
| 310 | map, |
| 311 | set, |
| 312 | }), |
| 313 | { |
| 314 | array: ["alpha", "[Circular]"], |
| 315 | map: { self: "[Circular]" }, |
| 316 | set: ["[Circular]"], |
| 317 | }, |
| 318 | ); |
| 319 | }); |
| 320 | |
| 321 | it("normalizes invalid dates without throwing", () => { |
| 322 | // @effect-diagnostics-next-line globalDate:off |
| 323 | const invalidDate = new Date("not-a-real-date"); |
| 324 | assert.deepStrictEqual( |
| 325 | compactTraceAttributes({ |
| 326 | invalidDate, |
| 327 | }), |
| 328 | { |
| 329 | invalidDate: "Invalid Date", |
| 330 | }, |
| 331 | ); |
| 332 | }); |
| 333 | |
| 334 | nodeServicesIt("node services", (it) => { |
| 335 | it.effect( |
| 336 | "keeps trace producers responsive during a slow write, bounds the backlog, and drains on close", |
| 337 | () => |
| 338 | Effect.scoped( |
| 339 | Effect.gen(function* () { |
| 340 | const fs = yield* FileSystem.FileSystem; |
| 341 | const path = yield* Path.Path; |
| 342 | const directory = yield* fs.makeTempDirectoryScoped({ |
| 343 | prefix: "t3-trace-backpressure-", |
| 344 | }); |
| 345 | const tracePath = path.join(directory, "trace.ndjson"); |
| 346 | const started = yield* Deferred.make<void>(); |
| 347 | const release = yield* Deferred.make<void>(); |
| 348 | const closed = yield* Ref.make(false); |
| 349 | const sink = yield* makeTraceSink({ |
| 350 | filePath: tracePath, |
| 351 | maxBytes: 5_000_000, |
| 352 | maxFiles: 2, |
| 353 | batchWindowMs: 10_000, |
| 354 | }).pipe( |
| 355 | Effect.provideService(FileSystem.FileSystem, { |
| 356 | ...fs, |
| 357 | writeFile: (file, data, options) => |
| 358 | Effect.gen(function* () { |
| 359 | yield* Deferred.succeed(started, undefined); |
| 360 | yield* Deferred.await(release); |
| 361 | yield* fs.writeFile(file, data, options); |
| 362 | }), |
| 363 | }), |
| 364 | ); |
| 365 | sink.push(makeRecord("first")); |
| 366 | const flushing = yield* Effect.forkChild(sink.flush); |
| 367 | yield* Deferred.await(started); |
| 368 | // These pushes return while the write is held. The backlog keeps one |
| 369 | // trace file of records: every small one, then large ones until the |
| 370 | // next would not fit. |
| 371 | for (let index = 0; index < 2_000; index++) |
| 372 | sink.push(makeRecord("small", String(index))); |
| 373 | for (let index = 0; index < 3; index++) |
| 374 | sink.push({ ...makeRecord("large"), attributes: { payload: "x".repeat(2_000_000) } }); |
| 375 | const closing = yield* Effect.forkChild( |
| 376 | sink.close().pipe(Effect.tap(() => Ref.set(closed, true))), |
| 377 | ); |
| 378 | yield* Effect.yieldNow; |
| 379 | assert.isFalse(yield* Ref.get(closed)); |
| 380 | yield* Deferred.succeed(release, undefined); |
| 381 | yield* Fiber.join(flushing); |
| 382 | yield* Fiber.join(closing); |
| 383 | const records = yield* readTraceRecords(tracePath); |
| 384 | assert.deepStrictEqual( |
| 385 | records.map((record) => record.name), |
| 386 | ["first", ...Array.from({ length: 2_000 }, () => "small"), "large", "large"], |
| 387 | ); |
| 388 | assert.isTrue(yield* Ref.get(closed)); |
| 389 | }), |
| 390 | ), |
| 391 | ); |
| 392 | |
| 393 | it.effect("flushes buffered trace records on close", () => |
| 394 | Effect.scoped( |
| 395 | Effect.gen(function* () { |
| 396 | const fileSystem = yield* FileSystem.FileSystem; |
| 397 | const path = yield* Path.Path; |
| 398 | const tempDir = yield* fileSystem.makeTempDirectoryScoped({ prefix: "t3-trace-sink-" }); |
| 399 | const tracePath = path.join(tempDir, "shared.trace.ndjson"); |
| 400 | |
| 401 | const sink = yield* makeTraceSink({ |
| 402 | filePath: tracePath, |
| 403 | maxBytes: 1024, |
| 404 | maxFiles: 2, |
| 405 | batchWindowMs: 10_000, |
| 406 | }); |
| 407 | |
| 408 | sink.push(makeRecord("alpha")); |
| 409 | sink.push(makeRecord("beta")); |
| 410 | yield* sink.close(); |
| 411 | |
| 412 | const lines = yield* readTraceRecords(tracePath); |
| 413 | |
| 414 | assert.equal(lines.length, 2); |
| 415 | assert.equal(lines[0]?.name, "alpha"); |
| 416 | assert.equal(lines[1]?.name, "beta"); |
| 417 | }), |
| 418 | ), |
| 419 | ); |
| 420 | |
| 421 | it.effect("reports successful logical trace writes", () => |
| 422 | Effect.scoped( |
| 423 | Effect.gen(function* () { |
| 424 | const fileSystem = yield* FileSystem.FileSystem; |
| 425 | const path = yield* Path.Path; |
| 426 | const tempDir = yield* fileSystem.makeTempDirectoryScoped({ prefix: "t3-trace-sink-" }); |
| 427 | const tracePath = path.join(tempDir, "shared.trace.ndjson"); |
| 428 | const reported = yield* Ref.make<ReadonlyArray<TraceSinkFlushStats>>([]); |
| 429 | |
| 430 | const sink = yield* makeTraceSink({ |
| 431 | filePath: tracePath, |
| 432 | maxBytes: 1024, |
| 433 | maxFiles: 2, |
| 434 | batchWindowMs: 10_000, |
| 435 | onFlush: (stats) => Ref.update(reported, (current) => [...current, stats]), |
| 436 | }); |
| 437 | |
| 438 | sink.push(makeRecord("attributed")); |
| 439 | yield* sink.flush; |
| 440 | |
| 441 | const stats = yield* Ref.get(reported); |
| 442 | assert.equal(stats.length, 1); |
| 443 | assert.equal(stats[0]?.count, 1); |
| 444 | assert.isAbove(stats[0]?.logicalWriteBytes ?? 0, 0); |
| 445 | }), |
| 446 | ), |
| 447 | ); |
| 448 | |
| 449 | it.effect("rotates the trace file when the configured max size is exceeded", () => |
| 450 | Effect.scoped( |
| 451 | Effect.gen(function* () { |
| 452 | const fileSystem = yield* FileSystem.FileSystem; |
| 453 | const path = yield* Path.Path; |
| 454 | const tempDir = yield* fileSystem.makeTempDirectoryScoped({ prefix: "t3-trace-sink-" }); |
| 455 | const tracePath = path.join(tempDir, "shared.trace.ndjson"); |
| 456 | |
| 457 | const sink = yield* makeTraceSink({ |
| 458 | filePath: tracePath, |
| 459 | maxBytes: 500, |
| 460 | maxFiles: 2, |
| 461 | batchWindowMs: 10_000, |
| 462 | }); |
| 463 | |
| 464 | for (let index = 0; index < 8; index += 1) { |
| 465 | sink.push(makeRecord("rotate", `${index}-${"x".repeat(48)}`)); |
| 466 | yield* sink.flush; |
| 467 | } |
| 468 | yield* sink.close(); |
| 469 | |
| 470 | const matchingFiles = Arr.sort( |
| 471 | (yield* fileSystem.readDirectory(tempDir)).filter( |
| 472 | (entry) => |
| 473 | entry === "shared.trace.ndjson" || entry.startsWith("shared.trace.ndjson."), |
| 474 | ), |
| 475 | Order.String, |
| 476 | ); |
| 477 | |
| 478 | assert.equal( |
| 479 | matchingFiles.some((entry) => entry === "shared.trace.ndjson.1"), |
| 480 | true, |
| 481 | ); |
| 482 | assert.equal( |
| 483 | matchingFiles.some((entry) => entry === "shared.trace.ndjson.3"), |
| 484 | false, |
| 485 | ); |
| 486 | }), |
| 487 | ), |
| 488 | ); |
| 489 | |
| 490 | it.effect("keeps every trace file within the configured limit for threshold flushes", () => |
| 491 | Effect.scoped( |
| 492 | Effect.gen(function* () { |
| 493 | const fileSystem = yield* FileSystem.FileSystem; |
| 494 | const path = yield* Path.Path; |
| 495 | const tempDir = yield* fileSystem.makeTempDirectoryScoped({ prefix: "t3-trace-sink-" }); |
| 496 | const tracePath = path.join(tempDir, "shared.trace.ndjson"); |
| 497 | const maxBytes = 1_024; |
| 498 | |
| 499 | const sink = yield* makeTraceSink({ |
| 500 | filePath: tracePath, |
| 501 | maxBytes, |
| 502 | maxFiles: 2, |
| 503 | batchWindowMs: 10_000, |
| 504 | }); |
| 505 | |
| 506 | for (let index = 0; index < 256; index += 1) { |
| 507 | sink.push(makeRecord("threshold", `${index}-${"x".repeat(48)}`)); |
| 508 | } |
| 509 | yield* sink.close(); |
| 510 | |
| 511 | const matchingFiles = (yield* fileSystem.readDirectory(tempDir)).filter( |
| 512 | (entry) => entry === "shared.trace.ndjson" || entry.startsWith("shared.trace.ndjson."), |
| 513 | ); |
| 514 | assert.include(matchingFiles, "shared.trace.ndjson.1"); |
| 515 | for (const entry of matchingFiles) { |
| 516 | const stat = yield* fileSystem.stat(path.join(tempDir, entry)); |
| 517 | assert.isAtMost(Number(stat.size), maxBytes, entry); |
| 518 | } |
| 519 | }), |
| 520 | ), |
| 521 | ); |
| 522 | |
| 523 | it.effect("drops a single trace record that cannot fit within the configured limit", () => |
| 524 | Effect.scoped( |
| 525 | Effect.gen(function* () { |
| 526 | const fileSystem = yield* FileSystem.FileSystem; |
| 527 | const path = yield* Path.Path; |
| 528 | const tempDir = yield* fileSystem.makeTempDirectoryScoped({ prefix: "t3-trace-sink-" }); |
| 529 | const tracePath = path.join(tempDir, "shared.trace.ndjson"); |
| 530 | const maxBytes = 1_024; |
| 531 | |
| 532 | const sink = yield* makeTraceSink({ |
| 533 | filePath: tracePath, |
| 534 | maxBytes, |
| 535 | maxFiles: 2, |
| 536 | batchWindowMs: 10_000, |
| 537 | }); |
| 538 | |
| 539 | sink.push(makeRecord("oversized", "x".repeat(maxBytes * 2))); |
| 540 | sink.push(makeRecord("retained")); |
| 541 | yield* sink.close(); |
| 542 | |
| 543 | const records = yield* readTraceRecords(tracePath); |
| 544 | const stat = yield* fileSystem.stat(tracePath); |
| 545 | assert.deepEqual( |
| 546 | records.map((record) => record.name), |
| 547 | ["retained"], |
| 548 | ); |
| 549 | assert.isAtMost(Number(stat.size), maxBytes); |
| 550 | }), |
| 551 | ), |
| 552 | ); |
| 553 | |
| 554 | it.effect("drops only the invalid trace record when serialization fails", () => |
| 555 | Effect.scoped( |
| 556 | Effect.gen(function* () { |
| 557 | const fileSystem = yield* FileSystem.FileSystem; |
| 558 | const path = yield* Path.Path; |
| 559 | const tempDir = yield* fileSystem.makeTempDirectoryScoped({ prefix: "t3-trace-sink-" }); |
| 560 | const tracePath = path.join(tempDir, "shared.trace.ndjson"); |
| 561 | |
| 562 | const sink = yield* makeTraceSink({ |
| 563 | filePath: tracePath, |
| 564 | maxBytes: 1024, |
| 565 | maxFiles: 2, |
| 566 | batchWindowMs: 10_000, |
| 567 | }); |
| 568 | |
| 569 | const circular: Array<unknown> = []; |
| 570 | circular.push(circular); |
| 571 | |
| 572 | sink.push(makeRecord("alpha")); |
| 573 | sink.push({ |
| 574 | ...makeRecord("invalid"), |
| 575 | attributes: { |
| 576 | circular, |
| 577 | }, |
| 578 | } as TraceRecord); |
| 579 | sink.push(makeRecord("beta")); |
| 580 | yield* sink.close(); |
| 581 | |
| 582 | const lines = yield* readTraceRecords(tracePath); |
| 583 | |
| 584 | assert.deepStrictEqual( |
| 585 | lines.map((line) => line.name), |
| 586 | ["alpha", "beta"], |
| 587 | ); |
| 588 | }), |
| 589 | ), |
| 590 | ); |
| 591 | |
| 592 | it.effect("drops records after a failed write and logs once per failure episode", () => { |
| 593 | const logs: Array<{ readonly logLevel: string; readonly message: unknown }> = []; |
| 594 | const captureLogs = Logger.make(({ logLevel, message }) => { |
| 595 | logs.push({ logLevel, message }); |
| 596 | }); |
| 597 | const spans: Array<Tracer.NativeSpan> = []; |
| 598 | const recordingTracer = Tracer.make({ |
| 599 | span: (options) => { |
| 600 | const span = new Tracer.NativeSpan(options); |
| 601 | spans.push(span); |
| 602 | return span; |
| 603 | }, |
| 604 | }); |
| 605 | |
| 606 | return Effect.gen(function* () { |
| 607 | const fileSystem = yield* FileSystem.FileSystem; |
| 608 | const path = yield* Path.Path; |
| 609 | const tempDir = yield* fileSystem.makeTempDirectoryScoped({ prefix: "t3-trace-sink-" }); |
| 610 | const tracePath = path.join(tempDir, "shared.trace.ndjson"); |
| 611 | // A directory at the trace path fails every append, like a full disk. |
| 612 | yield* fileSystem.makeDirectory(tracePath); |
| 613 | const write = vi.spyOn(fileSystem, "writeFile"); |
| 614 | yield* Effect.addFinalizer(() => Effect.sync(() => write.mockRestore())); |
| 615 | |
| 616 | const sink = yield* makeTraceSink({ |
| 617 | filePath: tracePath, |
| 618 | maxBytes: 1024 * 1024, |
| 619 | maxFiles: 2, |
| 620 | batchWindowMs: 1_000, |
| 621 | }).pipe(Effect.withTracer(recordingTracer)); |
| 622 | |
| 623 | for (let index = 0; index < 1_024; index += 1) { |
| 624 | sink.push(makeRecord("lost", String(index))); |
| 625 | } |
| 626 | yield* sink.flush; |
| 627 | // Timed flushes run in the fiber forked inside the makeTraceSink span. |
| 628 | for (let index = 0; index < 5; index += 1) { |
| 629 | sink.push(makeRecord("lost")); |
| 630 | yield* TestClock.adjust("1 second"); |
| 631 | yield* sink.flush; |
| 632 | } |
| 633 | |
| 634 | // One write per batch, never a growing backlog. |
| 635 | assert.deepStrictEqual( |
| 636 | write.mock.calls.map(([, chunk]) => Buffer.from(chunk).toString().split("\n").length - 1), |
| 637 | [1024, 1, 1, 1, 1, 1], |
| 638 | ); |
| 639 | expect(logs).toEqual([ |
| 640 | { logLevel: "Warn", message: [expect.any(String), { filePath: tracePath }] }, |
| 641 | ]); |
| 642 | |
| 643 | // Once the disk recovers, new records are written and the loss is reported. |
| 644 | yield* fileSystem.remove(tracePath, { recursive: true }); |
| 645 | sink.push(makeRecord("recovered")); |
| 646 | yield* TestClock.adjust("1 second"); |
| 647 | yield* sink.flush; |
| 648 | |
| 649 | const records = yield* readTraceRecords(tracePath); |
| 650 | assert.deepStrictEqual( |
| 651 | records.map((record) => record.name), |
| 652 | ["recovered"], |
| 653 | ); |
| 654 | expect(logs[1]).toEqual({ |
| 655 | logLevel: "Info", |
| 656 | message: [expect.any(String), { filePath: tracePath, droppedCount: 1_029 }], |
| 657 | }); |
| 658 | |
| 659 | // Healthy flushes after the recovery log nothing. |
| 660 | sink.push(makeRecord("healthy")); |
| 661 | yield* TestClock.adjust("1 second"); |
| 662 | yield* sink.flush; |
| 663 | expect(logs).toHaveLength(2); |
| 664 | |
| 665 | // A new failure episode warns again. |
| 666 | yield* fileSystem.remove(tracePath); |
| 667 | yield* fileSystem.makeDirectory(tracePath); |
| 668 | sink.push(makeRecord("lost-again")); |
| 669 | yield* TestClock.adjust("1 second"); |
| 670 | yield* sink.flush; |
| 671 | assert.deepStrictEqual( |
| 672 | logs.map((log) => log.logLevel), |
| 673 | ["Warn", "Info", "Warn"], |
| 674 | ); |
| 675 | |
| 676 | // The ended makeTraceSink span is never released, so it must not collect log events. |
| 677 | assert.deepStrictEqual( |
| 678 | spans.map((span) => [span.name, span.events.length]), |
| 679 | [["makeTraceSink", 0]], |
| 680 | ); |
| 681 | }).pipe( |
| 682 | Effect.scoped, |
| 683 | Effect.provide( |
| 684 | Logger.layer([captureLogs, Logger.tracerLogger], { mergeWithExisting: false }), |
| 685 | ), |
| 686 | ); |
| 687 | }); |
| 688 | |
| 689 | it.effect("writes nested spans to disk and captures log messages as span events", () => |
| 690 | Effect.scoped( |
| 691 | Effect.gen(function* () { |
| 692 | const fileSystem = yield* FileSystem.FileSystem; |
| 693 | const path = yield* Path.Path; |
| 694 | const tempDir = yield* fileSystem.makeTempDirectoryScoped({ prefix: "t3-local-tracer-" }); |
| 695 | const tracePath = path.join(tempDir, "shared.trace.ndjson"); |
| 696 | |
| 697 | yield* Effect.scoped( |
| 698 | Effect.gen(function* () { |
| 699 | const program = Effect.gen(function* () { |
| 700 | yield* Effect.annotateCurrentSpan({ |
| 701 | "demo.parent": true, |
| 702 | }); |
| 703 | yield* Effect.logInfo("parent event"); |
| 704 | yield* Effect.gen(function* () { |
| 705 | yield* Effect.annotateCurrentSpan({ |
| 706 | "demo.child": true, |
| 707 | }); |
| 708 | yield* Effect.logInfo("child event"); |
| 709 | }).pipe(Effect.withSpan("child-span")); |
| 710 | }).pipe(Effect.withSpan("parent-span")); |
| 711 | |
| 712 | yield* program.pipe(Effect.provide(layerTest(tracePath))); |
| 713 | }), |
| 714 | ); |
| 715 | |
| 716 | const records = yield* readTraceRecords(tracePath); |
| 717 | assert.equal(records.length, 2); |
| 718 | |
| 719 | const parent = records.find((record) => record.name === "parent-span"); |
| 720 | const child = records.find((record) => record.name === "child-span"); |
| 721 | |
| 722 | assert.notEqual(parent, undefined); |
| 723 | assert.notEqual(child, undefined); |
| 724 | if (!parent || !child) { |
| 725 | return; |
| 726 | } |
| 727 | |
| 728 | assert.equal(child.parentSpanId, parent.spanId); |
| 729 | assert.equal(parent.attributes["demo.parent"], true); |
| 730 | assert.equal(child.attributes["demo.child"], true); |
| 731 | assert.equal( |
| 732 | parent.events.some((event) => event.name === "parent event"), |
| 733 | true, |
| 734 | ); |
| 735 | assert.equal( |
| 736 | child.events.some((event) => event.name === "child event"), |
| 737 | true, |
| 738 | ); |
| 739 | assert.equal( |
| 740 | child.events.some((event) => event.attributes["effect.logLevel"] === "INFO"), |
| 741 | true, |
| 742 | ); |
| 743 | }), |
| 744 | ), |
| 745 | ); |
| 746 | |
| 747 | it.effect("serializes interrupted spans with an interrupted exit status", () => |
| 748 | Effect.scoped( |
| 749 | Effect.gen(function* () { |
| 750 | const fileSystem = yield* FileSystem.FileSystem; |
| 751 | const path = yield* Path.Path; |
| 752 | const tempDir = yield* fileSystem.makeTempDirectoryScoped({ prefix: "t3-local-tracer-" }); |
| 753 | const tracePath = path.join(tempDir, "shared.trace.ndjson"); |
| 754 | |
| 755 | yield* Effect.scoped( |
| 756 | Effect.exit( |
| 757 | Effect.interrupt.pipe( |
| 758 | Effect.withSpan("interrupt-span"), |
| 759 | Effect.provide(layerTest(tracePath)), |
| 760 | ), |
| 761 | ), |
| 762 | ); |
| 763 | |
| 764 | const records = yield* readTraceRecords(tracePath); |
| 765 | assert.equal(records.length, 1); |
| 766 | assert.equal(records[0]?.name, "interrupt-span"); |
| 767 | assert.equal(records[0]?.exit?._tag, "Interrupted"); |
| 768 | }), |
| 769 | ), |
| 770 | ); |
| 771 | }); |
| 772 | }); |
| 773 | |
| 774 | describe("OtlpHeadersFromString", () => { |
| 775 | const decode = Schema.decodeUnknownSync(OtlpHeadersFromString); |
| 776 | |
| 777 | it.each([ |
| 778 | { |
| 779 | name: "decodes percent-encoded values", |
| 780 | input: "authorization=Basic%20abc%3D%3D,x-tenant=t3", |
| 781 | expected: { authorization: "Basic abc==", "x-tenant": "t3" }, |
| 782 | }, |
| 783 | { |
| 784 | name: "ignores whitespace around separators", |
| 785 | input: "authorization=Basic%20abc%3D%3D, x-tenant = t3 ,", |
| 786 | expected: { authorization: "Basic abc==", "x-tenant": "t3" }, |
| 787 | }, |
| 788 | { |
| 789 | name: "keeps literal equals signs inside a value", |
| 790 | input: "authorization=Bearer abc==", |
| 791 | expected: { authorization: "Bearer abc==" }, |
| 792 | }, |
| 793 | { |
| 794 | name: "keeps an empty value", |
| 795 | input: "x-empty=", |
| 796 | expected: { "x-empty": "" }, |
| 797 | }, |
| 798 | ])("$name", ({ input, expected }) => { |
| 799 | expect(decode(input)).toEqual(expected); |
| 800 | }); |
| 801 | |
| 802 | it.each([ |
| 803 | { name: "rejects a pair without a separator", input: "authorization" }, |
| 804 | { name: "rejects a pair without a key", input: "=value" }, |
| 805 | { name: "rejects a malformed percent-encoding", input: "authorization=%E0" }, |
| 806 | ])("$name", ({ input }) => { |
| 807 | expect(() => decode(input)).toThrow(); |
| 808 | }); |
| 809 | }); |