From 44e49316516708884c459a29569c12ebbe584d4a Mon Sep 17 00:00:00 2001 From: ben-fornefeld Date: Thu, 4 Jun 2026 21:38:32 -0700 Subject: [PATCH] fix: flush otel logs with vercel waitUntil --- bun.lock | 28 +++---- package.json | 4 +- .../vercel-wait-until-log-record-processor.ts | 73 +++++++++++++++++++ src/instrumentation.node.ts | 11 ++- ...el-wait-until-log-record-processor.test.ts | 72 ++++++++++++++++++ 5 files changed, 168 insertions(+), 20 deletions(-) create mode 100644 src/core/server/observability/vercel-wait-until-log-record-processor.ts create mode 100644 tests/unit/vercel-wait-until-log-record-processor.test.ts diff --git a/bun.lock b/bun.lock index a97d38482..e8d4cc8c1 100644 --- a/bun.lock +++ b/bun.lock @@ -7,7 +7,7 @@ "@hookform/resolvers": "^5.2.2", "@marsidev/react-turnstile": "^1.4.1", "@next-safe-action/adapter-react-hook-form": "^2.0.0", - "@next/env": "^16.2.6", + "@next/env": "^16.2.7", "@opentelemetry/api": "^1.9.0", "@opentelemetry/auto-instrumentations-node": "^0.62.1", "@opentelemetry/exporter-logs-otlp-http": "^0.203.0", @@ -68,7 +68,7 @@ "micromatch": "^4.0.8", "motion": "^12.23.25", "nanoid": "^5.0.9", - "next": "^16.2.6", + "next": "^16.2.7", "next-safe-action": "^8.0.11", "next-themes": "^0.4.6", "nuqs": "^2.7.0", @@ -391,23 +391,23 @@ "@next-safe-action/adapter-react-hook-form": ["@next-safe-action/adapter-react-hook-form@2.0.0", "", { "peerDependencies": { "@hookform/resolvers": ">= 5.0.0", "next": ">= 14.0.0", "next-safe-action": ">= 8.0.0", "react": ">= 18.2.0", "react-dom": ">= 18.2.0", "react-hook-form": ">= 7.0.0" } }, "sha512-vp3KAd5NKnBBCF/3b8kDxEYj0+BUYVjlSZOWHikz/Y2O+yLheRmtj8Vcm379itlqGUKcLV5O2o/dwKHvH8pYog=="], - "@next/env": ["@next/env@16.2.6", "", {}, "sha512-gd8HoHN4ufj73WmR3JmVolrpJR47ILK6LouP5xElPglaVxir6e1a7VzvTvDWkOoPXT9rkkTzyCxBu4yeZfZwcw=="], + "@next/env": ["@next/env@16.2.7", "", {}, "sha512-tMJizPlj6ZYpBMMdK8S0LJufrP4QTdR6pcv9KQ/bVETPAmg0j1mlHE9G2c38UyGHxoBapgwuj7XjbGJ2RcDFOg=="], - "@next/swc-darwin-arm64": ["@next/swc-darwin-arm64@16.2.6", "", { "os": "darwin", "cpu": "arm64" }, "sha512-ZJGkkcNfYgrrMkqOdZ7zoLa1TOy0qpcMfk/z4Mh/FKUz40gVO+HNQWqmLxf67Z5WB64DRp0dhEbyHfel+6sJUg=="], + "@next/swc-darwin-arm64": ["@next/swc-darwin-arm64@16.2.7", "", { "os": "darwin", "cpu": "arm64" }, "sha512-vm1EDI/pVaBNNiychmxk3fft+OhQPVD9cIM/tReLZIQ3TfQ4kqI9DwKk00dzuS1ulC7icbrzCFrmRRlk9PfNdw=="], - "@next/swc-darwin-x64": ["@next/swc-darwin-x64@16.2.6", "", { "os": "darwin", "cpu": "x64" }, "sha512-v/YLBHIY132Ced3puBJ7YJKw1lqsCrgcNo2aRJlCEyQrrCeRJlvGlnmxhPxNQI3KE3N1DN5r9TPNPvka3nq5RQ=="], + "@next/swc-darwin-x64": ["@next/swc-darwin-x64@16.2.7", "", { "os": "darwin", "cpu": "x64" }, "sha512-O3IRSv1ZBL1zs0WrIgefTEcTKFVn+ryxBNe54erJ6KsD+2f/Mmt7g2jOYh8PSBdUwPtKQJuCsTMlZ7tIu2AcsQ=="], - "@next/swc-linux-arm64-gnu": ["@next/swc-linux-arm64-gnu@16.2.6", "", { "os": "linux", "cpu": "arm64" }, "sha512-RPOvqlYBbcQjkz9VQQDZ2T2bARIjXZV1KFlt+V2Mr6SW/e4I9fcKsaA0hdyf2FHoTlsV2xnBd5Y912rP/1Ce6w=="], + "@next/swc-linux-arm64-gnu": ["@next/swc-linux-arm64-gnu@16.2.7", "", { "os": "linux", "cpu": "arm64" }, "sha512-Re6PZtjBDd0aMU+VcZcC/PrIvj4WhrjDYtMhhCVQamWN4L90EVP0pcEOBQD25prSlw7OzNw5QpHLWMilRLsRNw=="], - "@next/swc-linux-arm64-musl": ["@next/swc-linux-arm64-musl@16.2.6", "", { "os": "linux", "cpu": "arm64" }, "sha512-URUTu1+dMkxJsPFgm+OeEvq9wf5sujw0EvgYy80TDGHTSLTnIHeqb0Eu8A3sC95IRgjejQL+kC4mw+4yPxiAXA=="], + "@next/swc-linux-arm64-musl": ["@next/swc-linux-arm64-musl@16.2.7", "", { "os": "linux", "cpu": "arm64" }, "sha512-qyogG9QtBzWxgJfeGBvOEHI3851gTfCF3wLZ5RDLTBJGAmE9p1qDwKCOdrBrvBzRvYDT+gUDp72pzlSEfAXgNA=="], - "@next/swc-linux-x64-gnu": ["@next/swc-linux-x64-gnu@16.2.6", "", { "os": "linux", "cpu": "x64" }, "sha512-DOj182mPV8G3UkrayLoREM5YEYI+Dk5wv7Ox9xl1fFibAELEsFD0lDPfHIeILlutMMfdyhlzYPELG3peuKaurw=="], + "@next/swc-linux-x64-gnu": ["@next/swc-linux-x64-gnu@16.2.7", "", { "os": "linux", "cpu": "x64" }, "sha512-Vhe4ZDuBpmMogrGi5D4R2Kq4JAQlj6+wvgaFYy31zfES0zPmt6TLA+cuYpM/OLrPZjo2MYQTHVqNUSCR6+fDZQ=="], - "@next/swc-linux-x64-musl": ["@next/swc-linux-x64-musl@16.2.6", "", { "os": "linux", "cpu": "x64" }, "sha512-HKQ5SP/V/ub73UvF7n/zeJlxk2kLmtL7Wzrg4WfmkjmNos5onJ2tKu7yZOPdL18A6Svfn3max29ym+ry7NkK4g=="], + "@next/swc-linux-x64-musl": ["@next/swc-linux-x64-musl@16.2.7", "", { "os": "linux", "cpu": "x64" }, "sha512-srvian89JahFLw1YLBEuhvPJ0DO5lpUeJQMXy4xYo7g628ZlNgXdNkqoxSAv9OYrBfByh6vxISMwW/mRbzCY+g=="], - "@next/swc-win32-arm64-msvc": ["@next/swc-win32-arm64-msvc@16.2.6", "", { "os": "win32", "cpu": "arm64" }, "sha512-LZXpTlPyS5v7HhSmnvsLGP3iIYgYOBnc8r8ArlT55sGHV89bR2HlDdBjWQ+PY6SJMmk8TuVGFuxalnP3k/0Dwg=="], + "@next/swc-win32-arm64-msvc": ["@next/swc-win32-arm64-msvc@16.2.7", "", { "os": "win32", "cpu": "arm64" }, "sha512-GX3wvLpULFuRFJzwHaKfm7QZJ18F4ZSuxlPJ96BoBglCzBmdSjyeBKF+ZhWhvL/ckxNfLnNa7bsObO2ipYpszw=="], - "@next/swc-win32-x64-msvc": ["@next/swc-win32-x64-msvc@16.2.6", "", { "os": "win32", "cpu": "x64" }, "sha512-F0+4i0h9J6C4eE3EAPWsoCk7UW/dbzOjyzxY0qnDUOYFu6FFmdZ6l97/XdV3/Nz3VYyO7UWjyEJUXkGqcoXfMA=="], + "@next/swc-win32-x64-msvc": ["@next/swc-win32-x64-msvc@16.2.7", "", { "os": "win32", "cpu": "x64" }, "sha512-J4WlM72NMk076Qsg0jTdK3SNXatlSdnjW7L7oNGLst1tAGjHrJh/FYi+pw9wyIjEtGRKDNzD0zuiY16oWYWVaw=="], "@opentelemetry/api": ["@opentelemetry/api@1.9.0", "", {}, "sha512-3giAOQvZiH5F9bMlMiv8+GSPMeqg0dbaeo58/0SlA9sxSqZhnUtxzX9/2FzyhS9sWQf5S0GJE0AKBrFqjpeYcg=="], @@ -1017,8 +1017,6 @@ "@vercel/speed-insights": ["@vercel/speed-insights@1.2.0", "", { "peerDependencies": { "@sveltejs/kit": "^1 || ^2", "next": ">= 13", "react": "^18 || ^19 || ^19.0.0-rc", "svelte": ">= 4", "vue": "^3", "vue-router": "^4" }, "optionalPeers": ["@sveltejs/kit", "next", "react", "svelte", "vue", "vue-router"] }, "sha512-y9GVzrUJ2xmgtQlzFP2KhVRoCglwfRQgjyfY607aU0hh0Un6d0OUyrJkjuAlsV18qR4zfoFPs/BiIj9YDS6Wzw=="], - "@xterm/xterm": ["@xterm/xterm@6.0.0", "", {}, "sha512-TQwDdQGtwwDt+2cgKDLn0IRaSxYu1tSUjgKarSDkUM0ZNiSRXFpjxEsvc/Zgc5kq5omJ+V0a8/kIM2WD3sMOYg=="], - "@vitest/coverage-v8": ["@vitest/coverage-v8@3.2.4", "", { "dependencies": { "@ampproject/remapping": "^2.3.0", "@bcoe/v8-coverage": "^1.0.2", "ast-v8-to-istanbul": "^0.3.3", "debug": "^4.4.1", "istanbul-lib-coverage": "^3.2.2", "istanbul-lib-report": "^3.0.1", "istanbul-lib-source-maps": "^5.0.6", "istanbul-reports": "^3.1.7", "magic-string": "^0.30.17", "magicast": "^0.3.5", "std-env": "^3.9.0", "test-exclude": "^7.0.1", "tinyrainbow": "^2.0.0" }, "peerDependencies": { "@vitest/browser": "3.2.4", "vitest": "3.2.4" }, "optionalPeers": ["@vitest/browser"] }, "sha512-EyF9SXU6kS5Ku/U82E259WSnvg6c8KTjppUncuNdm5QHpe17mwREHnjDzozC8x9MZ0xfBUFSaLkRv4TMA75ALQ=="], "@vitest/expect": ["@vitest/expect@3.2.4", "", { "dependencies": { "@types/chai": "^5.2.2", "@vitest/spy": "3.2.4", "@vitest/utils": "3.2.4", "chai": "^5.2.0", "tinyrainbow": "^2.0.0" } }, "sha512-Io0yyORnB6sikFlt8QW5K7slY4OjqNX9jmJQ02QDda8lyM6B5oNgVWoSoKPac8/kgnCUzuHQKrSLtu/uOqqrig=="], @@ -1037,6 +1035,8 @@ "@vitest/utils": ["@vitest/utils@3.0.7", "", { "dependencies": { "@vitest/pretty-format": "3.0.7", "loupe": "^3.1.3", "tinyrainbow": "^2.0.0" } }, "sha512-xePVpCRfooFX3rANQjwoditoXgWb1MaFbzmGuPP59MK6i13mrnDw/yEIyJudLeW6/38mCNcwCiJIGmpDPibAIg=="], + "@xterm/xterm": ["@xterm/xterm@6.0.0", "", {}, "sha512-TQwDdQGtwwDt+2cgKDLn0IRaSxYu1tSUjgKarSDkUM0ZNiSRXFpjxEsvc/Zgc5kq5omJ+V0a8/kIM2WD3sMOYg=="], + "acorn": ["acorn@8.15.0", "", { "bin": { "acorn": "bin/acorn" } }, "sha512-NZyJarBfL7nWwIq+FDL6Zp/yHEhePMNnnJ0y3qfieCrmNvYct8uvtiV41UvlSe6apAfk0fY1FbWx+NwfmpvtTg=="], "acorn-import-attributes": ["acorn-import-attributes@1.9.5", "", { "peerDependencies": { "acorn": "^8" } }, "sha512-n02Vykv5uA3eHGM/Z2dQrcD56kL8TyDb2p1+0P83PClMnC/nc+anbQRhIOWnSq4Ke/KvDPrY3C9hDtC/A3eHnQ=="], @@ -1501,7 +1501,7 @@ "nanoid": ["nanoid@5.1.6", "", { "bin": { "nanoid": "bin/nanoid.js" } }, "sha512-c7+7RQ+dMB5dPwwCp4ee1/iV/q2P6aK1mTZcfr1BTuVlyW9hJYiMPybJCcnBlQtuSmTIWNeazm/zqNoZSSElBg=="], - "next": ["next@16.2.6", "", { "dependencies": { "@next/env": "16.2.6", "@swc/helpers": "0.5.15", "baseline-browser-mapping": "^2.9.19", "caniuse-lite": "^1.0.30001579", "postcss": "8.4.31", "styled-jsx": "5.1.6" }, "optionalDependencies": { "@next/swc-darwin-arm64": "16.2.6", "@next/swc-darwin-x64": "16.2.6", "@next/swc-linux-arm64-gnu": "16.2.6", "@next/swc-linux-arm64-musl": "16.2.6", "@next/swc-linux-x64-gnu": "16.2.6", "@next/swc-linux-x64-musl": "16.2.6", "@next/swc-win32-arm64-msvc": "16.2.6", "@next/swc-win32-x64-msvc": "16.2.6", "sharp": "^0.34.5" }, "peerDependencies": { "@opentelemetry/api": "^1.1.0", "@playwright/test": "^1.51.1", "babel-plugin-react-compiler": "*", "react": "^18.2.0 || 19.0.0-rc-de68d2f4-20241204 || ^19.0.0", "react-dom": "^18.2.0 || 19.0.0-rc-de68d2f4-20241204 || ^19.0.0", "sass": "^1.3.0" }, "optionalPeers": ["@opentelemetry/api", "@playwright/test", "babel-plugin-react-compiler", "sass"], "bin": { "next": "dist/bin/next" } }, "sha512-qOVgKJg1+At15NpeUP+eJgCHvTCgXsogweq87Ri/Ix7PkqQHg4sdaXmSFqKlgaIXE4kW0g25LE68W87UANlHtw=="], + "next": ["next@16.2.7", "", { "dependencies": { "@next/env": "16.2.7", "@swc/helpers": "0.5.15", "baseline-browser-mapping": "^2.9.19", "caniuse-lite": "^1.0.30001579", "postcss": "8.4.31", "styled-jsx": "5.1.6" }, "optionalDependencies": { "@next/swc-darwin-arm64": "16.2.7", "@next/swc-darwin-x64": "16.2.7", "@next/swc-linux-arm64-gnu": "16.2.7", "@next/swc-linux-arm64-musl": "16.2.7", "@next/swc-linux-x64-gnu": "16.2.7", "@next/swc-linux-x64-musl": "16.2.7", "@next/swc-win32-arm64-msvc": "16.2.7", "@next/swc-win32-x64-msvc": "16.2.7", "sharp": "^0.34.5" }, "peerDependencies": { "@opentelemetry/api": "^1.1.0", "@playwright/test": "^1.51.1", "babel-plugin-react-compiler": "*", "react": "^18.2.0 || 19.0.0-rc-de68d2f4-20241204 || ^19.0.0", "react-dom": "^18.2.0 || 19.0.0-rc-de68d2f4-20241204 || ^19.0.0", "sass": "^1.3.0" }, "optionalPeers": ["@opentelemetry/api", "@playwright/test", "babel-plugin-react-compiler", "sass"], "bin": { "next": "dist/bin/next" } }, "sha512-eMJxgjRzBaj3olkP4cBamHDXL79A8FC6u1GcsO1D1Tsx8bw/LLXUJCaoajVxtnhD3A1IJqIT8IcRJjgBIPJq4w=="], "next-safe-action": ["next-safe-action@8.0.11", "", { "peerDependencies": { "next": ">= 14.0.0", "react": ">= 18.2.0", "react-dom": ">= 18.2.0" } }, "sha512-gqJLmnQLAoFCq1kRBopN46New+vx1n9J9Y/qDQLXpv/VqU40AWxDakvshwwnWAt8R0kLvlakNYNLX5PqlXWSMg=="], diff --git a/package.json b/package.json index 2477377ca..9da397f66 100644 --- a/package.json +++ b/package.json @@ -49,7 +49,7 @@ "@hookform/resolvers": "^5.2.2", "@marsidev/react-turnstile": "^1.4.1", "@next-safe-action/adapter-react-hook-form": "^2.0.0", - "@next/env": "^16.2.6", + "@next/env": "^16.2.7", "@opentelemetry/api": "^1.9.0", "@opentelemetry/auto-instrumentations-node": "^0.62.1", "@opentelemetry/exporter-logs-otlp-http": "^0.203.0", @@ -110,7 +110,7 @@ "micromatch": "^4.0.8", "motion": "^12.23.25", "nanoid": "^5.0.9", - "next": "^16.2.6", + "next": "^16.2.7", "next-safe-action": "^8.0.11", "next-themes": "^0.4.6", "nuqs": "^2.7.0", diff --git a/src/core/server/observability/vercel-wait-until-log-record-processor.ts b/src/core/server/observability/vercel-wait-until-log-record-processor.ts new file mode 100644 index 000000000..741f8719c --- /dev/null +++ b/src/core/server/observability/vercel-wait-until-log-record-processor.ts @@ -0,0 +1,73 @@ +import { type Context, diag } from '@opentelemetry/api' +import type { LogRecordProcessor, SdkLogRecord } from '@opentelemetry/sdk-logs' + +type WaitUntilInput = Promise | (() => Promise) + +interface VercelRequestContext { + waitUntil: (promiseOrFunc: WaitUntilInput) => void +} + +interface VercelRequestContextReader { + get: () => VercelRequestContext | undefined +} + +// This mirrors the private request-context hook used by @vercel/otel. +const VERCEL_REQUEST_CONTEXT_SYMBOL = Symbol.for('@vercel/request-context') + +function getVercelRequestContext(): VercelRequestContext | undefined { + const reader = Reflect.get(globalThis, VERCEL_REQUEST_CONTEXT_SYMBOL) as + | VercelRequestContextReader + | undefined + + return reader?.get() +} + +export class VercelWaitUntilLogRecordProcessor implements LogRecordProcessor { + private readonly pendingFlushContexts = new WeakSet() + + constructor(private readonly delegate: LogRecordProcessor) {} + + onEmit(logRecord: SdkLogRecord, context?: Context): void { + this.delegate.onEmit(logRecord, context) + this.scheduleRequestFlush() + } + + forceFlush(): Promise { + return this.delegate.forceFlush() + } + + shutdown(): Promise { + return this.delegate.shutdown() + } + + private scheduleRequestFlush(): void { + const requestContext = getVercelRequestContext() + + if (!requestContext || this.pendingFlushContexts.has(requestContext)) { + return + } + + this.pendingFlushContexts.add(requestContext) + + try { + requestContext.waitUntil(async () => { + try { + await this.delegate.forceFlush() + } catch (error) { + diag.warn( + 'Failed to flush OpenTelemetry logs in Vercel waitUntil', + error + ) + } finally { + this.pendingFlushContexts.delete(requestContext) + } + }) + } catch (error) { + this.pendingFlushContexts.delete(requestContext) + diag.warn( + 'Failed to schedule OpenTelemetry log flush in Vercel waitUntil', + error + ) + } + } +} diff --git a/src/instrumentation.node.ts b/src/instrumentation.node.ts index 041c8c6ad..fb0cf076c 100644 --- a/src/instrumentation.node.ts +++ b/src/instrumentation.node.ts @@ -15,6 +15,7 @@ import { ATTR_SERVICE_VERSION, } from '@opentelemetry/semantic-conventions' import { FetchInstrumentation } from '@vercel/otel' +import { VercelWaitUntilLogRecordProcessor } from './core/server/observability/vercel-wait-until-log-record-processor' function parseResourceAttributes( resourceAttrs?: string @@ -76,10 +77,12 @@ const sdk = new NodeSDK({ }), }), logRecordProcessors: [ - new BatchLogRecordProcessor( - new OTLPLogExporter({ - url: `${OTEL_EXPORTER_OTLP_ENDPOINT}/v1/logs`, - }) + new VercelWaitUntilLogRecordProcessor( + new BatchLogRecordProcessor( + new OTLPLogExporter({ + url: `${OTEL_EXPORTER_OTLP_ENDPOINT}/v1/logs`, + }) + ) ), ], instrumentations: [ diff --git a/tests/unit/vercel-wait-until-log-record-processor.test.ts b/tests/unit/vercel-wait-until-log-record-processor.test.ts new file mode 100644 index 000000000..d9ed4b990 --- /dev/null +++ b/tests/unit/vercel-wait-until-log-record-processor.test.ts @@ -0,0 +1,72 @@ +import type { Context } from '@opentelemetry/api' +import type { LogRecordProcessor, SdkLogRecord } from '@opentelemetry/sdk-logs' +import { afterEach, describe, expect, it, vi } from 'vitest' +import { VercelWaitUntilLogRecordProcessor } from '@/core/server/observability/vercel-wait-until-log-record-processor' + +type WaitUntilCallback = () => Promise +type WaitUntilInput = Promise | WaitUntilCallback + +const requestContextSymbol = Symbol.for('@vercel/request-context') +const logRecord = {} as SdkLogRecord + +class TestLogRecordProcessor implements LogRecordProcessor { + readonly onEmit = vi.fn() + readonly forceFlush = vi.fn(async () => {}) + readonly shutdown = vi.fn(async () => {}) +} + +function installVercelRequestContext( + waitUntil: (input: WaitUntilInput) => void +) { + const requestContext = { + waitUntil, + } + + Reflect.set(globalThis, requestContextSymbol, { + get: () => requestContext, + }) +} + +afterEach(() => { + Reflect.deleteProperty(globalThis, requestContextSymbol) + vi.clearAllMocks() +}) + +describe('VercelWaitUntilLogRecordProcessor', () => { + it('delegates log records without a Vercel request context', () => { + const delegate = new TestLogRecordProcessor() + const processor = new VercelWaitUntilLogRecordProcessor(delegate) + + processor.onEmit(logRecord) + + expect(delegate.onEmit).toHaveBeenCalledWith(logRecord, undefined) + expect(delegate.forceFlush).not.toHaveBeenCalled() + }) + + it('schedules one waitUntil flush per request context', async () => { + const callbacks: WaitUntilCallback[] = [] + const waitUntil = vi.fn((input: WaitUntilInput) => { + callbacks.push( + typeof input === 'function' ? input : async () => await input + ) + }) + installVercelRequestContext(waitUntil) + + const delegate = new TestLogRecordProcessor() + const processor = new VercelWaitUntilLogRecordProcessor(delegate) + + processor.onEmit(logRecord) + processor.onEmit(logRecord) + + expect(delegate.onEmit).toHaveBeenCalledTimes(2) + expect(waitUntil).toHaveBeenCalledTimes(1) + + await callbacks[0]?.() + + expect(delegate.forceFlush).toHaveBeenCalledTimes(1) + + processor.onEmit(logRecord, {} as Context) + + expect(waitUntil).toHaveBeenCalledTimes(2) + }) +})