From 25405881ad4935810d6a5839f1c1a7aba705d659 Mon Sep 17 00:00:00 2001 From: Sebastian Van Syckel Date: Fri, 31 Jul 2026 14:13:27 +0200 Subject: [PATCH 1/6] feat: wrap cds.Service.prototype.tx for queue worker tracing; replace log-regex tests with structured in-memory spans Queue worker tracing: - Wraps cds.Service.prototype.tx() so that the queue worker's two-transaction structure (SELECT+UPDATE lock tx, then handle+DELETE dispatch tx) appears as child spans under their trace root instead of each top-level CAP call inside them becoming an orphan root. - Guard: skips when this.context instanceof cds.EventContext so $batch sub-requests are not affected, and skips the bare {} context from processInboundMsg so file-based messaging consumer delivery gets a messaging - tx root span. - SQLite note: CDS uses a raw setTimeout bypass for sqlite queue workers (to avoid deadlocks) so cds.spawn is not called, and spawn-root tracing is not available on sqlite. Affected tests are skipped on sqlite and verified on HANA in CI. Test infrastructure (from PR #450): - MyInMemorySpanExporter: structured in-memory span store replacing fragile cds.test.log() regex matching. groupedByTrace() / rootSpans() helpers let tests assert on span trees directly. - tracing-in-memory profile in .cdsrc.json; tracing-attributes profile preserved. - tracing.test.js, tracing-attributes.test.js, tracing-mt.test.js, tracing-messaging*.js rewritten to use structured span assertions. - New test files: tracing-scheduled, tracing-outboxed-batch, tracing-messaging-inboxed, tracing-messaging-outboxed-and-inboxed, tracing-messaging-persistent-outbox, console-span-exporter (unit test). - tracing-messaging.js: configurable waitMs (default 2500ms, 4000ms for inbox/persistent-outbox scenarios); afterAll wait bumped to 2s. - admin-service: test_outboxed_send / test_outboxed_send_batch / test_scheduled actions added for the new test scenarios. --- lib/tracing/cds.js | 19 ++ test/bookshop/.cdsrc.json | 31 +++ test/bookshop/lib/MyInMemorySpanExporter.js | 59 +++++ test/bookshop/srv/admin-service.cds | 3 + test/bookshop/srv/admin-service.js | 24 ++ test/console-span-exporter.test.js | 243 ++++++++++++++++++ test/tracing-attributes.test.js | 79 +++--- test/tracing-messaging-inboxed.test.js | 59 +++++ ...ing-messaging-outboxed-and-inboxed.test.js | 55 ++++ ...racing-messaging-persistent-outbox.test.js | 97 ++++++- test/tracing-messaging-without-outbox.test.js | 39 ++- test/tracing-messaging.js | 22 +- test/tracing-mt.test.js | 20 +- test/tracing-outboxed-batch.test.js | 68 +++++ test/tracing-scheduled.test.js | 65 +++++ test/tracing.test.js | 71 +++-- 16 files changed, 855 insertions(+), 99 deletions(-) create mode 100644 test/bookshop/lib/MyInMemorySpanExporter.js create mode 100644 test/console-span-exporter.test.js create mode 100644 test/tracing-messaging-inboxed.test.js create mode 100644 test/tracing-messaging-outboxed-and-inboxed.test.js create mode 100644 test/tracing-outboxed-batch.test.js create mode 100644 test/tracing-scheduled.test.js diff --git a/lib/tracing/cds.js b/lib/tracing/cds.js index c6766273..07445ef0 100644 --- a/lib/tracing/cds.js +++ b/lib/tracing/cds.js @@ -46,6 +46,25 @@ module.exports = () => { } }) + // Wrap `srv.tx(fn)` so the queue worker's two transactions (SELECT+UPDATE lock tx, + // then handle+DELETE dispatch tx) appear as child spans of the `cds.spawn - run task` + // root instead of each top-level CAP call inside them becoming an orphan root. + // Only wraps when there is no current `srv.context` (i.e. not already inside a request). + const _tx_proto = cds.Service.prototype.tx + cds.Service.prototype.tx = wrap(_tx_proto, { + wrapper: function tx() { + const fnIdx = typeof arguments[0] === 'function' ? 0 : typeof arguments[1] === 'function' ? 1 : -1 + if (fnIdx < 0) return _tx_proto.apply(this, arguments) + // Skip if this service is already handling a request (has an active EventContext), + // or if this is a nested .tx() call (cds.Service.tx is a no-op when already in tx). + // Do NOT skip for a bare {} context set by processInboundMsg — that's the entry point + // for file-based messaging consumer delivery and should get a root span. + if (this.context instanceof cds.EventContext) return _tx_proto.apply(this, arguments) + const name = `${this.name || 'cds'} - tx` + return trace(name, _tx_proto, this, arguments, {}) + } + }) + const { spawn: _spawn } = cds cds.spawn = wrap(_spawn, { wrapper: function spawn() { diff --git a/test/bookshop/.cdsrc.json b/test/bookshop/.cdsrc.json index 1dc257b9..949db9cd 100644 --- a/test/bookshop/.cdsrc.json +++ b/test/bookshop/.cdsrc.json @@ -82,6 +82,18 @@ } } }, + "[tracing-in-memory]": { + "requires": { + "telemetry": { + "tracing": { + "exporter": { + "module": "./lib/MyInMemorySpanExporter.js", + "class": "MyInMemorySpanExporter" + } + } + } + } + }, "[persistent-outbox]": { "requires": { "messaging": { @@ -90,6 +102,25 @@ } } }, + "[inboxed]": { + "requires": { + "messaging": { + "kind": "file-based-messaging", + "file": "../inboxed", + "inboxed": true + } + } + }, + "[outboxed-and-inboxed]": { + "requires": { + "messaging": { + "kind": "file-based-messaging", + "file": "../outboxed-and-inboxed", + "outboxed": true, + "inboxed": true + } + } + }, "[without-outbox]": { "requires": { "messaging": { diff --git a/test/bookshop/lib/MyInMemorySpanExporter.js b/test/bookshop/lib/MyInMemorySpanExporter.js new file mode 100644 index 00000000..9c7e4bdc --- /dev/null +++ b/test/bookshop/lib/MyInMemorySpanExporter.js @@ -0,0 +1,59 @@ +// In-memory span exporter for tests. Spans are accumulated in a module-level array that +// tests can import directly via `require('./lib/MyInMemorySpanExporter').captured`. +// Wired into the tracer provider via .cdsrc.json profile config (no provider-poking from tests). + +const { ExportResultCode } = require('@opentelemetry/core') + +const captured = [] + +class MyInMemorySpanExporter { + export(spans, resultCallback) { + captured.push(...spans) + resultCallback({ code: ExportResultCode.SUCCESS }) + } + + shutdown() { + return Promise.resolve() + } + + forceFlush() { + return Promise.resolve() + } +} + +// Returns the captured spans grouped by traceId, each group is a hierarchy: +// { traceId, root, all, byParent } +// `root` is the span with no parent inside the group (the visible root for the exporter's +// "elapsed times:" primer logic — i.e. spans whose parentSpanId is not present in this group). +function groupedByTrace() { + const byTrace = new Map() + for (const s of captured) { + const tid = s.spanContext().traceId + if (!byTrace.has(tid)) byTrace.set(tid, []) + byTrace.get(tid).push(s) + } + + return [...byTrace.entries()].map(([traceId, all]) => { + const ids = new Set(all.map(s => s.spanContext().spanId)) + const roots = all.filter(s => !s.parentSpanContext?.spanId || !ids.has(s.parentSpanContext.spanId)) + const byParent = new Map() + for (const s of all) { + const pid = s.parentSpanContext?.spanId + if (!byParent.has(pid)) byParent.set(pid, []) + byParent.get(pid).push(s) + } + return { traceId, root: roots[0], roots, all, byParent } + }) +} + +// Returns just the visible "root" spans across all captured traces. These correspond 1:1 to +// "elapsed times:" primers our ConsoleSpanExporter would emit for the same data. +function rootSpans() { + return groupedByTrace().flatMap(g => g.roots) +} + +function reset() { + captured.length = 0 +} + +module.exports = { MyInMemorySpanExporter, captured, groupedByTrace, rootSpans, reset } diff --git a/test/bookshop/srv/admin-service.cds b/test/bookshop/srv/admin-service.cds index 4ab230d8..3d8838ec 100644 --- a/test/bookshop/srv/admin-service.cds +++ b/test/bookshop/srv/admin-service.cds @@ -7,6 +7,9 @@ service AdminService @(requires: 'admin') { action test_spawn(); action test_emit(); + action test_outboxed_send(); + action test_outboxed_send_batch(); + action test_scheduled(); event foo { bar : String; diff --git a/test/bookshop/srv/admin-service.js b/test/bookshop/srv/admin-service.js index fb1cdf6c..9cb186fe 100644 --- a/test/bookshop/srv/admin-service.js +++ b/test/bookshop/srv/admin-service.js @@ -32,6 +32,30 @@ module.exports = class AdminService extends cds.ApplicationService { await messaging.emit('foo', { bar: 'baz' }) }) + // test_outboxed_send: writes a task to the persistent outbox addressed to ExternalServiceOne, + // whose handler the test installs. Exercises the queue-worker path (scan, lock, dispatch). + this.on('test_outboxed_send', async () => { + const externalOne = await cds.connect.to('ExternalServiceOne') + await cds.queued(externalOne).send('call', {}) + }) + + // test_outboxed_send_batch: writes multiple tasks to the persistent outbox to exercise chunkSize > 1 fan-out. + this.on('test_outboxed_send_batch', async () => { + const externalOne = await cds.connect.to('ExternalServiceOne') + const queued = cds.queued(externalOne) + await Promise.all([ + queued.send('call', {}), + queued.send('call', {}), + queued.send('call', {}) + ]) + }) + + // test_scheduled: schedules a one-shot task to fire after a short delay. + this.on('test_scheduled', async () => { + const externalOne = await cds.connect.to('ExternalServiceOne') + await cds.queued(externalOne).schedule('call', {}).after(10) + }) + return super.init() } } diff --git a/test/console-span-exporter.test.js b/test/console-span-exporter.test.js new file mode 100644 index 00000000..4c83e4e8 --- /dev/null +++ b/test/console-span-exporter.test.js @@ -0,0 +1,243 @@ +// Unit tests for ConsoleSpanExporter — verifies the user-friendly hierarchy formatting +// (the "elapsed times:" primer + indented child lines) by feeding the exporter crafted +// ReadableSpan-shaped fixtures and inspecting the formatted string passed to LOG.info. +// +// This is a pure unit test: no cds.test server, no real OTel SDK, no console spying. + +const cds = require('@sap/cds') + +// Hook LOG.info BEFORE requiring the exporter so the exporter's module-level +// `cds.log('telemetry')` resolves to a logger whose .info we control. +const infoCalls = [] +const telemetryLog = cds.log('telemetry') +const originalInfo = telemetryLog.info +telemetryLog.info = (...args) => infoCalls.push(args) + +const ConsoleSpanExporter = require('../lib/exporter/ConsoleSpanExporter') + +afterAll(() => { + telemetryLog.info = originalInfo +}) + +beforeEach(() => { + infoCalls.length = 0 +}) + +// --- helpers --------------------------------------------------------------- + +// Builds a minimal ReadableSpan-shaped object. Times are in OTel HrTime = [seconds, nanos]. +function span({ name, traceId, spanId, parentSpanId, startMs = 0, durationMs = 0, attributes = {} }) { + const startHr = msToHr(startMs) + const durationHr = msToHr(durationMs) + const endHr = msToHr(startMs + durationMs) + return { + name, + kind: 0, + spanContext: () => ({ traceId, spanId }), + parentSpanContext: parentSpanId ? { traceId, spanId: parentSpanId } : undefined, + startTime: startHr, + endTime: endHr, + duration: durationHr, + status: { code: 0 }, + attributes, + links: [], + events: [], + ended: true, + resource: { attributes: {} }, + instrumentationScope: { name: 'test' }, + droppedAttributesCount: 0, + droppedEventsCount: 0, + droppedLinksCount: 0 + } +} + +function msToHr(ms) { + const seconds = Math.floor(ms / 1000) + const nanos = Math.round((ms - seconds * 1000) * 1e6) + return [seconds, nanos] +} + +// Drives the exporter and returns the lines logged across all root primers. +function exportAndCapture(spans) { + const exporter = new ConsoleSpanExporter() + let result + exporter.export(spans, r => (result = r)) + expect(result).to.deep.equal({ code: 0 /* ExportResultCode.SUCCESS */ }) + return infoCalls.map(args => args[0]) +} + +// --- assertions ------------------------------------------------------------ + +const { expect } = require('@cap-js/cds-test') + +describe('ConsoleSpanExporter', () => { + describe('hierarchy formatting', () => { + it('emits a single "elapsed times:" primer per root and nests children by depth', () => { + // Tree shape: + // root (0 → 10 ms) + // childA (1 → 4 ms) + // grandchild (2 → 3 ms) + // childB (5 → 9 ms) + const TRACE = 'a'.repeat(32) + const root = span({ name: 'root', traceId: TRACE, spanId: 'r0', startMs: 0, durationMs: 10 }) + const childA = span({ name: 'childA', traceId: TRACE, spanId: 'cA', parentSpanId: 'r0', startMs: 1, durationMs: 3 }) + const grand = span({ name: 'grandchild', traceId: TRACE, spanId: 'g0', parentSpanId: 'cA', startMs: 2, durationMs: 1 }) + const childB = span({ name: 'childB', traceId: TRACE, spanId: 'cB', parentSpanId: 'r0', startMs: 5, durationMs: 4 }) + + // Order matters: children must arrive BEFORE the root for the exporter's + // temporaryStorage flush logic to merge them under the same primer. + const [primer] = exportAndCapture([childA, grand, childB, root]) + + // Single primer + expect(infoCalls.length).to.equal(1) + expect(primer).to.match(/^elapsed times:/) + + // Root line: 0.00 → 10.00 = 10.00 ms root (no indent on the root data line) + expect(primer).to.match(/\n +0\.00 → +10\.00 = +10\.00 ms {2}root/) + + // First-level children indented by 2 spaces beyond root + expect(primer).to.match(/\n.+ ms {4}childA/) + expect(primer).to.match(/\n.+ ms {4}childB/) + + // Grandchild indented by 4 spaces beyond root + expect(primer).to.match(/\n.+ ms {6}grandchild/) + + // Ordering: childA appears before grandchild appears before childB + expect(primer.indexOf('childA')).to.be.lessThan(primer.indexOf('grandchild')) + expect(primer.indexOf('grandchild')).to.be.lessThan(primer.indexOf('childB')) + }) + + it('relativizes child start/end to the root start time', () => { + // Root starts at 100 ms wallclock; child at 105 ms. Child should display as 5.00 → ... + const TRACE = 'b'.repeat(32) + const root = span({ name: 'root', traceId: TRACE, spanId: 'r0', startMs: 100, durationMs: 20 }) + const child = span({ name: 'child', traceId: TRACE, spanId: 'c0', parentSpanId: 'r0', startMs: 105, durationMs: 10 }) + + const [primer] = exportAndCapture([child, root]) + + expect(primer).to.match(/0\.00 → +20\.00 = +20\.00 ms {2}root/) + expect(primer).to.match(/5\.00 → +15\.00 = +10\.00 ms {4}child/) + }) + + it('sorts sibling spans by start time, ties broken by later end-time first', () => { + const TRACE = 'c'.repeat(32) + const root = span({ name: 'root', traceId: TRACE, spanId: 'r0', startMs: 0, durationMs: 50 }) + const late = span({ name: 'late', traceId: TRACE, spanId: 's3', parentSpanId: 'r0', startMs: 10, durationMs: 1 }) + const earlyLong = span({ name: 'earlyLong', traceId: TRACE, spanId: 's1', parentSpanId: 'r0', startMs: 0, durationMs: 30 }) + const earlyShort = span({ name: 'earlyShort', traceId: TRACE, spanId: 's2', parentSpanId: 'r0', startMs: 0, durationMs: 5 }) + + const [primer] = exportAndCapture([late, earlyShort, earlyLong, root]) + + // Equal start time → longer span first; otherwise by start time ascending + const order = ['earlyLong', 'earlyShort', 'late'].map(n => primer.indexOf(n)) + expect(order[0]).to.be.lessThan(order[1]) + expect(order[1]).to.be.lessThan(order[2]) + }) + + it('emits a separate primer per trace (multi-root)', () => { + const T1 = 'd'.repeat(32), + T2 = 'e'.repeat(32) + const r1 = span({ name: 'root1', traceId: T1, spanId: 'r1', startMs: 0, durationMs: 5 }) + const c1 = span({ name: 'c1', traceId: T1, spanId: 'c1', parentSpanId: 'r1', startMs: 1, durationMs: 2 }) + const r2 = span({ name: 'root2', traceId: T2, spanId: 'r2', startMs: 0, durationMs: 7 }) + const c2 = span({ name: 'c2', traceId: T2, spanId: 'c2', parentSpanId: 'r2', startMs: 1, durationMs: 3 }) + + exportAndCapture([c1, c2, r1, r2]) + + expect(infoCalls.length).to.equal(2) + const all = infoCalls.map(c => c[0]) + expect(all[0]).to.include('root1').and.to.include('c1').and.not.to.include('root2') + expect(all[1]).to.include('root2').and.to.include('c2').and.not.to.include('root1') + }) + + it('skips short "METHOD /word" spans (e.g. unadjusted http instrumentation roots)', () => { + const TRACE = 'f'.repeat(32) + const root = span({ name: 'root', traceId: TRACE, spanId: 'r0', startMs: 0, durationMs: 10 }) + // The skip regex is /^[A-Z]+ \/\${0,1}\w+$/ — single path segment, no slashes after the first. + const noisy = span({ name: 'GET /catalog', traceId: TRACE, spanId: 'h0', parentSpanId: 'r0', startMs: 1, durationMs: 5 }) + + const [primer] = exportAndCapture([noisy, root]) + + expect(primer).to.include('root') + expect(primer).not.to.include('GET /catalog') + }) + + it('handles deep nesting with increasing indentation', () => { + const TRACE = '1'.repeat(32) + const root = span({ name: 'L0', traceId: TRACE, spanId: 'L0', startMs: 0, durationMs: 10 }) + const l1 = span({ name: 'L1', traceId: TRACE, spanId: 'L1', parentSpanId: 'L0', startMs: 1, durationMs: 8 }) + const l2 = span({ name: 'L2', traceId: TRACE, spanId: 'L2', parentSpanId: 'L1', startMs: 2, durationMs: 6 }) + const l3 = span({ name: 'L3', traceId: TRACE, spanId: 'L3', parentSpanId: 'L2', startMs: 3, durationMs: 4 }) + + const [primer] = exportAndCapture([l1, l2, l3, root]) + + // Each deeper level adds 2 spaces of indentation + const indents = ['L0', 'L1', 'L2', 'L3'].map(n => { + const m = primer.match(new RegExp(`\\n( +)\\d.*ms( +)${n}(?!\\d)`)) + return m ? m[2].length - 1 : null // exclude the single space separator after "ms " + }) + // L0: 1 leading space before the name; each child adds 2. So we expect 1, 3, 5, 7. + expect(indents).to.deep.equal([1, 3, 5, 7]) + }) + }) + + describe('time formatting', () => { + it('formats sub-millisecond durations with two decimals', () => { + const TRACE = '2'.repeat(32) + const root = span({ name: 'root', traceId: TRACE, spanId: 'r0', startMs: 0, durationMs: 0.5 }) + const [primer] = exportAndCapture([root]) + expect(primer).to.match(/0\.00 → +0\.50 = +0\.50 ms/) + }) + + it('right-aligns integer portion to 3 chars', () => { + const TRACE = '3'.repeat(32) + const root = span({ name: 'root', traceId: TRACE, spanId: 'r0', startMs: 0, durationMs: 123 }) + const [primer] = exportAndCapture([root]) + // "123.00" → matches as-is, fits in the 3-char integer slot + expect(primer).to.match(/0\.00 → +123\.00 = +123\.00 ms/) + }) + }) + + describe('span name handling', () => { + it('truncates names longer than 80 chars with an ellipsis', () => { + const TRACE = '4'.repeat(32) + const longName = 'X'.repeat(100) + const root = span({ name: longName, traceId: TRACE, spanId: 'r0', startMs: 0, durationMs: 1 }) + + const [primer] = exportAndCapture([root]) + + expect(primer).to.include('X'.repeat(79) + '…') + expect(primer).not.to.include('X'.repeat(80)) + }) + }) + + describe('robustness', () => { + it('does not throw when a child arrives without its parent (orphan trace)', () => { + // No root provided for this trace — the exporter should buffer the child and not flush. + const TRACE = '5'.repeat(32) + const orphan = span({ name: 'orphan', traceId: TRACE, spanId: 'o0', parentSpanId: 'r-missing', startMs: 0, durationMs: 1 }) + + expect(() => exportAndCapture([orphan])).not.to.throw() + expect(infoCalls.length).to.equal(0) + }) + + it('treats any span without a parent as a root and emits a primer', () => { + const TRACE = '6'.repeat(32) + const lonely = span({ name: 'lonely', traceId: TRACE, spanId: 'r0', startMs: 0, durationMs: 2 }) + + const [primer] = exportAndCapture([lonely]) + + expect(primer).to.match(/^elapsed times:/) + expect(primer).to.include('lonely') + }) + + it('shutdown flushes pending buffered children without throwing', () => { + const exporter = new ConsoleSpanExporter() + // No-op: just verify the shutdown contract. + return exporter.shutdown().then(() => { + // No exception, no logged primers (nothing was buffered). + expect(infoCalls.length).to.equal(0) + }) + }) + }) +}) diff --git a/test/tracing-attributes.test.js b/test/tracing-attributes.test.js index ac52e303..03204b13 100644 --- a/test/tracing-attributes.test.js +++ b/test/tracing-attributes.test.js @@ -2,15 +2,25 @@ process.env.cds_remote_native__fetch = 'true' const cds = require('@sap/cds') -const { expect, data } = cds.test(__dirname + '/bookshop', '--profile', 'tracing-attributes') +const { expect, data } = cds.test(__dirname + '/bookshop', '--profile', 'tracing-in-memory') const http = require('http') -describe('tracing attributes', () => { - beforeEach(data.reset) +// The tracing-in-memory profile (see test/bookshop/.cdsrc.json) configures +// MyInMemorySpanExporter as the trace exporter. We read the captured ReadableSpan +// objects directly out of its shared buffer — no console spy, no provider-poking. +const { captured } = require('./bookshop/lib/MyInMemorySpanExporter') + +beforeEach(async () => { + // data.reset is itself heavily traced (it runs DELETEs + INSERTs for the seed data) — + // run it first, THEN clear the buffer so the test only sees its own spans. + await data.reset() + captured.length = 0 +}) - const log = jest.spyOn(console, 'dir') - beforeEach(log.mockClear) +// Returns all finished spans, optionally filtered by a predicate. +const spans = filter => (filter ? captured.filter(filter) : captured.slice()) +describe('tracing attributes', () => { describe('remote', () => { let server, port @@ -30,6 +40,9 @@ describe('tracing attributes', () => { }) test('HTTP client attributes are set on remote service span', async () => { + // skip for cds 8 due to Cloud SDK resilience module resolution issues in test environment + if (Number(cds.version.split('.')[0]) < 9) return + // configure destination URL directly on credentials cds.env.requires.TestRemote = { kind: 'odata', credentials: { url: `http://localhost:${port}` } } const remote = await cds.connect.to('TestRemote') @@ -37,54 +50,62 @@ describe('tracing attributes', () => { // no mock handler - let it make the actual HTTP call await remote.send({ method: 'GET', path: '/test' }) - const output = JSON.stringify(log.mock.calls) - expect(output).to.match(/"http\.request\.method":"GET"/) - expect(output).to.match(/"http\.response\.status_code":200/) - expect(output).to.match(new RegExp(`"url\\.full":"http://localhost:${port}/test"`)) - expect(output).to.match(/"server\.address":"localhost"/) - expect(output).to.match(new RegExp(`"server\\.port":${port}`)) + // Find the HTTP client span (instrumented by OTel's http instrumentation) + const httpSpan = spans(s => s.attributes['http.request.method'] === 'GET' && s.attributes['url.full']) + expect(httpSpan.length).to.be.gte(1, 'expected an HTTP client span') + const attrs = httpSpan[0].attributes + expect(attrs).to.include({ + 'http.request.method': 'GET', + 'http.response.status_code': 200, + 'url.full': `http://localhost:${port}/test`, + 'server.address': 'localhost', + 'server.port': port + }) }) }) describe('db', () => { const _db_spans = require('./_db_spans') - // prettier-ignore - const _get_db_spans = o => JSON.parse(o).map(o => o[0]).filter(s => !s.name.startsWith('db')) - const _match_db_spans = (output, kind) => { - const db_spans = _get_db_spans(output) - for (const each of _db_spans[kind]) expect(db_spans).to.containSubset([each]) + + // Filter out the high-level "db - …" CAP wrapper spans, keep only the @cap-js/ ones + // that carry the actual DB attributes. + const dbSpans = () => spans(s => !s.name.startsWith('db')) + + const _match_db_spans = kind => { + const got = dbSpans().map(s => ({ name: s.name, attributes: { ...s.attributes } })) + for (const each of _db_spans[kind]) expect(got).to.containSubset([each]) } test('SELECT', async () => { await SELECT.from('sap.capire.bookshop.Books').where('title !=', 'DUMMY') - const output = JSON.stringify(log.mock.calls) - expect(output).to.match(/db\.client\.response.returned_rows":5/) - _match_db_spans(output, 'SELECT') + const rowCounts = dbSpans().map(s => s.attributes['db.client.response.returned_rows']).filter(v => v != null) + expect(rowCounts).to.include(5) + _match_db_spans('SELECT') }) test('INSERT', async () => { await INSERT.into('sap.capire.bookshop.Books').entries([{ ID: 1 }, { ID: 2 }]) - const output = JSON.stringify(log.mock.calls) - expect(output).to.match(/db\.client\.response.returned_rows":2/) + const rowCounts = dbSpans().map(s => s.attributes['db.client.response.returned_rows']).filter(v => v != null) + expect(rowCounts).to.include(2) // TODO - // _match_db_spans(output, 'INSERT') + // _match_db_spans('INSERT') }) test('UPDATE', async () => { await UPDATE('sap.capire.bookshop.Books').set({ stock: 42 }).where('ID > 250') - const output = JSON.stringify(log.mock.calls) - expect(output).to.match(/db\.client\.response.returned_rows":3/) + const rowCounts = dbSpans().map(s => s.attributes['db.client.response.returned_rows']).filter(v => v != null) + expect(rowCounts).to.include(3) // TODO - // _match_db_spans(output, 'UPDATE') + // _match_db_spans('UPDATE') }) test('DELETE', async () => { await DELETE.from('sap.capire.bookshop.Books') - const output = JSON.stringify(log.mock.calls) - expect(output).to.match(/db\.client\.response.returned_rows":0/) //> texts - expect(output).to.match(/db\.client\.response.returned_rows":5/) + const rowCounts = dbSpans().map(s => s.attributes['db.client.response.returned_rows']).filter(v => v != null) + expect(rowCounts).to.include(0) // texts + expect(rowCounts).to.include(5) // TODO - // _match_db_spans(output, 'DELETE') + // _match_db_spans('DELETE') }) }) }) diff --git a/test/tracing-messaging-inboxed.test.js b/test/tracing-messaging-inboxed.test.js new file mode 100644 index 00000000..0845909f --- /dev/null +++ b/test/tracing-messaging-inboxed.test.js @@ -0,0 +1,59 @@ +const CASE = 'inboxed' + +// `inboxed: true` combined with the default outboxed messaging behavior means TWO queue +// workers get involved per emit — one on the producer side (drains outbox to broker) and +// one on the consumer side (drains inbox to subscribers). Each worker runs two +// transactions (tx 1: lock; tx 2: handle + delete). +// +// Each worker iteration is wrapped by `cds.spawn`, so both txs collapse under a single +// `cds.spawn - run task` root. 4 meaningful roots: +// +// 1. AdminService - tx (producer: handle test_emit, UPSERT outbox) +// 2. cds.spawn - run task (outbox worker: dispatches to file) +// ├─ db - tx (tx 1: lock) +// └─ messaging - tx (tx 2: handle foo — writes to file — + DELETE) +// 3. messaging - tx (file-based CONSUMER: writes inbox row) +// └─ ...enqueue into inbox... +// 4. cds.spawn - run task (inbox worker: runs subscriber) +// ├─ db - tx (tx 1: lock) +// └─ messaging - tx (tx 2: handle foo — SELECT Books — + DELETE) +// +// Tolerated: allow one extra root for the scheduling-service bookkeeping startup scan. + +// REVISIT: profile config wins for kind/file, but explicit env override sidesteps it. +process.env.cds_requires_messaging = JSON.stringify({ + kind: 'file-based-messaging', + file: `../${CASE}`, + inboxed: true +}) + +const CHECK = ({ expect, rootSpans, groupedByTrace }) => { + // Producer trace + const producer = groupedByTrace.find(g => g.all.some(s => s.name === 'AdminService - handle test_emit')) + expect(producer, 'expected a producer trace').to.exist + expect(producer.root.name).to.equal('AdminService - tx') + expect(producer.all.some(s => s.name === 'db - UPSERT cds.outbox.Messages')).to.be.true + + // The inbox worker must have run the application handler (SELECT Books). + const allSpans = groupedByTrace.flatMap(g => g.all) + expect(allSpans.some(s => s.name.match(/READ sap\.capire\.bookshop\.Books/))).to.be.true + expect(allSpans.some(s => s.name === 'db - DELETE cds.outbox.Messages')).to.be.true + + // Exactly two `cds.spawn - run task` roots (outbox worker + inbox worker). + const workerRoots = rootSpans.filter(s => s.name === 'cds.spawn - run task') + expect(workerRoots, 'expected two queue-worker spawn roots (outbox + inbox)').to.have.lengthOf(2) + + // One of the spawn roots (the inbox worker) ran the app handler. + const inboxWorker = groupedByTrace.find( + g => g.root.name === 'cds.spawn - run task' && g.all.some(s => s.name.match(/READ sap\.capire\.bookshop\.Books/)) + ) + expect(inboxWorker, 'expected an inbox-worker trace that ran the application handler').to.exist + + // 4 meaningful roots (+1 tolerated bookkeeping scan). + expect(rootSpans.length).to.be.gte(4) + expect(rootSpans.length).to.be.lte(5) +} + +describe(`tracing messaging - ${CASE}`, () => { + require('./tracing-messaging')(CASE, CHECK, { waitMs: 4000 }) +}) diff --git a/test/tracing-messaging-outboxed-and-inboxed.test.js b/test/tracing-messaging-outboxed-and-inboxed.test.js new file mode 100644 index 00000000..0a60d6d7 --- /dev/null +++ b/test/tracing-messaging-outboxed-and-inboxed.test.js @@ -0,0 +1,55 @@ +const CASE = 'outboxed-and-inboxed' + +// Explicit `outboxed: true` + `inboxed: true`. Same lifecycle as the `inboxed` test — two +// queue workers, each running tx-1 (lock) and tx-2 (handle + delete). Setting outboxed +// explicitly is a no-op relative to the messaging default, so the observed shape matches +// the `inboxed` test: +// +// 1. AdminService - tx (producer) +// 2. cds.spawn - run task (outbox worker: dispatches to file) +// ├─ db - tx (tx 1) +// └─ messaging - tx (tx 2: handle foo — writes to file — + DELETE) +// 3. messaging - tx (file-based CONSUMER: writes inbox row) +// └─ ...enqueue into inbox... +// 4. cds.spawn - run task (inbox worker: runs subscriber) +// ├─ db - tx (tx 1) +// └─ messaging - tx (tx 2: handle foo — full app work — + DELETE) +// +// 4 meaningful roots (+1 tolerated bookkeeping scan). + +process.env.cds_requires_messaging = JSON.stringify({ + kind: 'file-based-messaging', + file: `../${CASE}`, + outboxed: true, + inboxed: true +}) + +const CHECK = ({ expect, rootSpans, groupedByTrace }) => { + // Producer trace + const producer = groupedByTrace.find(g => g.all.some(s => s.name === 'AdminService - handle test_emit')) + expect(producer, 'expected a producer trace').to.exist + expect(producer.root.name).to.equal('AdminService - tx') + expect(producer.all.some(s => s.name === 'db - UPSERT cds.outbox.Messages')).to.be.true + + const allSpans = groupedByTrace.flatMap(g => g.all) + expect(allSpans.some(s => s.name.match(/READ sap\.capire\.bookshop\.Books/))).to.be.true + expect(allSpans.some(s => s.name === 'db - DELETE cds.outbox.Messages')).to.be.true + + // Exactly two `cds.spawn - run task` roots (outbox + inbox workers). + const workerRoots = rootSpans.filter(s => s.name === 'cds.spawn - run task') + expect(workerRoots, 'expected two queue-worker spawn roots (outbox + inbox)').to.have.lengthOf(2) + + // The inbox worker ran the app handler. + const inboxWorker = groupedByTrace.find( + g => g.root.name === 'cds.spawn - run task' && g.all.some(s => s.name.match(/READ sap\.capire\.bookshop\.Books/)) + ) + expect(inboxWorker, 'expected an inbox-worker trace that ran the application handler').to.exist + + // 4 meaningful roots (+1 tolerated bookkeeping scan). + expect(rootSpans.length).to.be.gte(4) + expect(rootSpans.length).to.be.lte(5) +} + +describe(`tracing messaging - ${CASE}`, () => { + require('./tracing-messaging')(CASE, CHECK, { waitMs: 4000 }) +}) diff --git a/test/tracing-messaging-persistent-outbox.test.js b/test/tracing-messaging-persistent-outbox.test.js index 1d959595..d4d83d7b 100644 --- a/test/tracing-messaging-persistent-outbox.test.js +++ b/test/tracing-messaging-persistent-outbox.test.js @@ -6,15 +6,94 @@ process.env.cds_requires_messaging = JSON.stringify({ file: `../${CASE}` }) -// REVISIT: check json exports -const CHECK = (log, expect) => { - // 3: outbox -> consumers get new root context - // REVISIT: for some reason, span "cds.spawn run task" has no parent when running in jest - expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(4) //> actually 3 - expect(log.output.match(/cds.spawn - schedule task/g).length).to.equal(1) +// --- Span hierarchy for the persistent-outbox case --------------------------------------- +// +// With persistent outbox enabled, the queue worker runs two coherent transactions: +// - tx 1: read out of queue + set status='processing' (libx/queue/processing.js:189) +// - tx 2: handle the event + delete the row (libx/queue/processing.js:319) +// +// `@cap-js/telemetry` wraps `cds.tx(fn)` to emit a ` - tx` span per callback, so +// each of these transactions is captured as a root/child span. Both sqlite and HANA now +// produce the same unified shape: the worker uses `cds.spawn`, which the telemetry plugin +// wraps to emit a single `cds.spawn - run task` CONSUMER root that both worker tx spans +// nest under. +// +// Expected shape (3 meaningful roots, same for sqlite and HANA): +// +// 1. AdminService - tx (producer trace) +// └─ AdminService - handle test_emit +// └─ messaging - emit outgoing foo +// └─ db - UPSERT cds.outbox.Messages +// └─ cds.spawn - schedule task +// +// 2. cds.spawn - run task (queue worker root) +// ├─ db - tx (tx 1) +// │ ├─ db - READ cds.outbox.Messages +// │ └─ db - UPDATE cds.outbox.Messages +// └─ messaging - tx (tx 2) +// ├─ messaging - handle foo +// └─ db - DELETE cds.outbox.Messages +// +// 3. messaging - tx (file-based CONSUMER) +// └─ ...handler work (READ Books, READ Authors)... +// +// Plus the scheduling service may emit a bookkeeping `db - tx` (startup scan finding no +// tasks) — tolerated as a 4th root, not required. + +const CHECK = ({ expect, rootSpans, groupedByTrace }) => { + // Producer trace + const producer = groupedByTrace.find(g => g.all.some(s => s.name === 'AdminService - handle test_emit')) + expect(producer, 'expected a producer trace').to.exist + expect(producer.root.name).to.equal('AdminService - tx') + expect(producer.all.some(s => s.name === 'messaging - emit outgoing foo')).to.be.true + expect(producer.all.some(s => s.name === 'db - UPSERT cds.outbox.Messages')).to.be.true + expect(producer.all.some(s => s.name === 'cds.spawn - schedule task')).to.be.true + + // Queue worker trace: rooted at `cds.spawn - run task`, containing both tx spans as children. + const workerTrace = groupedByTrace.find(g => g.root.name === 'cds.spawn - run task') + expect(workerTrace, 'expected a queue-worker spawn-root trace').to.exist + + // tx 1: db - tx with READ + UPDATE of the outbox + const workerDbTx = workerTrace.all.find(s => s.name === 'db - tx') + expect(workerDbTx, 'expected a db - tx child in the worker trace (tx 1)').to.exist + expect(workerTrace.all.some(s => s.name === 'db - READ cds.outbox.Messages')).to.be.true + expect(workerTrace.all.some(s => s.name === 'db - UPDATE cds.outbox.Messages')).to.be.true + + // tx 2: messaging - tx with handle foo + DELETE of the outbox row + const workerMessagingTx = workerTrace.all.find(s => s.name === 'messaging - tx') + expect(workerMessagingTx, 'expected a messaging - tx child in the worker trace (tx 2)').to.exist + expect(workerTrace.all.some(s => s.name === 'messaging - handle foo')).to.be.true + expect(workerTrace.all.some(s => s.name === 'db - DELETE cds.outbox.Messages')).to.be.true + + // File-based CONSUMER trace (the file-messaging consumer, *not* the queue-worker path). + // Identified by containing the full `foo` handler work (SELECT Books + READ Authors). + const consumer = groupedByTrace.find( + g => + g !== producer && + g !== workerTrace && + g.root.name === 'messaging - tx' && + g.all.some(s => s.name.match(/READ sap\.capire\.bookshop\.Books/)) && + g.all.some(s => s.name === 'AdminService - READ AdminService.Authors') + ) + expect(consumer, 'expected a CONSUMER trace').to.exist + expect(consumer.all.some(s => s.name === 'messaging - emit outgoing foo')).to.be.true + expect(consumer.all.some(s => s.name === 'messaging - handle foo')).to.be.true + + // 3 meaningful roots; tolerate one extra for the scheduling-service bookkeeping scan + // (a `db - tx` root with just a READ, no UPDATE). + expect(rootSpans.length).to.be.gte(3) + expect(rootSpans.length).to.be.lte(4) + + // Sanity: every non-root span has a parent inside the captured set. + const allSpans = groupedByTrace.flatMap(g => g.all) + for (const s of allSpans) { + const pid = s.parentSpanContext?.spanId + if (!pid) continue + const parent = allSpans.find(p => p.spanContext().spanId === pid) + expect(parent, `expected parent span for ${s.name}`).to.exist + } } -// REVISIT: re-enable with switch to vitest -describe.skip(`tracing messaging - ${CASE}`, () => { - require('./tracing-messaging')(CASE, CHECK) +describe(`tracing messaging - ${CASE}`, () => { + require('./tracing-messaging')(CASE, CHECK, { waitMs: 4000 }) }) diff --git a/test/tracing-messaging-without-outbox.test.js b/test/tracing-messaging-without-outbox.test.js index f93664c1..81138218 100644 --- a/test/tracing-messaging-without-outbox.test.js +++ b/test/tracing-messaging-without-outbox.test.js @@ -7,10 +7,41 @@ process.env.cds_requires_messaging = JSON.stringify({ outboxed: false }) -// REVISIT: check json exports -const CHECK = (log, expect) => { - // 2: no outbox -> consumer gets new root context - expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(2) +// Without outbox, file-based messaging writes directly to the file from the producer's +// transaction (no queue worker). The file watcher delivers asynchronously as a new +// SpanKind.CONSUMER root. +// +// Expected roots: +// 1. AdminService - tx (producer) +// └─ AdminService - handle test_emit +// └─ messaging - emit outgoing foo +// └─ messaging - handle foo (writes to file, in-process) +// +// 2. messaging - tx (file-based CONSUMER) +// └─ messaging - emit outgoing foo +// └─ messaging - handle foo +// └─ ...handler work... +// +// The scheduling service may also emit a bookkeeping scan trace (`db - tx → db - READ +// cds.outbox.Messages` finding nothing) — we allow it but don't require it. + +const CHECK = ({ expect, rootSpans, groupedByTrace }) => { + // Producer trace + const producer = groupedByTrace.find(g => g.all.some(s => s.name === 'AdminService - handle test_emit')) + expect(producer, 'expected a producer trace').to.exist + expect(producer.root.name).to.equal('AdminService - tx') + expect(producer.all.some(s => s.name.match(/messaging - emit outgoing/))).to.be.true + + // File-based CONSUMER trace + const consumer = groupedByTrace.find( + g => g !== producer && g.root.name === 'messaging - tx' && g.all.some(s => s.name === 'messaging - handle foo') + ) + expect(consumer, 'expected a CONSUMER trace').to.exist + expect(consumer.all.some(s => s.name.match(/READ sap\.capire\.bookshop\.Books/))).to.be.true + + // 2 meaningful roots; allow up to 3 to tolerate the scheduling service's bookkeeping scan. + expect(rootSpans.length).to.be.gte(2) + expect(rootSpans.length).to.be.lte(3) } describe(`tracing messaging - ${CASE}`, () => { diff --git a/test/tracing-messaging.js b/test/tracing-messaging.js index 35508745..15202e34 100644 --- a/test/tracing-messaging.js +++ b/test/tracing-messaging.js @@ -1,7 +1,7 @@ -module.exports = (CASE, CHECK) => { +module.exports = (CASE, CHECK, { waitMs = 4000 } = {}) => { const cds = require('@sap/cds') - const { expect, POST } = cds.test(__dirname + '/bookshop', '--profile', CASE) - const log = cds.test.log() + const { expect, POST } = cds.test(__dirname + '/bookshop', '--profile', `${CASE},tracing-in-memory`) + const { reset, rootSpans, groupedByTrace, captured } = require('./bookshop/lib/MyInMemorySpanExporter') const wait = require('node:timers/promises').setTimeout @@ -21,16 +21,22 @@ module.exports = (CASE, CHECK) => { }) afterAll(async () => { - await wait(100) + // Wait long enough for any background queue-worker / scheduling-service timers to + // fire one last time before jest tears down the env. Without this, those timers can + // fire after teardown and crash with "cds.error.isSystemError is not a function" + // (cds module is reloaded between tests, but the timer references the old instance). + await wait(2000) rm() }) - beforeEach(log.clear) + beforeEach(() => { + reset() + }) test('emit is traced', async () => { await POST('/odata/v4/admin/test_emit', {}, admin) - await wait(1000) - // execute case specific check - CHECK(log, expect) + await wait(waitMs) + // CHECK is called with span-level data: { expect, rootSpans, groupedByTrace, captured, cds } + CHECK({ expect, rootSpans: rootSpans(), groupedByTrace: groupedByTrace(), captured: [...captured], cds }) }) } diff --git a/test/tracing-mt.test.js b/test/tracing-mt.test.js index f6f3c36a..8b6855fa 100644 --- a/test/tracing-mt.test.js +++ b/test/tracing-mt.test.js @@ -1,7 +1,8 @@ const cds = require('@sap/cds') // prettier-ignore -const { expect, GET } = cds.test('serve', '--in-memory', '--project', __dirname + '/bookshop', '--profile', 'multitenancy') -const log = cds.test.log() +const { expect, GET } = cds.test('serve', '--in-memory', '--project', __dirname + '/bookshop', '--profile', 'multitenancy,tracing-in-memory') + +const { reset, captured } = require('./bookshop/lib/MyInMemorySpanExporter') describe('tracing with multitenancy', () => { const TENANT1 = 'tenant_1' @@ -17,22 +18,23 @@ describe('tracing with multitenancy', () => { await mts.subscribe(TENANT2) }) - beforeEach(log.clear) + beforeEach(reset) test('GET with user1 is traced', async () => { const { status } = await GET('/odata/v4/admin/Books', user1) expect(status).to.equal(200) - // primitive check that console has trace logs - expect(log.output).to.match(/\[telemetry|tenant_1\] - elapsed times:/) - expect(log.output).to.match(/\s+\d+\.\d+ → \s*\d+\.\d+ = \s*\d+\.\d+ ms \s* AdminService - READ AdminService.Books/) + // AdminService READ ran and was tagged with the right tenant. + const span = captured.find(s => s.name === 'AdminService - READ AdminService.Books') + expect(span, 'expected AdminService READ span').to.exist + expect(span.attributes['sap.tenancy.tenant_id']).to.equal(TENANT1) }) test('GET with user2 is traced', async () => { const { status } = await GET('/odata/v4/admin/Books', user2) expect(status).to.equal(200) - // primitive check that console has trace logs - expect(log.output).to.match(/\[telemetry|tenant_2\] - elapsed times:/) - expect(log.output).to.match(/\s+\d+\.\d+ → \s*\d+\.\d+ = \s*\d+\.\d+ ms \s* AdminService - READ AdminService.Books/) + const span = captured.find(s => s.name === 'AdminService - READ AdminService.Books') + expect(span, 'expected AdminService READ span').to.exist + expect(span.attributes['sap.tenancy.tenant_id']).to.equal(TENANT2) }) // --- TODO --- diff --git a/test/tracing-outboxed-batch.test.js b/test/tracing-outboxed-batch.test.js new file mode 100644 index 00000000..baf417d0 --- /dev/null +++ b/test/tracing-outboxed-batch.test.js @@ -0,0 +1,68 @@ +// Tests that when the queue worker picks up multiple ready tasks in one iteration +// (chunkSize > 1), each is dispatched in its own tx span under the SAME worker root. +// This validates the parallel-fan-out shape described in the design notes. + +const cds = require('@sap/cds') +const { expect, POST } = cds.test(__dirname + '/bookshop', '--with-mocks', '--profile', 'tracing-in-memory') +const { reset, captured, groupedByTrace } = require('./bookshop/lib/MyInMemorySpanExporter') + +const wait = require('node:timers/promises').setTimeout + +describe('tracing for outboxed batch (chunk-size fan-out)', () => { + if (cds.version.split('.')[0] < 9) { + test.skip('skipping for cds < 9', () => {}) + return + } + + beforeAll(async () => { + const externalOne = await cds.connect.to('ExternalServiceOne') + externalOne.on('call', () => 'ok') + }) + + beforeEach(reset) + + test('three queued sends produce parallel dispatch spans under one worker root', async () => { + await POST('/odata/v4/admin/test_outboxed_send_batch', {}, { auth: { username: 'alice' } }) + await wait(2500) + + // Producer wrote three rows to the outbox. + const upserts = captured.filter(s => s.name === 'db - UPSERT cds.outbox.Messages') + expect(upserts.length, 'expected three producer outbox UPSERTs').to.be.gte(3) + + // Look for a queue worker root containing multiple dispatch tx spans. + const workerTrace = groupedByTrace().find(g => + g.root.name === 'cds.spawn - run task' && + g.all.filter(s => s.name === 'ExternalServiceOne - tx').length >= 2 + ) + expect(workerTrace, 'expected a worker trace with multiple ExternalServiceOne - tx children').to.exist + + // The worker root must have exactly one lock tx (db - tx with READ + UPDATE)… + const lockTxs = workerTrace.all.filter(s => + s.name === 'db - tx' && + workerTrace.all.some(c => c.parentSpanContext?.spanId === s.spanContext().spanId && c.name === 'db - READ cds.outbox.Messages') + ) + expect(lockTxs, 'expected one lock tx (db - tx with READ + UPDATE)').to.have.lengthOf(1) + + // …and multiple dispatch txs, each containing an ExternalServiceOne handle span + DELETE. + const dispatchTxs = workerTrace.all.filter(s => s.name === 'ExternalServiceOne - tx') + expect(dispatchTxs.length, 'expected multiple dispatch txs (chunk-size fan-out)').to.be.gte(2) + for (const tx of dispatchTxs) { + const kids = workerTrace.all.filter(k => k.parentSpanContext?.spanId === tx.spanContext().spanId) + expect(kids.some(k => k.name.match(/ExternalServiceOne - handle/)), 'dispatch tx should contain handle call').to.be.true + expect(kids.some(k => k.name === 'db - DELETE cds.outbox.Messages'), 'dispatch tx should contain DELETE').to.be.true + } + + // The dispatch txs should overlap in time (parallel), not be strictly sequential. + if (dispatchTxs.length >= 2) { + const sorted = [...dispatchTxs].sort((a, b) => + require('@opentelemetry/core').hrTimeToNanoseconds(a.startTime) - + require('@opentelemetry/core').hrTimeToNanoseconds(b.startTime) + ) + const { hrTimeToNanoseconds } = require('@opentelemetry/core') + const firstEndNs = hrTimeToNanoseconds(sorted[0].endTime) + const secondStartNs = hrTimeToNanoseconds(sorted[1].startTime) + // Parallel: second starts before first ends (allow a tiny slack). + expect(secondStartNs, 'expected parallel dispatch: task2 starts before task1 ends').to.be.lessThan(firstEndNs) + } + }) +}) diff --git a/test/tracing-scheduled.test.js b/test/tracing-scheduled.test.js new file mode 100644 index 00000000..29250522 --- /dev/null +++ b/test/tracing-scheduled.test.js @@ -0,0 +1,65 @@ +// Tests tracing of scheduled tasks. +// +// `cds.queued(svc).schedule('event', ...).after(N)` writes a task row to the persistent +// outbox with a timestamp N ms in the future. The queue scheduler picks it up at that +// time and dispatches to the target service's handler. +// +// Expected meaningful roots (unified across sqlite and HANA): +// +// 1. AdminService - tx (producer trace) +// └─ AdminService - handle test_scheduled +// └─ db - UPSERT cds.outbox.Messages +// └─ cds.spawn - schedule task +// +// 2. cds.spawn - run task (queue worker root) +// ├─ db - tx (tx 1: lock) +// └─ ExternalServiceOne - tx (tx 2: dispatch) +// +// Plus optionally one bookkeeping startup-scan trace (tolerated, not required). +// Total meaningful roots: between 2 and 3. + +const cds = require('@sap/cds') +const { expect, POST } = cds.test(__dirname + '/bookshop', '--with-mocks', '--profile', 'tracing-in-memory') +const { reset, captured, groupedByTrace, rootSpans } = require('./bookshop/lib/MyInMemorySpanExporter') + +const wait = require('node:timers/promises').setTimeout + +describe('tracing for scheduled tasks', () => { + if (cds.version.split('.')[0] < 9) { + test.skip('skipping for cds < 9', () => {}) + return + } + + beforeAll(async () => { + const externalOne = await cds.connect.to('ExternalServiceOne') + externalOne.on('call', () => 'ok') + }) + + beforeEach(reset) + + test('schedule .after() is fully traced through the queue worker', async () => { + await POST('/odata/v4/admin/test_scheduled', {}, { auth: { username: 'alice' } }) + // wait long enough for the scheduled task to fire (10ms after-delay + worker latency) + await wait(1500) + + // Producer trace: writes the task row inside the HTTP request tx. + const producer = groupedByTrace().find(g => g.all.some(s => s.name === 'AdminService - handle test_scheduled')) + expect(producer, 'expected a producer trace').to.exist + expect(producer.root.name).to.equal('AdminService - tx') + expect(producer.all.some(s => s.name === 'db - UPSERT cds.outbox.Messages')).to.be.true + expect(producer.all.some(s => s.name === 'cds.spawn - schedule task')).to.be.true + + // Queue worker trace: rooted at cds.spawn - run task, contains both tx spans. + const workerTrace = groupedByTrace().find(g => g.root.name === 'cds.spawn - run task') + expect(workerTrace, 'expected a queue-worker spawn-root trace').to.exist + expect(workerTrace.all.some(s => s.name === 'db - tx')).to.be.true + expect(workerTrace.all.some(s => s.name === 'ExternalServiceOne - tx')).to.be.true + + // The ExternalServiceOne handler was invoked. + expect(captured.some(s => s.name.match(/ExternalServiceOne - handle/))).to.be.true + + // Total meaningful roots: producer + worker (+ optional bookkeeping scan). + expect(rootSpans().length).to.be.gte(2) + expect(rootSpans().length).to.be.lte(3) + }) +}) diff --git a/test/tracing.test.js b/test/tracing.test.js index f3d0ce05..b1cd985a 100644 --- a/test/tracing.test.js +++ b/test/tracing.test.js @@ -4,22 +4,27 @@ process.env.cds_requires_telemetry_tracing_sampler = JSON.stringify({ }) const cds = require('@sap/cds') -const { expect, GET, POST } = cds.test(__dirname + '/bookshop') -const log = cds.test.log() +const { expect, GET, POST } = cds.test(__dirname + '/bookshop', '--profile', 'tracing-in-memory') + +// Assert against the structured ReadableSpan objects captured by MyInMemorySpanExporter +// (configured via the tracing-in-memory profile in test/bookshop/.cdsrc.json) — no +// console spying, no string-regex matching of formatted output. +const { reset, rootSpans, captured } = require('./bookshop/lib/MyInMemorySpanExporter') const wait = require('node:timers/promises').setTimeout describe('tracing', () => { const admin = { auth: { username: 'alice' } } - beforeEach(log.clear) + beforeEach(reset) test('GET is traced', async () => { const { status } = await GET('/odata/v4/admin/Books', admin) expect(status).to.equal(200) - // primitive check that console has trace logs - expect(log.output).to.match(/\[telemetry\] - elapsed times:/) - expect(log.output).to.match(/\s+\d+\.\d+ → \s*\d+\.\d+ = \s*\d+\.\d+ ms \s* AdminService - READ AdminService.Books/) + // The AdminService READ for Books was traced + expect(captured.some(s => s.name === 'AdminService - READ AdminService.Books')).to.be.true + // ...and at least one trace was rooted (i.e. our exporter would emit "elapsed times:") + expect(rootSpans().length).to.be.gte(1) }) // REVISIT: jest breaks otel's patching of incoming request handling -> no span for 'GET' -> behavior to test not reproducible @@ -27,17 +32,13 @@ describe('tracing', () => { const config = { ...admin, headers: { traceparent: '00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01' } } const { status } = await GET('/odata/v4/admin/Books', config) expect(status).to.equal(200) - // primitive check that console has trace logs - expect(log.output).to.match(/\[telemetry\] - elapsed times:/) - expect(log.output).to.match(/\s+\d+\.\d+ → \s*\d+\.\d+ = \s*\d+\.\d+ ms \s* AdminService - READ AdminService.Books/) + expect(captured.some(s => s.name === 'AdminService - READ AdminService.Books')).to.be.true }) test('custom GET is traced', async () => { const { status } = await GET('/custom/Books', admin) expect(status).to.equal(200) - // primitive check that console has trace logs - expect(log.output).to.match(/\[telemetry\] - elapsed times:/) - expect(log.output).to.match(/\s+\d+\.\d+ → \s*\d+\.\d+ = \s*\d+\.\d+ ms \s* db - READ sap.capire.bookshop.Books/) + expect(captured.some(s => s.name === 'db - READ sap.capire.bookshop.Books')).to.be.true }) test('NonRecordingSpans are handled correctly', async () => { @@ -45,20 +46,13 @@ describe('tracing', () => { expect(postStatus).to.equal(201) const { status: getStatus } = await GET('/odata/v4/admin/Authors?$select=ID', admin) expect(getStatus).to.equal(200) - // primitive check that console has no trace logs - expect(log.output).not.to.match(/telemetry/) + // The sampler in this test ignores /odata/v4/admin/Authors — no spans should be captured for it. + // (Other unrelated background work may still produce spans; assert only that none mention Authors.) + expect(captured.filter(s => s.attributes['url.path']?.includes('/admin/Authors'))).to.have.lengthOf(0) }) // REVISIT: jest breaks otel's patching of incoming request handling -> behavior to test not reproducible - xtest('instrumentation hooks', async () => { - await GET('/odata/v4/admin/Books(251)', admin) - // primitive check that console has trace logs - expect(log.output).to.match(/\[telemetry\] - elapsed times:/) - log.clear() - await GET('/odata/v4/admin/Books(252)', admin) - // primitive check that console has no trace logs - expect(log.output).not.to.match(/telemetry/) - }) + xtest('instrumentation hooks', async () => {}) test('$batch is traced', async () => { await POST( @@ -71,51 +65,48 @@ describe('tracing', () => { }, admin ) - // 4: POST: create/ new + read after write, GET: read actives + read drafts - expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(4) + // With the tx wrap (lib/tracing/cds.js), each batch request's tx becomes a single root — + // the previously-visible 4 sub-roots (POST: CREATE + read-after-write; GET: read actives + + // read drafts) are now nested under 2 root tx spans, one per batch entry. + expect(rootSpans()).to.have.lengthOf(2) }) test('cds.spawn is traced', async () => { await POST('/odata/v4/admin/test_spawn', {}, admin) await wait(30) - // 2: action + spawned action - expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(2) + // 2 visible roots: the action invocation + the spawned task + expect(rootSpans()).to.have.lengthOf(2) + expect(captured.some(s => s.name === 'cds.spawn - schedule task')).to.be.true + expect(captured.some(s => s.name === 'cds.spawn - run task')).to.be.true }) test('emit is traced', async () => { await POST('/odata/v4/admin/test_emit', {}, admin) await wait(100) - // 1: local-messaging remains in same context - expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(1) + // local-messaging keeps the consumer in the same context → exactly 1 visible root + expect(rootSpans()).to.have.lengthOf(1) }) describe('db', () => { describe('ql', () => { test('SELECT is traced', async () => { await SELECT.from('sap.capire.bookshop.Books') - // primitive check that console has trace logs - expect(log.output).to.match(/\[telemetry\] - elapsed times:/) - expect(log.output).to.match( - /\s+\d+\.\d+ → \s*\d+\.\d+ = \s*\d+\.\d+ ms \s* db - READ sap\.capire\.bookshop\.Books/ - ) + expect(captured.some(s => s.name === 'db - READ sap.capire.bookshop.Books')).to.be.true }) }) test('native db statement is traced', async () => { const db = await cds.connect.to('db') await db.run('SELECT ID, title, stock, price FROM AdminService_Books WHERE ID = 201 OR ID = 207') - // primitive check that console has trace logs - expect(log.output).to.match(/\[telemetry\] - elapsed times:/) - expect(log.output).to.match( - /\s+\d+\.\d+ → \s*\d+\.\d+ = \s*\d+\.\d+ ms \s* db - SELECT .* FROM AdminService_Books WHERE ID = 201 OR I…/ - ) + // The wrapper "db - SELECT …" span carries the raw SQL as part of the name. + expect(captured.some(s => s.name.startsWith('db - SELECT') && s.name.includes('AdminService_Books'))).to.be.true }) }) test('custom spans are supported', async () => { await GET('/odata/v4/catalog/ListOfBooks', {}, admin) await wait(100) - expect(log.output.match(/my custom span/g).length).to.equal(1) + expect(captured.filter(s => s.name === 'my custom span')).to.have.lengthOf(1) }) // --- TODO --- From 73e22105c0340ba3849e2848fa303699cf523551 Mon Sep 17 00:00:00 2001 From: Sebastian Van Syckel Date: Thu, 6 Aug 2026 15:23:01 +0200 Subject: [PATCH 2/6] test: skip queue-worker tracing suites on sqlite pending cds spawn fix The queue-worker tracing tests (scheduled, outboxed-batch, and the inboxed/ outboxed-and-inboxed/persistent-outbox messaging cases) assert on the 'cds.spawn - run task' root span and its child tx spans. That root only appears when @sap/cds routes the sqlite queue worker through cds.spawn. Published cds uses a raw setTimeout bypass on sqlite (to avoid a single-writer deadlock), so those spans never appear there. Skip these suites on sqlite until the cds fix lands (cap/cds branch test/queue-spawn-sqlite-extended-tenant, which removes the bypass by fixing the actual deadlock root cause). A follow-up PR removes these skips once the required cds version is released. HANA CI already exercises the full path. --- test/tracing-messaging-inboxed.test.js | 7 +++++++ test/tracing-messaging-outboxed-and-inboxed.test.js | 7 +++++++ test/tracing-messaging-persistent-outbox.test.js | 7 +++++++ test/tracing-outboxed-batch.test.js | 5 +++++ test/tracing-scheduled.test.js | 8 ++++++++ 5 files changed, 34 insertions(+) diff --git a/test/tracing-messaging-inboxed.test.js b/test/tracing-messaging-inboxed.test.js index 0845909f..a5ec21e3 100644 --- a/test/tracing-messaging-inboxed.test.js +++ b/test/tracing-messaging-inboxed.test.js @@ -54,6 +54,13 @@ const CHECK = ({ expect, rootSpans, groupedByTrace }) => { expect(rootSpans.length).to.be.lte(5) } +const cds = require('@sap/cds') + describe(`tracing messaging - ${CASE}`, () => { + // Queue-worker spans need cds.spawn on sqlite (pending cds fix). REMOVE with follow-up PR. + if (cds.env.requires.db?.kind === 'sqlite') { + test.skip('queue-worker tracing needs cds.spawn on sqlite (pending cds fix)', () => {}) + return + } require('./tracing-messaging')(CASE, CHECK, { waitMs: 4000 }) }) diff --git a/test/tracing-messaging-outboxed-and-inboxed.test.js b/test/tracing-messaging-outboxed-and-inboxed.test.js index 0a60d6d7..f1f4cf25 100644 --- a/test/tracing-messaging-outboxed-and-inboxed.test.js +++ b/test/tracing-messaging-outboxed-and-inboxed.test.js @@ -50,6 +50,13 @@ const CHECK = ({ expect, rootSpans, groupedByTrace }) => { expect(rootSpans.length).to.be.lte(5) } +const cds = require('@sap/cds') + describe(`tracing messaging - ${CASE}`, () => { + // Queue-worker spans need cds.spawn on sqlite (pending cds fix). REMOVE with follow-up PR. + if (cds.env.requires.db?.kind === 'sqlite') { + test.skip('queue-worker tracing needs cds.spawn on sqlite (pending cds fix)', () => {}) + return + } require('./tracing-messaging')(CASE, CHECK, { waitMs: 4000 }) }) diff --git a/test/tracing-messaging-persistent-outbox.test.js b/test/tracing-messaging-persistent-outbox.test.js index d4d83d7b..82b89109 100644 --- a/test/tracing-messaging-persistent-outbox.test.js +++ b/test/tracing-messaging-persistent-outbox.test.js @@ -94,6 +94,13 @@ const CHECK = ({ expect, rootSpans, groupedByTrace }) => { } } +const cds = require('@sap/cds') + describe(`tracing messaging - ${CASE}`, () => { + // Queue-worker spans need cds.spawn on sqlite (pending cds fix). REMOVE with follow-up PR. + if (cds.env.requires.db?.kind === 'sqlite') { + test.skip('queue-worker tracing needs cds.spawn on sqlite (pending cds fix)', () => {}) + return + } require('./tracing-messaging')(CASE, CHECK, { waitMs: 4000 }) }) diff --git a/test/tracing-outboxed-batch.test.js b/test/tracing-outboxed-batch.test.js index baf417d0..347f7dba 100644 --- a/test/tracing-outboxed-batch.test.js +++ b/test/tracing-outboxed-batch.test.js @@ -13,6 +13,11 @@ describe('tracing for outboxed batch (chunk-size fan-out)', () => { test.skip('skipping for cds < 9', () => {}) return } + // Queue-worker spans need cds.spawn on sqlite (pending cds fix). REMOVE with follow-up PR. + if (cds.env.requires.db?.kind === 'sqlite') { + test.skip('queue-worker tracing needs cds.spawn on sqlite (pending cds fix)', () => {}) + return + } beforeAll(async () => { const externalOne = await cds.connect.to('ExternalServiceOne') diff --git a/test/tracing-scheduled.test.js b/test/tracing-scheduled.test.js index 29250522..7b834eeb 100644 --- a/test/tracing-scheduled.test.js +++ b/test/tracing-scheduled.test.js @@ -29,6 +29,14 @@ describe('tracing for scheduled tasks', () => { test.skip('skipping for cds < 9', () => {}) return } + // Queue-worker spans (cds.spawn - run task root) require @sap/cds to route the sqlite + // queue worker through cds.spawn. Published cds uses a raw setTimeout bypass on sqlite + // (to avoid a single-writer deadlock), so those spans never appear. Skip until the cds + // fix lands (cap/cds test/queue-spawn-sqlite-extended-tenant). REMOVE with follow-up PR. + if (cds.env.requires.db?.kind === 'sqlite') { + test.skip('queue-worker tracing needs cds.spawn on sqlite (pending cds fix)', () => {}) + return + } beforeAll(async () => { const externalOne = await cds.connect.to('ExternalServiceOne') From 55b89e2f449dbcc9f5f56d2f09c3838b12f5b75c Mon Sep 17 00:00:00 2001 From: Sebastian Van Syckel Date: Thu, 6 Aug 2026 16:02:20 +0200 Subject: [PATCH 3/6] =?UTF-8?q?test:=20address=20PR=20review=20=E2=80=94?= =?UTF-8?q?=20explicit=20Number()=20version=20compare,=20dedup=20require,?= =?UTF-8?q?=20tighten=20mt=20assertion?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Number(cds.version.split('.')[0]) < 9 instead of relying on string coercion (tracing-outboxed-batch, tracing-scheduled) - hoist single hrTimeToNanoseconds require, drop the double require in the sort comparator (tracing-outboxed-batch) - multitenancy: assert exactly one AdminService READ span (filter + length 1) instead of find, guarding against residue leaking past reset (tracing-mt) Skipped bot findings: byParent[undefined] (field is unused by any test); tx double-wrap guard (same pattern as existing emit/handle wraps, plugin loads once per process). --- test/tracing-mt.test.js | 14 +++++++------- test/tracing-outboxed-batch.test.js | 9 ++++----- test/tracing-scheduled.test.js | 2 +- 3 files changed, 12 insertions(+), 13 deletions(-) diff --git a/test/tracing-mt.test.js b/test/tracing-mt.test.js index 8b6855fa..872a6dc2 100644 --- a/test/tracing-mt.test.js +++ b/test/tracing-mt.test.js @@ -23,18 +23,18 @@ describe('tracing with multitenancy', () => { test('GET with user1 is traced', async () => { const { status } = await GET('/odata/v4/admin/Books', user1) expect(status).to.equal(200) - // AdminService READ ran and was tagged with the right tenant. - const span = captured.find(s => s.name === 'AdminService - READ AdminService.Books') - expect(span, 'expected AdminService READ span').to.exist - expect(span.attributes['sap.tenancy.tenant_id']).to.equal(TENANT1) + // AdminService READ ran exactly once and was tagged with the right tenant. + const spans = captured.filter(s => s.name === 'AdminService - READ AdminService.Books') + expect(spans.length, 'expected exactly one AdminService READ span').to.equal(1) + expect(spans[0].attributes['sap.tenancy.tenant_id']).to.equal(TENANT1) }) test('GET with user2 is traced', async () => { const { status } = await GET('/odata/v4/admin/Books', user2) expect(status).to.equal(200) - const span = captured.find(s => s.name === 'AdminService - READ AdminService.Books') - expect(span, 'expected AdminService READ span').to.exist - expect(span.attributes['sap.tenancy.tenant_id']).to.equal(TENANT2) + const spans = captured.filter(s => s.name === 'AdminService - READ AdminService.Books') + expect(spans.length, 'expected exactly one AdminService READ span').to.equal(1) + expect(spans[0].attributes['sap.tenancy.tenant_id']).to.equal(TENANT2) }) // --- TODO --- diff --git a/test/tracing-outboxed-batch.test.js b/test/tracing-outboxed-batch.test.js index 347f7dba..640689ea 100644 --- a/test/tracing-outboxed-batch.test.js +++ b/test/tracing-outboxed-batch.test.js @@ -5,11 +5,12 @@ const cds = require('@sap/cds') const { expect, POST } = cds.test(__dirname + '/bookshop', '--with-mocks', '--profile', 'tracing-in-memory') const { reset, captured, groupedByTrace } = require('./bookshop/lib/MyInMemorySpanExporter') +const { hrTimeToNanoseconds } = require('@opentelemetry/core') const wait = require('node:timers/promises').setTimeout describe('tracing for outboxed batch (chunk-size fan-out)', () => { - if (cds.version.split('.')[0] < 9) { + if (Number(cds.version.split('.')[0]) < 9) { test.skip('skipping for cds < 9', () => {}) return } @@ -59,11 +60,9 @@ describe('tracing for outboxed batch (chunk-size fan-out)', () => { // The dispatch txs should overlap in time (parallel), not be strictly sequential. if (dispatchTxs.length >= 2) { - const sorted = [...dispatchTxs].sort((a, b) => - require('@opentelemetry/core').hrTimeToNanoseconds(a.startTime) - - require('@opentelemetry/core').hrTimeToNanoseconds(b.startTime) + const sorted = [...dispatchTxs].sort( + (a, b) => hrTimeToNanoseconds(a.startTime) - hrTimeToNanoseconds(b.startTime) ) - const { hrTimeToNanoseconds } = require('@opentelemetry/core') const firstEndNs = hrTimeToNanoseconds(sorted[0].endTime) const secondStartNs = hrTimeToNanoseconds(sorted[1].startTime) // Parallel: second starts before first ends (allow a tiny slack). diff --git a/test/tracing-scheduled.test.js b/test/tracing-scheduled.test.js index 7b834eeb..a5928956 100644 --- a/test/tracing-scheduled.test.js +++ b/test/tracing-scheduled.test.js @@ -25,7 +25,7 @@ const { reset, captured, groupedByTrace, rootSpans } = require('./bookshop/lib/M const wait = require('node:timers/promises').setTimeout describe('tracing for scheduled tasks', () => { - if (cds.version.split('.')[0] < 9) { + if (Number(cds.version.split('.')[0]) < 9) { test.skip('skipping for cds < 9', () => {}) return } From 74d924a13737e009772f5c56f99c100dfe75acf3 Mon Sep 17 00:00:00 2001 From: Sebastian Van Syckel Date: Fri, 7 Aug 2026 10:05:34 +0200 Subject: [PATCH 4/6] docs: changelog entry for queue worker tracing --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3995a012..39154001 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,8 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Added +- Queue worker transactions are traced as coherent ` - tx` spans under the `cds.spawn - run task` root, instead of orphaned per-call spans + ### Changed ### Fixed From 545e15b4c667e4b3e7952964e5269a23ff8e3dda Mon Sep 17 00:00:00 2001 From: Sebastian Van Syckel Date: Fri, 7 Aug 2026 16:01:49 +0200 Subject: [PATCH 5/6] test: drop redundant outboxed-and-inboxed messaging test Messaging is outboxed by default, so `outboxed: true, inboxed: true` exercises the exact same code path and asserts the identical span shape as the `inboxed` test. Remove the duplicate test + its unused .cdsrc profile. --- test/bookshop/.cdsrc.json | 10 --- ...ing-messaging-outboxed-and-inboxed.test.js | 62 ------------------- 2 files changed, 72 deletions(-) delete mode 100644 test/tracing-messaging-outboxed-and-inboxed.test.js diff --git a/test/bookshop/.cdsrc.json b/test/bookshop/.cdsrc.json index 949db9cd..6571cbe7 100644 --- a/test/bookshop/.cdsrc.json +++ b/test/bookshop/.cdsrc.json @@ -111,16 +111,6 @@ } } }, - "[outboxed-and-inboxed]": { - "requires": { - "messaging": { - "kind": "file-based-messaging", - "file": "../outboxed-and-inboxed", - "outboxed": true, - "inboxed": true - } - } - }, "[without-outbox]": { "requires": { "messaging": { diff --git a/test/tracing-messaging-outboxed-and-inboxed.test.js b/test/tracing-messaging-outboxed-and-inboxed.test.js deleted file mode 100644 index f1f4cf25..00000000 --- a/test/tracing-messaging-outboxed-and-inboxed.test.js +++ /dev/null @@ -1,62 +0,0 @@ -const CASE = 'outboxed-and-inboxed' - -// Explicit `outboxed: true` + `inboxed: true`. Same lifecycle as the `inboxed` test — two -// queue workers, each running tx-1 (lock) and tx-2 (handle + delete). Setting outboxed -// explicitly is a no-op relative to the messaging default, so the observed shape matches -// the `inboxed` test: -// -// 1. AdminService - tx (producer) -// 2. cds.spawn - run task (outbox worker: dispatches to file) -// ├─ db - tx (tx 1) -// └─ messaging - tx (tx 2: handle foo — writes to file — + DELETE) -// 3. messaging - tx (file-based CONSUMER: writes inbox row) -// └─ ...enqueue into inbox... -// 4. cds.spawn - run task (inbox worker: runs subscriber) -// ├─ db - tx (tx 1) -// └─ messaging - tx (tx 2: handle foo — full app work — + DELETE) -// -// 4 meaningful roots (+1 tolerated bookkeeping scan). - -process.env.cds_requires_messaging = JSON.stringify({ - kind: 'file-based-messaging', - file: `../${CASE}`, - outboxed: true, - inboxed: true -}) - -const CHECK = ({ expect, rootSpans, groupedByTrace }) => { - // Producer trace - const producer = groupedByTrace.find(g => g.all.some(s => s.name === 'AdminService - handle test_emit')) - expect(producer, 'expected a producer trace').to.exist - expect(producer.root.name).to.equal('AdminService - tx') - expect(producer.all.some(s => s.name === 'db - UPSERT cds.outbox.Messages')).to.be.true - - const allSpans = groupedByTrace.flatMap(g => g.all) - expect(allSpans.some(s => s.name.match(/READ sap\.capire\.bookshop\.Books/))).to.be.true - expect(allSpans.some(s => s.name === 'db - DELETE cds.outbox.Messages')).to.be.true - - // Exactly two `cds.spawn - run task` roots (outbox + inbox workers). - const workerRoots = rootSpans.filter(s => s.name === 'cds.spawn - run task') - expect(workerRoots, 'expected two queue-worker spawn roots (outbox + inbox)').to.have.lengthOf(2) - - // The inbox worker ran the app handler. - const inboxWorker = groupedByTrace.find( - g => g.root.name === 'cds.spawn - run task' && g.all.some(s => s.name.match(/READ sap\.capire\.bookshop\.Books/)) - ) - expect(inboxWorker, 'expected an inbox-worker trace that ran the application handler').to.exist - - // 4 meaningful roots (+1 tolerated bookkeeping scan). - expect(rootSpans.length).to.be.gte(4) - expect(rootSpans.length).to.be.lte(5) -} - -const cds = require('@sap/cds') - -describe(`tracing messaging - ${CASE}`, () => { - // Queue-worker spans need cds.spawn on sqlite (pending cds fix). REMOVE with follow-up PR. - if (cds.env.requires.db?.kind === 'sqlite') { - test.skip('queue-worker tracing needs cds.spawn on sqlite (pending cds fix)', () => {}) - return - } - require('./tracing-messaging')(CASE, CHECK, { waitMs: 4000 }) -}) From d1812a11a3ed33bd7fbb1b28ac24dbde4b3492e3 Mon Sep 17 00:00:00 2001 From: Sebastian Van Syckel Date: Thu, 6 Aug 2026 15:27:04 +0200 Subject: [PATCH 6/6] test: remove sqlite skips for queue-worker tracing suites Removes the sqlite skip guards added while the cds queue-spawn fix was pending. With cds routing the sqlite queue worker through cds.spawn (cap/cds branch test/queue-spawn-sqlite-extended-tenant: removes the setTimeout bypass and fixes the underlying deadlock by wrapping ExtendedModels.model4() in cds.tx()), the 'cds.spawn - run task' root span and its child tx spans now appear on sqlite too. Merge only after that cds fix is released and the @sap/cds dependency is bumped. --- test/tracing-messaging-inboxed.test.js | 7 ------- test/tracing-messaging-persistent-outbox.test.js | 7 ------- test/tracing-outboxed-batch.test.js | 5 ----- test/tracing-scheduled.test.js | 8 -------- 4 files changed, 27 deletions(-) diff --git a/test/tracing-messaging-inboxed.test.js b/test/tracing-messaging-inboxed.test.js index a5ec21e3..0845909f 100644 --- a/test/tracing-messaging-inboxed.test.js +++ b/test/tracing-messaging-inboxed.test.js @@ -54,13 +54,6 @@ const CHECK = ({ expect, rootSpans, groupedByTrace }) => { expect(rootSpans.length).to.be.lte(5) } -const cds = require('@sap/cds') - describe(`tracing messaging - ${CASE}`, () => { - // Queue-worker spans need cds.spawn on sqlite (pending cds fix). REMOVE with follow-up PR. - if (cds.env.requires.db?.kind === 'sqlite') { - test.skip('queue-worker tracing needs cds.spawn on sqlite (pending cds fix)', () => {}) - return - } require('./tracing-messaging')(CASE, CHECK, { waitMs: 4000 }) }) diff --git a/test/tracing-messaging-persistent-outbox.test.js b/test/tracing-messaging-persistent-outbox.test.js index 82b89109..d4d83d7b 100644 --- a/test/tracing-messaging-persistent-outbox.test.js +++ b/test/tracing-messaging-persistent-outbox.test.js @@ -94,13 +94,6 @@ const CHECK = ({ expect, rootSpans, groupedByTrace }) => { } } -const cds = require('@sap/cds') - describe(`tracing messaging - ${CASE}`, () => { - // Queue-worker spans need cds.spawn on sqlite (pending cds fix). REMOVE with follow-up PR. - if (cds.env.requires.db?.kind === 'sqlite') { - test.skip('queue-worker tracing needs cds.spawn on sqlite (pending cds fix)', () => {}) - return - } require('./tracing-messaging')(CASE, CHECK, { waitMs: 4000 }) }) diff --git a/test/tracing-outboxed-batch.test.js b/test/tracing-outboxed-batch.test.js index 640689ea..03849fc4 100644 --- a/test/tracing-outboxed-batch.test.js +++ b/test/tracing-outboxed-batch.test.js @@ -14,11 +14,6 @@ describe('tracing for outboxed batch (chunk-size fan-out)', () => { test.skip('skipping for cds < 9', () => {}) return } - // Queue-worker spans need cds.spawn on sqlite (pending cds fix). REMOVE with follow-up PR. - if (cds.env.requires.db?.kind === 'sqlite') { - test.skip('queue-worker tracing needs cds.spawn on sqlite (pending cds fix)', () => {}) - return - } beforeAll(async () => { const externalOne = await cds.connect.to('ExternalServiceOne') diff --git a/test/tracing-scheduled.test.js b/test/tracing-scheduled.test.js index a5928956..7fa1d9c7 100644 --- a/test/tracing-scheduled.test.js +++ b/test/tracing-scheduled.test.js @@ -29,14 +29,6 @@ describe('tracing for scheduled tasks', () => { test.skip('skipping for cds < 9', () => {}) return } - // Queue-worker spans (cds.spawn - run task root) require @sap/cds to route the sqlite - // queue worker through cds.spawn. Published cds uses a raw setTimeout bypass on sqlite - // (to avoid a single-writer deadlock), so those spans never appear. Skip until the cds - // fix lands (cap/cds test/queue-spawn-sqlite-extended-tenant). REMOVE with follow-up PR. - if (cds.env.requires.db?.kind === 'sqlite') { - test.skip('queue-worker tracing needs cds.spawn on sqlite (pending cds fix)', () => {}) - return - } beforeAll(async () => { const externalOne = await cds.connect.to('ExternalServiceOne')