diff --git a/test/bookshop/.cdsrc.json b/test/bookshop/.cdsrc.json index 6571cbe7..606f66f5 100644 --- a/test/bookshop/.cdsrc.json +++ b/test/bookshop/.cdsrc.json @@ -30,6 +30,10 @@ "metrics": { "config": { "exportIntervalMillis": 100 + }, + "exporter": { + "module": "./lib/MyInMemoryMetricReader.js", + "class": "MyInMemoryMetricReader" } } } @@ -46,8 +50,8 @@ "_db_pool": false, "_queue": true, "exporter": { - "module": "@opentelemetry/sdk-metrics", - "class": "ConsoleMetricExporter" + "module": "./lib/MyInMemoryMetricReader.js", + "class": "MyInMemoryMetricReader" } } } @@ -64,8 +68,8 @@ "_db_pool": false, "_queue": false, "exporter": { - "module": "@opentelemetry/sdk-metrics", - "class": "ConsoleMetricExporter" + "module": "./lib/MyInMemoryMetricReader.js", + "class": "MyInMemoryMetricReader" } } } diff --git a/test/bookshop/lib/MyInMemoryMetricReader.js b/test/bookshop/lib/MyInMemoryMetricReader.js new file mode 100644 index 00000000..5787ee01 --- /dev/null +++ b/test/bookshop/lib/MyInMemoryMetricReader.js @@ -0,0 +1,189 @@ +// In-memory metric reader for tests. Exported metrics are accumulated in a module-level array +// that tests can import directly via `require('./lib/MyInMemoryMetricReader').captured`. +// Wired into the meter provider via .cdsrc.json profile config (no provider-poking from tests): +// the class is exporter-shaped (has `export()`), so lib/metrics/index.js wraps it in a +// PeriodicExportingMetricReader — keeping the configured `exportIntervalMillis` working. +// +// Kept dependency-light on purpose: it does NOT `require('@sap/cds')` at module top (doing so +// broke span capture once for the sibling span exporter). Only @opentelemetry primitives. +// +// TEMPORALITY: mirrors production. lib/metrics/index.js configures the real exporter with +// `temporalityPreference: AggregationTemporality.DELTA`, so the tests must validate what a real +// DELTA export produces — the reader honors that preference rather than forcing CUMULATIVE. +// +// Under DELTA each export reports only the *increment* since the previous collection, and +// `expectEventually` force-flushes repeatedly, so a naive "latest datapoint" read of a counter +// would drop to 0 after the first flush. We therefore split handling by datapoint type: +// * SUM datapoints (the 3 counters: incoming_messages, outgoing_messages, processing_failures) +// are summed into a running total per counter series (metric name + full attribute set) — +// reconstructing the cumulative value the tests assert against (totalInc/totalOut/totalFailed). +// * GAUGE datapoints (cold_entries, remaining_entries, *_storage_time_in_seconds) are absolute +// point-in-time observations; for those we keep the latest exported value, never a sum. + +const { ExportResultCode } = require('@opentelemetry/core') +const { AggregationTemporality, DataPointType } = require('@opentelemetry/sdk-metrics') +const { metrics } = require('@opentelemetry/api') + +// Raw ResourceMetrics objects, one per collection/flush. Drives the GAUGE latest-value lookup. +const captured = [] + +// Running totals for SUM (counter) series. Keyed by the fully-qualified series identity +// (metric name + every attribute on the datapoint) so distinct (queue.name, tenant) series never +// collide; each entry keeps the original attributes so lookups can match by attribute subset the +// same way the gauge path does. Under DELTA the SDK reports the increment since its last +// collection; summing every increment a series receives reconstructs its cumulative value — which +// is what the tests track (totalInc/totalOut/totalFailed grow monotonically, never reset per case). +// +// NOTE: `captured` and `counterSeries` are process-level singletons. Cross-file correctness relies +// on Vitest isolating each test file in its own worker process (vitest.config.mjs: pool:'forks' + +// isolate:true). Two files sharing this module in one process would bleed counter totals together. +const counterSeries = new Map() + +function seriesKey(metricName, attributes) { + const sorted = Object.keys(attributes) + .sort() + .map(k => `${k}=${attributes[k]}`) + .join('&') + return `${metricName} ${sorted}` +} + +// True when `sub` is an attribute subset of `full` (all keys present with equal values). +function attributesMatch(full, sub) { + return Object.entries(sub).every(([key, value]) => full[key] === value) +} + +class MyInMemoryMetricReader { + constructor(config = {}) { + // Honor the temporality the plugin config sets (DELTA in production) so the tests exercise the + // real export shape. Defaults to DELTA to match lib/metrics/index.js when no config is passed. + this._temporality = config.temporalityPreference ?? AggregationTemporality.DELTA + } + + // Invoked by PeriodicExportingMetricReader for each instrument type. + selectAggregationTemporality() { + return this._temporality + } + + export(resourceMetrics, resultCallback) { + captured.push(resourceMetrics) + + // Fold DELTA increments of SUM (counter) datapoints into the running totals. + for (const scopeMetrics of resourceMetrics.scopeMetrics) { + for (const metric of scopeMetrics.metrics) { + if (metric.dataPointType !== DataPointType.SUM) continue + for (const dp of metric.dataPoints) { + const key = seriesKey(metric.descriptor.name, dp.attributes) + const entry = counterSeries.get(key) + if (entry) entry.total += dp.value + else counterSeries.set(key, { name: metric.descriptor.name, attributes: dp.attributes, total: dp.value }) + } + } + } + + resultCallback({ code: ExportResultCode.SUCCESS }) + } + + shutdown() { + return Promise.resolve() + } + + forceFlush() { + return Promise.resolve() + } +} + +// Most recent GAUGE MetricData for `queue.` that carries datapoints, scanning captured +// exports newest-first (mirrors the old `consoleDirLogs.findLast(... && dataPoints?.length)`). +function latestGaugeMetric(metricName) { + const name = `queue.${metricName}` + for (let i = captured.length - 1; i >= 0; i--) { + for (const scopeMetrics of captured[i].scopeMetrics) { + for (const metric of scopeMetrics.metrics) { + if ( + metric.descriptor.name === name && + metric.dataPointType === DataPointType.GAUGE && + metric.dataPoints?.length + ) + return metric + } + } + } + return null +} + +// Accumulated counter total for `queue.` across all series whose attributes match the +// given filter (subset match, like the gauge lookup). Returns null when no counter series exists +// for that name — i.e. the metric was never exported as a counter (queue metrics disabled) or the +// filter matches nothing. +function counterTotal(metricName, attributes) { + const name = `queue.${metricName}` + let found = false + let total = 0 + for (const entry of counterSeries.values()) { + if (entry.name === name && attributesMatch(entry.attributes, attributes)) { + found = true + total += entry.total + } + } + return found ? total : null +} + +// Names of metrics that are SUM (counter) instruments — the three counters the queue plugin +// registers. Dispatches latestDataPointValue explicitly, rather than relying on counterSeries +// happening to be populated (which is empty on the first poll after reset()). +const COUNTER_METRIC_NAMES = new Set([ + 'queue.incoming_messages', + 'queue.outgoing_messages', + 'queue.processing_failures' +]) + +function isCounter(metricName) { + return COUNTER_METRIC_NAMES.has(`queue.${metricName}`) +} + +// Value of `queue.` for the datapoint(s) matching all given attributes +// (e.g. { 'queue.name': ... } and/or { 'sap.tenancy.tenant_id': ... }). For counters this is the +// accumulated running total (cumulative, reconstructed from DELTA increments); for gauges it is +// the latest absolute observation. Returns null when the metric was never exported (queue metrics +// disabled) or no datapoint matches the filter. +function latestDataPointValue(metricName, attributes = {}) { + if (isCounter(metricName)) return counterTotal(metricName, attributes) + + const metric = latestGaugeMetric(metricName) + if (!metric) return null + const dp = metric.dataPoints.find(dp => attributesMatch(dp.attributes, attributes)) + return dp ? dp.value : null +} + +// Force the wired meter provider to collect + export now, so the reader reflects the latest state. +// Fails fast if the provider isn't the real (wired) one — a NoopMeterProvider has no forceFlush, +// which would otherwise silently no-op and let a polling helper busy-spin its whole timeout. +async function forceFlush() { + const provider = metrics.getMeterProvider() + if (typeof provider.forceFlush !== 'function') { + throw new Error( + 'MyInMemoryMetricReader.forceFlush: meter provider is not wired up (no forceFlush) — ' + + 'is the metrics-outbox profile active and the reader configured?' + ) + } + await provider.forceFlush() +} + +// Clears the per-test GAUGE state (captured exports) so a stale point-in-time value from a previous +// case cannot leak. The counter running totals are intentionally NOT cleared: the suites' counter +// assertions (totalInc/totalOut/totalFailed) and the plugin's underlying counters are cumulative +// across the whole file, and the SDK's DELTA baseline likewise persists across flushes — zeroing +// only our side would desync it and under-count. See the module header for the full rationale. +function reset() { + captured.length = 0 +} + +module.exports = { + MyInMemoryMetricReader, + captured, + counterSeries, + latestGaugeMetric, + latestDataPointValue, + forceFlush, + reset +} diff --git a/test/console-metric-exporter.test.js b/test/console-metric-exporter.test.js new file mode 100644 index 00000000..ab13af1f --- /dev/null +++ b/test/console-metric-exporter.test.js @@ -0,0 +1,255 @@ +// Unit tests for ConsoleMetricExporter — verifies the user-friendly formatting of the three +// output branches (db.pool table, queue table, "other" metrics) plus the aggregated host-metrics +// block, by feeding the exporter crafted ResourceMetrics-shaped fixtures and inspecting the +// formatted strings 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 ConsoleMetricExporter = require('../lib/exporter/ConsoleMetricExporter') + +afterAll(() => { + telemetryLog.info = originalInfo +}) + +beforeEach(() => { + infoCalls.length = 0 +}) + +// --- helpers --------------------------------------------------------------- + +// Builds a minimal ScopeMetrics-shaped object. +function scopeMetrics(name, metrics) { + return { scope: { name }, metrics } +} + +// Builds a minimal MetricData-shaped object. `dataPoints` are `{ attributes, value }`. +function metric(name, dataPoints, description = name) { + return { descriptor: { name, description }, dataPoints } +} + +// Drives the exporter and returns the lines logged. Asserts the result callback got SUCCESS. +function exportAndCapture(scopes) { + const exporter = new ConsoleMetricExporter() + let result + exporter.export({ scopeMetrics: scopes }, 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') + +const APP_SCOPE = '@cap-js/telemetry' +const HOST_SCOPE = '@opentelemetry/instrumentation-host-metrics' + +describe('ConsoleMetricExporter', () => { + describe('db.pool table', () => { + it('renders a "db.pool:" header and the size/available/pending table row', () => { + const scopes = [ + scopeMetrics(APP_SCOPE, [ + metric('db.pool.size', [{ attributes: {}, value: 3 }]), + metric('db.pool.max', [{ attributes: {}, value: 10 }]), + metric('db.pool.available', [{ attributes: {}, value: 2 }]), + metric('db.pool.pending', [{ attributes: {}, value: 1 }]) + ]) + ] + + const [line] = exportAndCapture(scopes) + + expect(infoCalls.length).to.equal(1) + expect(line).to.match(/^db\.pool:/) + // Column header + expect(line).to.include('size | available | pending') + // size/max, available/size, pending — padded into the row + expect(line).to.match(/3\/10 \| +2\/3 \| +1/) + }) + + it('labels the table with the tenant id when a datapoint carries sap.tenancy.tenant_id', () => { + const attributes = { 'sap.tenancy.tenant_id': 't1' } + const scopes = [ + scopeMetrics(APP_SCOPE, [ + metric('db.pool.size', [{ attributes, value: 5 }]), + metric('db.pool.max', [{ attributes, value: 8 }]), + metric('db.pool.available', [{ attributes, value: 4 }]), + metric('db.pool.pending', [{ attributes, value: 0 }]) + ]) + ] + + const [line] = exportAndCapture(scopes) + + expect(line).to.match(/^db\.pool of tenant "t1":/) + expect(line).to.match(/5\/8 \| +4\/5 \| +0/) + }) + }) + + describe('queue table', () => { + it('renders a "queue:" header, the wide column header, and lands the values', () => { + const dp = value => [{ attributes: {}, value }] + const scopes = [ + scopeMetrics(APP_SCOPE, [ + metric('queue.cold_entries', dp(1)), + metric('queue.remaining_entries', dp(2)), + metric('queue.min_storage_time_in_seconds', dp(3)), + metric('queue.med_storage_time_in_seconds', dp(4)), + metric('queue.max_storage_time_in_seconds', dp(5)), + metric('queue.incoming_messages', dp(6)), + metric('queue.outgoing_messages', dp(7)), + metric('queue.processing_failures', dp(8)) + ]) + ] + + const [line] = exportAndCapture(scopes) + + expect(infoCalls.length).to.equal(1) + expect(line).to.match(/^queue:/) + // Column header (all eight columns) + expect(line).to.include( + 'cold | remaining | min storage time | med storage time | max storage time | incoming | outgoing | failed' + ) + // The eight values land in the padded row, in column order. + const row = line.split('\n').at(-1) + expect(row.split('|').map(c => c.trim())).to.deep.equal(['1', '2', '3', '4', '5', '6', '7', '8']) + }) + + it('labels the queue table with the tenant id when present', () => { + const attributes = { 'sap.tenancy.tenant_id': 't2' } + const dp = value => [{ attributes, value }] + const scopes = [ + scopeMetrics(APP_SCOPE, [ + metric('queue.cold_entries', dp(0)), + metric('queue.remaining_entries', dp(0)), + metric('queue.min_storage_time_in_seconds', dp(0)), + metric('queue.med_storage_time_in_seconds', dp(0)), + metric('queue.max_storage_time_in_seconds', dp(0)), + metric('queue.incoming_messages', dp(0)), + metric('queue.outgoing_messages', dp(0)), + metric('queue.processing_failures', dp(0)) + ]) + ] + + const [line] = exportAndCapture(scopes) + + expect(line).to.match(/^queue of tenant "t2":/) + }) + }) + + describe('other metrics', () => { + it('logs a single-datapoint metric unwrapped (inspect of the datapoint object)', () => { + const scopes = [ + scopeMetrics(APP_SCOPE, [metric('nodejs.eventloop.utilization', [{ attributes: {}, value: 0.42 }])]) + ] + + const [line] = exportAndCapture(scopes) + + expect(infoCalls.length).to.equal(1) + // Unwrapped: inspect(v[0]) of a single datapoint object → starts with "{" + expect(line).to.match(/^nodejs\.eventloop\.utilization: \{/) + expect(line).to.include('value: 0.42') + expect(line).not.to.match(/^nodejs\.eventloop\.utilization: \[/) + }) + + it('logs a multi-datapoint metric as an array (inspect of the datapoints array)', () => { + const scopes = [ + scopeMetrics(APP_SCOPE, [ + metric('nodejs.eventloop.time', [ + { attributes: { 'nodejs.eventloop.state': 'active' }, value: 100 }, + { attributes: { 'nodejs.eventloop.state': 'idle' }, value: 200 } + ]) + ]) + ] + + const [line] = exportAndCapture(scopes) + + expect(infoCalls.length).to.equal(1) + // Wrapped: inspect(v) of the datapoints array → starts with "[" + expect(line).to.match(/^nodejs\.eventloop\.time: \[/) + expect(line).to.include('value: 100') + expect(line).to.include('value: 200') + }) + + it('labels other metrics with the tenant id when present', () => { + const scopes = [ + scopeMetrics(APP_SCOPE, [metric('some.metric', [{ attributes: { 'sap.tenancy.tenant_id': 't3' }, value: 1 }])]) + ] + + const [line] = exportAndCapture(scopes) + + expect(line).to.match(/^some\.metric of tenant "t3": \{/) + }) + }) + + describe('host metrics', () => { + const original = process.env.HOST_METRICS_LOG_SYSTEM + + afterEach(() => { + if (original === undefined) delete process.env.HOST_METRICS_LOG_SYSTEM + else process.env.HOST_METRICS_LOG_SYSTEM = original + }) + + // process.* metrics are always aggregated; a system.network.* metric is only aggregated when + // HOST_METRICS_LOG_SYSTEM is set. + function hostScope() { + return [ + scopeMetrics(HOST_SCOPE, [ + metric('process.cpu.time', [{ attributes: { 'process.cpu.state': 'user' }, value: 1.5 }], 'process cpu time'), + metric('process.memory.usage', [{ attributes: {}, value: 123456 }], 'process memory usage'), + metric( + 'system.network.io', + [{ attributes: { device: 'eth0', direction: 'receive' }, value: 999 }], + 'system network io' + ) + ]) + ] + } + + it('aggregates only process.* into a "host metrics:" block when HOST_METRICS_LOG_SYSTEM is unset', () => { + delete process.env.HOST_METRICS_LOG_SYSTEM + + const [line] = exportAndCapture(hostScope()) + + expect(infoCalls.length).to.equal(1) + expect(line).to.match(/^host metrics:/) + expect(line).to.include('process cpu time') + expect(line).to.include('process memory usage') + // system.* excluded when the flag is unset + expect(line).not.to.include('system network io') + }) + + it('additionally aggregates system.* when HOST_METRICS_LOG_SYSTEM is set', () => { + process.env.HOST_METRICS_LOG_SYSTEM = 'true' + + const [line] = exportAndCapture(hostScope()) + + expect(infoCalls.length).to.equal(1) + expect(line).to.match(/^host metrics:/) + expect(line).to.include('process cpu time') + expect(line).to.include('process memory usage') + expect(line).to.include('system network io') + }) + }) + + describe('shutdown', () => { + it('returns FAILED via setImmediate when the exporter is shutting down', () => { + const exporter = new ConsoleMetricExporter() + exporter._shutdown = true + + return new Promise(resolve => { + exporter.export({ scopeMetrics: [] }, result => { + expect(result).to.deep.equal({ code: 1 /* ExportResultCode.FAILED */ }) + expect(infoCalls.length).to.equal(0) + resolve() + }) + }) + }) + }) +}) diff --git a/test/metrics-outbox-disabled.test.js b/test/metrics-outbox-disabled.test.js index 2616a09e..6b6e33a8 100644 --- a/test/metrics-outbox-disabled.test.js +++ b/test/metrics-outbox-disabled.test.js @@ -1,23 +1,13 @@ -import { vi } from 'vitest' -// Mock console.dir to capture logs ConsoleMetricExporter writes -const consoleDirLogs = [] -vi.spyOn(console, 'dir').mockImplementation((...args) => { - consoleDirLogs.push(args) -}) - const cds = require('@sap/cds') -const { setTimeout: wait } = require('node:timers/promises') + +// With queue metrics disabled (_queue: false in the metrics-outbox-disabled profile) the +// in-memory reader should never capture any `queue.*` datapoints. +const { latestDataPointValue, forceFlush, reset } = require('./bookshop/lib/MyInMemoryMetricReader') const { expect, GET } = cds.test(__dirname + '/bookshop', '--with-mocks', '--profile', 'metrics-outbox-disabled') function metricValue(metric) { - const mostRecentMetricLog = consoleDirLogs.findLast( - metricLog => metricLog[0].descriptor.name === `queue.${metric}` - )?.[0] - - if (!mostRecentMetricLog) return null - - return mostRecentMetricLog.dataPoints[0].value + return latestDataPointValue(metric) } describe('queue metrics is disabled', () => { @@ -35,12 +25,15 @@ describe('queue metrics is disabled', () => { externalServiceOne.before('*', () => {}) }) - beforeEach(() => (consoleDirLogs.length = 0)) + beforeEach(() => reset()) test('metrics are not collected', async () => { await GET('/odata/v4/proxy/proxyCallToExternalServiceOne', admin) - await wait(150) // Wait for metrics to be collected + // Assert absence: with _queue disabled no queue.* instrument is ever registered, so nothing can + // be exported. Force a few export cycles (rather than a fixed sleep) to give the app every chance + // to emit a queue metric — none must appear. + for (let i = 0; i < 5; i++) await forceFlush() expect(metricValue('cold_entries')).to.eq(null) expect(metricValue('remaining_entries')).to.eq(null) diff --git a/test/metrics-outbox-multitenant.test.js b/test/metrics-outbox-multitenant.test.js index 0f0b459b..d97bc09f 100644 --- a/test/metrics-outbox-multitenant.test.js +++ b/test/metrics-outbox-multitenant.test.js @@ -1,13 +1,10 @@ -import { vi } from 'vitest' -// Mock console.dir to capture logs ConsoleMetricExporter writes -const consoleDirLogs = [] -vi.spyOn(console, 'dir').mockImplementation((...args) => { - consoleDirLogs.push(args) -}) - const cds = require('@sap/cds') const { setTimeout: wait } = require('node:timers/promises') +// Exported metric data is captured in-memory by MyInMemoryMetricReader (wired via the +// metrics-outbox profile in .cdsrc.json) instead of scraping ConsoleMetricExporter's console.dir. +const { latestDataPointValue, forceFlush, reset } = require('./bookshop/lib/MyInMemoryMetricReader') + const { expect, GET, axios } = cds.test( __dirname + '/bookshop', '--with-mocks', @@ -17,19 +14,36 @@ const { expect, GET, axios } = cds.test( axios.defaults.validateStatus = () => true function metricValue(tenant, metric) { - const mostRecentMetricLog = consoleDirLogs.findLast( - metricLog => metricLog[0].descriptor.name === `queue.${metric}` - )?.[0] - - if (!mostRecentMetricLog) return null + return latestDataPointValue(metric, { 'sap.tenancy.tenant_id': tenant }) +} - const mostRecentTenantDataPoint = mostRecentMetricLog.dataPoints.find( - dp => dp.attributes['sap.tenancy.tenant_id'] === tenant - ) - return mostRecentTenantDataPoint ? mostRecentTenantDataPoint.value : null +// State-based wait: force the wired meter provider to collect + export, then re-run the assertion +// block. Replaces all fixed-time `wait(…)` sleeps — the loop completes the instant the in-memory +// per-tenant queue statistics (kept fresh by the existing cds.spawn poller) reflect the asserted +// state. forceFlush() throws fast if the provider isn't wired, so a misconfigured profile fails +// loudly instead of busy-spinning the full timeout. +async function expectEventually(assertion, { timeout = 10000, interval = 25 } = {}) { + const start = Date.now() + let lastError + while (true) { + await forceFlush() + try { + assertion() + return + } catch (err) { + lastError = err + if (Date.now() - start >= timeout) throw lastError + await wait(interval) + } + } } describe('queue metrics for multi tenant service', () => { + if (cds.version.split('.')[0] < 9) { + test.skip('skipping tests for cds version < 9', () => {}) + return + } + const T1 = 'tenant_1' const T2 = 'tenant_2' @@ -67,7 +81,7 @@ describe('queue metrics for multi tenant service', () => { beforeEach(async () => { await cds.tx({ tenant: T1 }, () => DELETE.from('cds.outbox.Messages')) await cds.tx({ tenant: T2 }, () => DELETE.from('cds.outbox.Messages')) - consoleDirLogs.length = 0 + reset() }) describe('given the target service succeeds immediately', () => { @@ -77,34 +91,39 @@ describe('queue metrics for multi tenant service', () => { GET('/odata/v4/proxy/proxyCallToExternalServiceOne', user[T2]) ]) - await wait(150) // Wait for metrics to be collected - - expect(metricValue(T1, 'cold_entries')).to.eq(0) - expect(metricValue(T1, 'incoming_messages')).to.eq(totalInc[T1]) - expect(metricValue(T1, 'outgoing_messages')).to.eq(totalOut[T1]) - expect(metricValue(T1, 'remaining_entries')).to.eq(0) - expect(metricValue(T1, 'min_storage_time_in_seconds')).to.eq(0) - expect(metricValue(T1, 'med_storage_time_in_seconds')).to.eq(0) - expect(metricValue(T1, 'max_storage_time_in_seconds')).to.eq(0) - - expect(metricValue(T2, 'cold_entries')).to.eq(0) - expect(metricValue(T2, 'incoming_messages')).to.eq(totalInc[T2]) - expect(metricValue(T2, 'outgoing_messages')).to.eq(totalOut[T2]) - expect(metricValue(T2, 'remaining_entries')).to.eq(0) - expect(metricValue(T2, 'min_storage_time_in_seconds')).to.eq(0) - expect(metricValue(T2, 'med_storage_time_in_seconds')).to.eq(0) - expect(metricValue(T2, 'max_storage_time_in_seconds')).to.eq(0) + await expectEventually(() => { + expect(metricValue(T1, 'cold_entries')).to.eq(0) + expect(metricValue(T1, 'incoming_messages')).to.eq(totalInc[T1]) + expect(metricValue(T1, 'outgoing_messages')).to.eq(totalOut[T1]) + expect(metricValue(T1, 'remaining_entries')).to.eq(0) + expect(metricValue(T1, 'min_storage_time_in_seconds')).to.eq(0) + expect(metricValue(T1, 'med_storage_time_in_seconds')).to.eq(0) + expect(metricValue(T1, 'max_storage_time_in_seconds')).to.eq(0) + + expect(metricValue(T2, 'cold_entries')).to.eq(0) + expect(metricValue(T2, 'incoming_messages')).to.eq(totalInc[T2]) + expect(metricValue(T2, 'outgoing_messages')).to.eq(totalOut[T2]) + expect(metricValue(T2, 'remaining_entries')).to.eq(0) + expect(metricValue(T2, 'min_storage_time_in_seconds')).to.eq(0) + expect(metricValue(T2, 'med_storage_time_in_seconds')).to.eq(0) + expect(metricValue(T2, 'max_storage_time_in_seconds')).to.eq(0) + }) }) }) describe('given a target service that requires retries', () => { let currentRetryCount, unboxedService + // Fail the first 3 attempts so the 4th delivers — the same widened window #445 introduced for + // the single-tenant suite: it opens a comfortable gap between "message has aged >=1s in the + // queue" and "message is delivered and removed", which is what made the wall-clock test flaky. + const ATTEMPTS_TO_FAIL = 3 + beforeAll(async () => { unboxedService = await cds.connect.to('ExternalServiceOne') unboxedService.before('call', req => { - if ((currentRetryCount[cds.context.tenant] += 1) <= 2) { + if ((currentRetryCount[cds.context.tenant] += 1) <= ATTEMPTS_TO_FAIL) { totalFailed[cds.context.tenant] += 1 return req.reject({ status: 503 }) } @@ -120,76 +139,75 @@ describe('queue metrics for multi tenant service', () => { }) test('storage time increases before message can be delivered', async () => { + // Reference time taken BEFORE the GETs so the queuing round-trip counts toward the wall-clock debounce below. const timeOfInitialCall = Date.now() await Promise.all([ GET('/odata/v4/proxy/proxyCallToExternalServiceOne', user[T1]), GET('/odata/v4/proxy/proxyCallToExternalServiceOne', user[T2]) ]) - // Wait for the first retry to be processed - while (currentRetryCount[T1] < 2) await wait(10) - while (currentRetryCount[T2] < 2) await wait(10) - - // Wait until at least 1 second has passed since the initial call - const timeAfterFirstRetry = Date.now() - if (timeAfterFirstRetry - timeOfInitialCall < 1000) { - await wait(1000 - (timeAfterFirstRetry - timeOfInitialCall)) - } - await wait(150) // ... for metrics to be collected - - expect(metricValue(T1, 'cold_entries')).to.eq(0) - expect(metricValue(T1, 'incoming_messages')).to.eq(totalInc[T1]) - expect(metricValue(T1, 'outgoing_messages')).to.eq(totalOut[T1]) - expect(metricValue(T1, 'processing_failures')).to.eq(totalFailed[T1]) - expect(metricValue(T1, 'remaining_entries')).to.eq(1) - expect(metricValue(T1, 'min_storage_time_in_seconds')).to.be.gte(1) - expect(metricValue(T1, 'med_storage_time_in_seconds')).to.be.gte(1) - expect(metricValue(T1, 'max_storage_time_in_seconds')).to.be.gte(1) - - expect(metricValue(T2, 'cold_entries')).to.eq(0) - expect(metricValue(T2, 'incoming_messages')).to.eq(totalInc[T2]) - expect(metricValue(T2, 'outgoing_messages')).to.eq(totalOut[T2]) - expect(metricValue(T2, 'processing_failures')).to.eq(totalFailed[T2]) - expect(metricValue(T2, 'remaining_entries')).to.eq(1) - expect(metricValue(T2, 'min_storage_time_in_seconds')).to.be.gte(1) - expect(metricValue(T2, 'med_storage_time_in_seconds')).to.be.gte(1) - expect(metricValue(T2, 'max_storage_time_in_seconds')).to.be.gte(1) - - // Wait for the second retry to be processd - while (currentRetryCount[T1] < 3) await wait(10) - while (currentRetryCount[T2] < 3) await wait(10) - await wait(600) // ... for metrics to be collected - - expect(metricValue(T1, 'cold_entries')).to.eq(0) - expect(metricValue(T1, 'incoming_messages')).to.eq(totalInc[T1]) - expect(metricValue(T1, 'outgoing_messages')).to.eq(totalOut[T1]) - expect(metricValue(T1, 'processing_failures')).to.eq(totalFailed[T1]) - expect(metricValue(T1, 'remaining_entries')).to.eq(0) - expect(metricValue(T1, 'min_storage_time_in_seconds')).to.eq(0) - expect(metricValue(T1, 'med_storage_time_in_seconds')).to.eq(0) - expect(metricValue(T1, 'max_storage_time_in_seconds')).to.eq(0) - - expect(metricValue(T2, 'cold_entries')).to.eq(0) - expect(metricValue(T2, 'incoming_messages')).to.eq(totalInc[T2]) - expect(metricValue(T2, 'outgoing_messages')).to.eq(totalOut[T2]) - expect(metricValue(T2, 'processing_failures')).to.eq(totalFailed[T2]) - expect(metricValue(T2, 'remaining_entries')).to.eq(0) - expect(metricValue(T2, 'min_storage_time_in_seconds')).to.eq(0) - expect(metricValue(T2, 'med_storage_time_in_seconds')).to.eq(0) - expect(metricValue(T2, 'max_storage_time_in_seconds')).to.eq(0) + // The storage_time gauges need a real second to elapse since the messages were enqueued — + // this is the one place the test fundamentally depends on wall-clock time. + const elapsed = Date.now() - timeOfInitialCall + if (elapsed < 1500) await wait(1500 - elapsed) + + await expectEventually(() => { + // Message is still being retried (>=1s aged) for both tenants. + expect(currentRetryCount[T1]).to.be.gte(2) + expect(currentRetryCount[T2]).to.be.gte(2) + + expect(metricValue(T1, 'cold_entries')).to.eq(0) + expect(metricValue(T1, 'incoming_messages')).to.eq(totalInc[T1]) + expect(metricValue(T1, 'outgoing_messages')).to.eq(totalOut[T1]) + expect(metricValue(T1, 'processing_failures')).to.eq(totalFailed[T1]) + expect(metricValue(T1, 'remaining_entries')).to.eq(1) + expect(metricValue(T1, 'min_storage_time_in_seconds')).to.be.gte(1) + expect(metricValue(T1, 'med_storage_time_in_seconds')).to.be.gte(1) + expect(metricValue(T1, 'max_storage_time_in_seconds')).to.be.gte(1) + + expect(metricValue(T2, 'cold_entries')).to.eq(0) + expect(metricValue(T2, 'incoming_messages')).to.eq(totalInc[T2]) + expect(metricValue(T2, 'outgoing_messages')).to.eq(totalOut[T2]) + expect(metricValue(T2, 'processing_failures')).to.eq(totalFailed[T2]) + expect(metricValue(T2, 'remaining_entries')).to.eq(1) + expect(metricValue(T2, 'min_storage_time_in_seconds')).to.be.gte(1) + expect(metricValue(T2, 'med_storage_time_in_seconds')).to.be.gte(1) + expect(metricValue(T2, 'max_storage_time_in_seconds')).to.be.gte(1) + }) + + // Final attempt — the message is delivered and removed from the outbox for both tenants. + await expectEventually(() => { + expect(currentRetryCount[T1]).to.be.gte(ATTEMPTS_TO_FAIL + 1) + expect(currentRetryCount[T2]).to.be.gte(ATTEMPTS_TO_FAIL + 1) + + expect(metricValue(T1, 'cold_entries')).to.eq(0) + expect(metricValue(T1, 'incoming_messages')).to.eq(totalInc[T1]) + expect(metricValue(T1, 'outgoing_messages')).to.eq(totalOut[T1]) + expect(metricValue(T1, 'processing_failures')).to.eq(totalFailed[T1]) + expect(metricValue(T1, 'remaining_entries')).to.eq(0) + expect(metricValue(T1, 'min_storage_time_in_seconds')).to.eq(0) + expect(metricValue(T1, 'med_storage_time_in_seconds')).to.eq(0) + expect(metricValue(T1, 'max_storage_time_in_seconds')).to.eq(0) + + expect(metricValue(T2, 'cold_entries')).to.eq(0) + expect(metricValue(T2, 'incoming_messages')).to.eq(totalInc[T2]) + expect(metricValue(T2, 'outgoing_messages')).to.eq(totalOut[T2]) + expect(metricValue(T2, 'processing_failures')).to.eq(totalFailed[T2]) + expect(metricValue(T2, 'remaining_entries')).to.eq(0) + expect(metricValue(T2, 'min_storage_time_in_seconds')).to.eq(0) + expect(metricValue(T2, 'med_storage_time_in_seconds')).to.eq(0) + expect(metricValue(T2, 'max_storage_time_in_seconds')).to.eq(0) + }) }) }) describe('given a taget service that fails unrecoverably', () => { let unboxedService - const didProcess = { [T1]: false, [T2]: false } - beforeAll(async () => { unboxedService = await cds.connect.to('ExternalServiceOne') unboxedService.before('call', req => { - didProcess[cds.context.tenant] = true totalFailed[cds.context.tenant] += 1 return req.reject({ status: 418, unrecoverable: true }) }) @@ -205,21 +223,19 @@ describe('queue metrics for multi tenant service', () => { GET('/odata/v4/proxy/proxyCallToExternalServiceOne', user[T2]) ]) - while (!didProcess[T1]) await wait(10) - while (!didProcess[T2]) await wait(10) - await wait(500) // ... for metrics to be collected - - expect(metricValue(T1, 'cold_entries')).to.eq(1) - expect(metricValue(T1, 'incoming_messages')).to.eq(totalInc[T1]) - expect(metricValue(T1, 'outgoing_messages')).to.eq(totalOut[T1]) - expect(metricValue(T1, 'processing_failures')).to.eq(totalFailed[T1]) - expect(metricValue(T1, 'remaining_entries')).to.eq(0) - - expect(metricValue(T2, 'cold_entries')).to.eq(1) - expect(metricValue(T2, 'incoming_messages')).to.eq(totalInc[T2]) - expect(metricValue(T2, 'outgoing_messages')).to.eq(totalOut[T2]) - expect(metricValue(T2, 'processing_failures')).to.eq(totalFailed[T2]) - expect(metricValue(T2, 'remaining_entries')).to.eq(0) + await expectEventually(() => { + expect(metricValue(T1, 'cold_entries')).to.eq(1) + expect(metricValue(T1, 'incoming_messages')).to.eq(totalInc[T1]) + expect(metricValue(T1, 'outgoing_messages')).to.eq(totalOut[T1]) + expect(metricValue(T1, 'processing_failures')).to.eq(totalFailed[T1]) + expect(metricValue(T1, 'remaining_entries')).to.eq(0) + + expect(metricValue(T2, 'cold_entries')).to.eq(1) + expect(metricValue(T2, 'incoming_messages')).to.eq(totalInc[T2]) + expect(metricValue(T2, 'outgoing_messages')).to.eq(totalOut[T2]) + expect(metricValue(T2, 'processing_failures')).to.eq(totalFailed[T2]) + expect(metricValue(T2, 'remaining_entries')).to.eq(0) + }) }) }) }) diff --git a/test/metrics-outbox.test.js b/test/metrics-outbox.test.js index 113a76ee..ab9f0d95 100644 --- a/test/metrics-outbox.test.js +++ b/test/metrics-outbox.test.js @@ -1,9 +1,4 @@ import { vi } from 'vitest' -// Mock console.dir to capture logs ConsoleMetricExporter writes -const consoleDirLogs = [] -vi.spyOn(console, 'dir').mockImplementation((...args) => { - consoleDirLogs.push(args) -}) const E1 = 'ExternalServiceOne' const E2 = 'ExternalServiceTwo' @@ -11,26 +6,46 @@ const E2 = 'ExternalServiceTwo' const cds = require('@sap/cds') const { setTimeout: wait } = require('node:timers/promises') +// Exported metric data is captured in-memory by MyInMemoryMetricReader (wired via the +// metrics-outbox profile in .cdsrc.json) instead of scraping ConsoleMetricExporter's console.dir. +const { latestDataPointValue, forceFlush, reset } = require('./bookshop/lib/MyInMemoryMetricReader') + const { expect, GET, axios } = cds.test(__dirname + '/bookshop', '--with-mocks', '--profile', 'metrics-outbox') axios.defaults.validateStatus = () => true function metricValue(metric, queuedServiceName) { - const mostRecentMetricLog = consoleDirLogs.findLast( - metricLog => metricLog[0].descriptor.name === `queue.${metric}` && metricLog[0].dataPoints?.length - )?.[0] - - const mestRecentQueueMetricData = mostRecentMetricLog?.dataPoints.find( - dataPoint => dataPoint.attributes['queue.name'] === queuedServiceName - ) - - if (!mestRecentQueueMetricData) return null + return latestDataPointValue(metric, { 'queue.name': queuedServiceName }) +} - return mestRecentQueueMetricData.value +// State-based wait: force the wired meter provider to collect + export, then re-run the assertion +// block. Replaces all fixed-time `wait(150)` sleeps — the loop completes the instant the in-memory +// queue statistics (kept fresh by the existing cds.spawn poller) reflect the asserted state. +// forceFlush() throws fast if the provider isn't wired, so a misconfigured profile fails loudly +// instead of busy-spinning the full timeout. +async function expectEventually(assertion, { timeout = 10000, interval = 25 } = {}) { + const start = Date.now() + let lastError + while (true) { + await forceFlush() + try { + assertion() + return + } catch (err) { + lastError = err + if (Date.now() - start >= timeout) throw lastError + await wait(interval) + } + } } const debugLog = (cds.log('telemetry').debug = vi.fn(() => {})) describe('queue metrics for single tenant service', () => { + if (cds.version.split('.')[0] < 9) { + test.skip('skipping tests for cds version < 9', () => {}) + return + } + let totalInc = { [E1]: 0, [E2]: 0 } let totalOut = { [E1]: 0, [E2]: 0 } let totalFailed = { [E1]: 0, [E2]: 0 } @@ -74,7 +89,7 @@ describe('queue metrics for single tenant service', () => { beforeEach(async () => { await DELETE.from('cds.outbox.Messages') - consoleDirLogs.length = 0 + reset() debugLog.mockClear() }) @@ -82,37 +97,43 @@ describe('queue metrics for single tenant service', () => { test('metrics are collected', async () => { await GET('/odata/v4/proxy/proxyCallToExternalServiceOne', admin) - await wait(150) // Wait for metrics to be collected - - expect(metricValue('cold_entries', E1)).to.eq(0) - expect(metricValue('remaining_entries', E1)).to.eq(0) - expect(metricValue('incoming_messages', E1)).to.eq(totalInc[E1]) - expect(metricValue('outgoing_messages', E1)).to.eq(totalOut[E1]) - expect(metricValue('processing_failures', E1)).to.eq(totalFailed[E1]) - expect(metricValue('min_storage_time_in_seconds', E1)).to.eq(0) - expect(metricValue('med_storage_time_in_seconds', E1)).to.eq(0) - expect(metricValue('max_storage_time_in_seconds', E1)).to.eq(0) + await expectEventually(() => { + expect(metricValue('cold_entries', E1)).to.eq(0) + expect(metricValue('remaining_entries', E1)).to.eq(0) + expect(metricValue('incoming_messages', E1)).to.eq(totalInc[E1]) + expect(metricValue('outgoing_messages', E1)).to.eq(totalOut[E1]) + expect(metricValue('processing_failures', E1)).to.eq(totalFailed[E1]) + expect(metricValue('min_storage_time_in_seconds', E1)).to.eq(0) + expect(metricValue('med_storage_time_in_seconds', E1)).to.eq(0) + expect(metricValue('max_storage_time_in_seconds', E1)).to.eq(0) + }) await GET('/odata/v4/proxy/proxyCallToExternalServiceTwo', admin) - await wait(150) // Wait for metrics to be collected - - expect(metricValue('cold_entries', E2)).to.eq(0) - expect(metricValue('remaining_entries', E2)).to.eq(0) - expect(metricValue('incoming_messages', E2)).to.eq(totalInc[E2]) - expect(metricValue('outgoing_messages', E2)).to.eq(totalOut[E2]) - expect(metricValue('processing_failures', E2)).to.eq(totalFailed[E2]) - expect(metricValue('min_storage_time_in_seconds', E2)).to.eq(0) - expect(metricValue('med_storage_time_in_seconds', E2)).to.eq(0) - expect(metricValue('max_storage_time_in_seconds', E2)).to.eq(0) + await expectEventually(() => { + expect(metricValue('cold_entries', E2)).to.eq(0) + expect(metricValue('remaining_entries', E2)).to.eq(0) + expect(metricValue('incoming_messages', E2)).to.eq(totalInc[E2]) + expect(metricValue('outgoing_messages', E2)).to.eq(totalOut[E2]) + expect(metricValue('processing_failures', E2)).to.eq(totalFailed[E2]) + expect(metricValue('min_storage_time_in_seconds', E2)).to.eq(0) + expect(metricValue('med_storage_time_in_seconds', E2)).to.eq(0) + expect(metricValue('max_storage_time_in_seconds', E2)).to.eq(0) + }) }) }) describe('given a target service that requires retries', () => { let currentRetryCount, customizedHandler + // Fail the first 3 attempts so the 4th delivers. With the queue's exp-backoff schedule + // (0.5s, 1.25s, 2.375s, ...), this places the 4th attempt at ~t=4.1s after enqueue — + // giving a comfortable ~3s window between "message has aged 1s in the queue" and + // "message is finally delivered and removed". Tightening that window is what made the + // original wall-clock-based test flaky. + const ATTEMPTS_TO_FAIL = 3 const customizedHandlerFor = E => req => { - if ((currentRetryCount[E] += 1) <= 2) { + if ((currentRetryCount[E] += 1) <= ATTEMPTS_TO_FAIL) { totalFailed[E] += 1 return req.reject({ status: 503 }) } @@ -142,88 +163,87 @@ describe('queue metrics for single tenant service', () => { test('storage time increases before message can be delivered', async () => { await GET('/odata/v4/proxy/proxyCallToExternalServiceOne', admin) await GET('/odata/v4/proxy/proxyCallToExternalServiceTwo', admin) - + // Reference time taken after GETs return — i.e. after both messages are persisted in the outbox. const timeOfInitialCall = Date.now() - await wait(150) // ... for metrics to be collected - expect(currentRetryCount[E1]).to.eq(1) - expect(currentRetryCount[E2]).to.eq(1) - - expect(metricValue('cold_entries', E1)).to.eq(0) - expect(metricValue('remaining_entries', E1)).to.eq(1) - expect(metricValue('incoming_messages', E1)).to.eq(totalInc[E1]) - expect(metricValue('outgoing_messages', E1)).to.eq(totalOut[E1]) - expect(metricValue('processing_failures', E1)).to.eq(totalFailed[E1]) - expect(metricValue('min_storage_time_in_seconds', E1)).to.eq(0) - expect(metricValue('med_storage_time_in_seconds', E1)).to.eq(0) - expect(metricValue('max_storage_time_in_seconds', E1)).to.eq(0) - - expect(metricValue('cold_entries', E2)).to.eq(0) - expect(metricValue('remaining_entries', E2)).to.eq(1) - expect(metricValue('incoming_messages', E2)).to.eq(totalInc[E2]) - expect(metricValue('outgoing_messages', E2)).to.eq(totalOut[E2]) - expect(metricValue('processing_failures', E2)).to.eq(totalFailed[E2]) - expect(metricValue('min_storage_time_in_seconds', E2)).to.eq(0) - expect(metricValue('med_storage_time_in_seconds', E2)).to.eq(0) - expect(metricValue('max_storage_time_in_seconds', E2)).to.eq(0) - - // Wait for the first retry to be initiated - while (currentRetryCount[E1] < 2) await wait(10) - while (currentRetryCount[E2] < 2) await wait(10) - await wait(150) // ... for the retry to be processed and metrics to be collected - expect(currentRetryCount[E1]).to.eq(2) - expect(currentRetryCount[E2]).to.eq(2) - - // Wait until at least 1 second has passed since the initial call - const timeAfterFirstRetry = Date.now() - if (timeAfterFirstRetry - timeOfInitialCall < 1000) { - await wait(1000 - (timeAfterFirstRetry - timeOfInitialCall)) - } + // The queue has made its first delivery attempt for both services (handler invocation count is + // observed directly via the rejecting `before('call')` handler — pure CAP event observation). + await expectEventually(() => { + expect(currentRetryCount[E1]).to.be.gte(1) + expect(currentRetryCount[E2]).to.be.gte(1) + + expect(metricValue('cold_entries', E1)).to.eq(0) + expect(metricValue('remaining_entries', E1)).to.eq(1) + expect(metricValue('incoming_messages', E1)).to.eq(totalInc[E1]) + expect(metricValue('outgoing_messages', E1)).to.eq(totalOut[E1]) + expect(metricValue('processing_failures', E1)).to.eq(totalFailed[E1]) + expect(metricValue('min_storage_time_in_seconds', E1)).to.eq(0) + expect(metricValue('med_storage_time_in_seconds', E1)).to.eq(0) + expect(metricValue('max_storage_time_in_seconds', E1)).to.eq(0) + + expect(metricValue('cold_entries', E2)).to.eq(0) + expect(metricValue('remaining_entries', E2)).to.eq(1) + expect(metricValue('incoming_messages', E2)).to.eq(totalInc[E2]) + expect(metricValue('outgoing_messages', E2)).to.eq(totalOut[E2]) + expect(metricValue('processing_failures', E2)).to.eq(totalFailed[E2]) + expect(metricValue('min_storage_time_in_seconds', E2)).to.eq(0) + expect(metricValue('med_storage_time_in_seconds', E2)).to.eq(0) + expect(metricValue('max_storage_time_in_seconds', E2)).to.eq(0) + }) - await wait(150) // ... for metrics to be collected again - - expect(metricValue('cold_entries', E1)).to.eq(0) - expect(metricValue('remaining_entries', E1)).to.eq(1) - expect(metricValue('incoming_messages', E1)).to.eq(totalInc[E1]) - expect(metricValue('outgoing_messages', E1)).to.eq(totalOut[E1]) - expect(metricValue('processing_failures', E1)).to.eq(totalFailed[E1]) - expect(metricValue('min_storage_time_in_seconds', E1)).to.be.gte(1) - expect(metricValue('med_storage_time_in_seconds', E1)).to.be.gte(1) - expect(metricValue('max_storage_time_in_seconds', E1)).to.be.gte(1) - - expect(metricValue('cold_entries', E2)).to.eq(0) - expect(metricValue('remaining_entries', E2)).to.eq(1) - expect(metricValue('incoming_messages', E2)).to.eq(totalInc[E2]) - expect(metricValue('outgoing_messages', E2)).to.eq(totalOut[E2]) - expect(metricValue('processing_failures', E2)).to.eq(totalFailed[E2]) - expect(metricValue('min_storage_time_in_seconds', E2)).to.be.gte(1) - expect(metricValue('med_storage_time_in_seconds', E2)).to.be.gte(1) - expect(metricValue('max_storage_time_in_seconds', E2)).to.be.gte(1) - - // Wait for the second retry to be initiated - while (currentRetryCount[E1] < 3) await wait(10) - while (currentRetryCount[E2] < 3) await wait(10) - await wait(150) // ... for the retry to be processed and metrics to be collected - expect(currentRetryCount[E1]).to.eq(3) - expect(currentRetryCount[E2]).to.eq(3) - - expect(metricValue('cold_entries', E1)).to.eq(0) - expect(metricValue('remaining_entries', E1)).to.eq(0) - expect(metricValue('incoming_messages', E1)).to.eq(totalInc[E1]) - expect(metricValue('outgoing_messages', E1)).to.eq(totalOut[E1]) - expect(metricValue('processing_failures', E1)).to.eq(totalFailed[E1]) - expect(metricValue('min_storage_time_in_seconds', E1)).to.eq(0) - expect(metricValue('med_storage_time_in_seconds', E1)).to.eq(0) - expect(metricValue('max_storage_time_in_seconds', E1)).to.eq(0) - - expect(metricValue('cold_entries', E2)).to.eq(0) - expect(metricValue('remaining_entries', E2)).to.eq(0) - expect(metricValue('incoming_messages', E2)).to.eq(totalInc[E2]) - expect(metricValue('outgoing_messages', E2)).to.eq(totalOut[E2]) - expect(metricValue('processing_failures', E2)).to.eq(totalFailed[E2]) - expect(metricValue('min_storage_time_in_seconds', E2)).to.eq(0) - expect(metricValue('med_storage_time_in_seconds', E2)).to.eq(0) - expect(metricValue('max_storage_time_in_seconds', E2)).to.eq(0) + // The storage_time gauges need a real second to elapse since the messages were enqueued — + // this is the one place the test fundamentally depends on wall-clock time. + const elapsed = Date.now() - timeOfInitialCall + if (elapsed < 1500) await wait(1500 - elapsed) + + await expectEventually(() => { + // Either still on attempt 2 (waiting to retry) or on attempt 3 (delivered) — both are fine + // for these assertions, the message has been in the queue >=1s either way. + expect(currentRetryCount[E1]).to.be.gte(2) + expect(currentRetryCount[E2]).to.be.gte(2) + + expect(metricValue('cold_entries', E1)).to.eq(0) + expect(metricValue('remaining_entries', E1)).to.eq(1) + expect(metricValue('incoming_messages', E1)).to.eq(totalInc[E1]) + expect(metricValue('outgoing_messages', E1)).to.eq(totalOut[E1]) + expect(metricValue('processing_failures', E1)).to.eq(totalFailed[E1]) + expect(metricValue('min_storage_time_in_seconds', E1)).to.be.gte(1) + expect(metricValue('med_storage_time_in_seconds', E1)).to.be.gte(1) + expect(metricValue('max_storage_time_in_seconds', E1)).to.be.gte(1) + + expect(metricValue('cold_entries', E2)).to.eq(0) + expect(metricValue('remaining_entries', E2)).to.eq(1) + expect(metricValue('incoming_messages', E2)).to.eq(totalInc[E2]) + expect(metricValue('outgoing_messages', E2)).to.eq(totalOut[E2]) + expect(metricValue('processing_failures', E2)).to.eq(totalFailed[E2]) + expect(metricValue('min_storage_time_in_seconds', E2)).to.be.gte(1) + expect(metricValue('med_storage_time_in_seconds', E2)).to.be.gte(1) + expect(metricValue('max_storage_time_in_seconds', E2)).to.be.gte(1) + }) + + // Final attempt — the message is delivered and removed from the outbox. + await expectEventually(() => { + expect(currentRetryCount[E1]).to.be.gte(ATTEMPTS_TO_FAIL + 1) + expect(currentRetryCount[E2]).to.be.gte(ATTEMPTS_TO_FAIL + 1) + + expect(metricValue('cold_entries', E1)).to.eq(0) + expect(metricValue('remaining_entries', E1)).to.eq(0) + expect(metricValue('incoming_messages', E1)).to.eq(totalInc[E1]) + expect(metricValue('outgoing_messages', E1)).to.eq(totalOut[E1]) + expect(metricValue('processing_failures', E1)).to.eq(totalFailed[E1]) + expect(metricValue('min_storage_time_in_seconds', E1)).to.eq(0) + expect(metricValue('med_storage_time_in_seconds', E1)).to.eq(0) + expect(metricValue('max_storage_time_in_seconds', E1)).to.eq(0) + + expect(metricValue('cold_entries', E2)).to.eq(0) + expect(metricValue('remaining_entries', E2)).to.eq(0) + expect(metricValue('incoming_messages', E2)).to.eq(totalInc[E2]) + expect(metricValue('outgoing_messages', E2)).to.eq(totalOut[E2]) + expect(metricValue('processing_failures', E2)).to.eq(totalFailed[E2]) + expect(metricValue('min_storage_time_in_seconds', E2)).to.eq(0) + expect(metricValue('med_storage_time_in_seconds', E2)).to.eq(0) + expect(metricValue('max_storage_time_in_seconds', E2)).to.eq(0) + }) }) }) @@ -256,25 +276,25 @@ describe('queue metrics for single tenant service', () => { await GET('/odata/v4/proxy/proxyCallToExternalServiceOne', admin) await GET('/odata/v4/proxy/proxyCallToExternalServiceTwo', admin) - await wait(150) // ... for metrics to be collected - - expect(metricValue('cold_entries', E1)).to.eq(1) - expect(metricValue('remaining_entries', E1)).to.eq(0) - expect(metricValue('incoming_messages', E1)).to.eq(totalInc[E1]) - expect(metricValue('outgoing_messages', E1)).to.eq(totalOut[E1]) - expect(metricValue('processing_failures', E1)).to.eq(totalFailed[E1]) - expect(metricValue('min_storage_time_in_seconds', E1)).to.eq(0) - expect(metricValue('med_storage_time_in_seconds', E1)).to.eq(0) - expect(metricValue('max_storage_time_in_seconds', E1)).to.eq(0) - - expect(metricValue('cold_entries', E2)).to.eq(1) - expect(metricValue('remaining_entries', E2)).to.eq(0) - expect(metricValue('incoming_messages', E2)).to.eq(totalInc[E2]) - expect(metricValue('outgoing_messages', E2)).to.eq(totalOut[E2]) - expect(metricValue('processing_failures', E2)).to.eq(totalFailed[E2]) - expect(metricValue('min_storage_time_in_seconds', E2)).to.eq(0) - expect(metricValue('med_storage_time_in_seconds', E2)).to.eq(0) - expect(metricValue('max_storage_time_in_seconds', E2)).to.eq(0) + await expectEventually(() => { + expect(metricValue('cold_entries', E1)).to.eq(1) + expect(metricValue('remaining_entries', E1)).to.eq(0) + expect(metricValue('incoming_messages', E1)).to.eq(totalInc[E1]) + expect(metricValue('outgoing_messages', E1)).to.eq(totalOut[E1]) + expect(metricValue('processing_failures', E1)).to.eq(totalFailed[E1]) + expect(metricValue('min_storage_time_in_seconds', E1)).to.eq(0) + expect(metricValue('med_storage_time_in_seconds', E1)).to.eq(0) + expect(metricValue('max_storage_time_in_seconds', E1)).to.eq(0) + + expect(metricValue('cold_entries', E2)).to.eq(1) + expect(metricValue('remaining_entries', E2)).to.eq(0) + expect(metricValue('incoming_messages', E2)).to.eq(totalInc[E2]) + expect(metricValue('outgoing_messages', E2)).to.eq(totalOut[E2]) + expect(metricValue('processing_failures', E2)).to.eq(totalFailed[E2]) + expect(metricValue('min_storage_time_in_seconds', E2)).to.eq(0) + expect(metricValue('med_storage_time_in_seconds', E2)).to.eq(0) + expect(metricValue('max_storage_time_in_seconds', E2)).to.eq(0) + }) }) }) diff --git a/test/metrics.test.js b/test/metrics.test.js index 78765d24..6582b7a3 100644 --- a/test/metrics.test.js +++ b/test/metrics.test.js @@ -1,36 +1,90 @@ -// process.env.HOST_METRICS_RETAIN_SYSTEM = 'true' //> with this the test would fail -process.env.HOST_METRICS_LOG_SYSTEM = 'true' +// Integration tests for metrics collection — asserts on what is actually COLLECTED (which +// instruments produce datapoints, and how many), captured in-memory by MyInMemoryMetricReader +// (wired via the `metrics` profile in .cdsrc.json) instead of scraping ConsoleMetricExporter's +// log output. The formatting of those metrics is unit-tested in console-metric-exporter.test.js. const cds = require('@sap/cds') +const { setTimeout: wait } = require('node:timers/promises') + +const { captured, forceFlush, reset } = require('./bookshop/lib/MyInMemoryMetricReader') + const { expect, GET } = cds.test(__dirname + '/bookshop', '--profile', 'metrics') -const log = cds.test.log() -const wait = require('node:timers/promises').setTimeout +// State-based wait: force the wired meter provider to collect + export, then re-run the assertion +// block. Replaces fixed-time sleeps — the loop completes the instant the captured datapoints +// reflect the asserted state. forceFlush() throws fast if the provider isn't wired, so a +// misconfigured profile fails loudly instead of busy-spinning the full timeout. +async function expectEventually(assertion, { timeout = 10000, interval = 25 } = {}) { + const start = Date.now() + let lastError + while (true) { + await forceFlush() + try { + assertion() + return + } catch (err) { + lastError = err + if (Date.now() - start >= timeout) throw lastError + await wait(interval) + } + } +} + +// All metric descriptor names present across every captured export. +function capturedMetricNames() { + const names = new Set() + for (const rm of captured) { + for (const scopeMetrics of rm.scopeMetrics) { + for (const metric of scopeMetrics.metrics) names.add(metric.descriptor.name) + } + } + return names +} + +// Most recent captured MetricData for the given descriptor name (newest export first). +function latestMetric(name) { + for (let i = captured.length - 1; i >= 0; i--) { + for (const scopeMetrics of captured[i].scopeMetrics) { + for (const metric of scopeMetrics.metrics) { + if (metric.descriptor.name === name && metric.dataPoints?.length) return metric + } + } + } + return null +} describe('metrics', () => { const admin = { auth: { username: 'alice' } } - beforeEach(log.clear) + beforeEach(reset) test('system metrics are not collected by default', async () => { const { status } = await GET('/odata/v4/admin/Books', admin) expect(status).to.equal(200) - await wait(100) - - expect(log.output).to.match(/process/i) - expect(log.output).not.to.match(/network/i) + await expectEventually(() => { + const names = capturedMetricNames() + // process.* host metrics ARE collected out of the box ... + expect([...names].some(n => n.startsWith('process.'))).to.be.true + // ... but system.* (network/cpu/memory) collection is NOT enabled by default. + expect([...names].some(n => n.startsWith('system.'))).to.be.false + expect([...names].some(n => n.includes('network'))).to.be.false + }) }) - test('other metrics with multiple datapoints are logged as array', async () => { + test('other metrics can carry multiple datapoints', async () => { const { status } = await GET('/odata/v4/admin/Books', admin) expect(status).to.equal(200) - await wait(200) - - // nodejs.eventloop.time has multiple datapoints (active + idle) → logged as array - expect(log.output).to.match(/nodejs\.eventloop\.time: \[/) - // nodejs.eventloop.utilization has single datapoint → logged unwrapped (not as array) - expect(log.output).to.match(/nodejs\.eventloop\.utilization: \{/) + await expectEventually(() => { + // nodejs.eventloop.time is collected with multiple datapoints (active + idle) ... + const time = latestMetric('nodejs.eventloop.time') + expect(time).to.exist + expect(time.dataPoints.length).to.be.greaterThan(1) + // ... whereas nodejs.eventloop.utilization is a single datapoint. + const utilization = latestMetric('nodejs.eventloop.utilization') + expect(utilization).to.exist + expect(utilization.dataPoints.length).to.equal(1) + }) }) })