diff --git a/test/metrics-outbox-disabled.test.js b/test/metrics-outbox-disabled.test.js index 35f2ee88..2fcc0267 100644 --- a/test/metrics-outbox-disabled.test.js +++ b/test/metrics-outbox-disabled.test.js @@ -1,11 +1,11 @@ -// Mock console.dir to capture logs ConsoleMetricExporter writes +// Capture exported metric data via ConsoleMetricExporter's console.dir output const consoleDirLogs = [] jest.spyOn(console, 'dir').mockImplementation((...args) => { consoleDirLogs.push(args) }) const cds = require('@sap/cds') -const { setTimeout: wait } = require('node:timers/promises') +const { metrics } = require('@opentelemetry/api') const { expect, GET } = cds.test(__dirname + '/bookshop', '--with-mocks', '--profile', 'metrics-outbox-disabled') @@ -41,7 +41,10 @@ describe('queue metrics is disabled', () => { await GET('/odata/v4/proxy/proxyCallToExternalServiceOne', admin) - await wait(150) // Wait for metrics to be collected + // Drain the metric pipeline deterministically. If queue metrics were enabled they'd appear + // in `consoleDirLogs` right after this returns; since they're disabled, the assertions below + // verify nothing was emitted — no sleep needed. + await metrics.getMeterProvider().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 5205d7c4..8f1363a2 100644 --- a/test/metrics-outbox-multitenant.test.js +++ b/test/metrics-outbox-multitenant.test.js @@ -1,10 +1,11 @@ -// Mock console.dir to capture logs ConsoleMetricExporter writes +// Capture exported metric data via ConsoleMetricExporter's console.dir output const consoleDirLogs = [] jest.spyOn(console, 'dir').mockImplementation((...args) => { consoleDirLogs.push(args) }) const cds = require('@sap/cds') +const { metrics } = require('@opentelemetry/api') const { setTimeout: wait } = require('node:timers/promises') const { expect, GET, axios } = cds.test( @@ -28,6 +29,25 @@ function metricValue(tenant, metric) { return mostRecentTenantDataPoint ? mostRecentTenantDataPoint.value : null } +// State-based wait: force the metric provider to export, then re-run the assertion block. +// Replaces all fixed-time `wait(150)`-style sleeps — the loop completes the instant the in-memory +// queue statistics (kept fresh by the existing cds.spawn poller) reflect the asserted state. +async function expectEventually(assertion, { timeout = 10000, interval = 25 } = {}) { + const start = Date.now() + let lastError + while (true) { + await metrics.getMeterProvider().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', () => { const T1 = 'tenant_1' const T2 = 'tenant_2' @@ -78,34 +98,37 @@ 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 — see metrics-outbox.test.js for rationale. + 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 }) } @@ -123,76 +146,77 @@ describe('queue metrics for multi tenant service', () => { test('storage time increases before message can be delivered', async () => { if (cds.version.split('.')[0] < 9) return - const timeOfInitialCall = Date.now() await Promise.all([ GET('/odata/v4/proxy/proxyCallToExternalServiceOne', user[T1]), GET('/odata/v4/proxy/proxyCallToExternalServiceOne', user[T2]) ]) + // Reference time taken after GETs return — i.e. after both messages are persisted in the outbox. + const timeOfInitialCall = Date.now() - // 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) + // Wait for both tenants to make their second attempt (= first retry). + await expectEventually(() => { + expect(currentRetryCount[T1]).to.be.gte(2) + expect(currentRetryCount[T2]).to.be.gte(2) + }) + + // 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(() => { + 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. + 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 }) }) @@ -210,21 +234,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 d0b4b747..ee7807b1 100644 --- a/test/metrics-outbox.test.js +++ b/test/metrics-outbox.test.js @@ -1,4 +1,4 @@ -// Mock console.dir to capture logs ConsoleMetricExporter writes +// Capture exported metric data via ConsoleMetricExporter's console.dir output const consoleDirLogs = [] jest.spyOn(console, 'dir').mockImplementation((...args) => { consoleDirLogs.push(args) @@ -8,6 +8,7 @@ const E1 = 'ExternalServiceOne' const E2 = 'ExternalServiceTwo' const cds = require('@sap/cds') +const { metrics } = require('@opentelemetry/api') const { setTimeout: wait } = require('node:timers/promises') const { expect, GET, axios } = cds.test(__dirname + '/bookshop', '--with-mocks', '--profile', 'metrics-outbox') @@ -27,6 +28,25 @@ function metricValue(metric, queuedServiceName) { return mestRecentQueueMetricData.value } +// State-based wait: force the metric provider to 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. +async function expectEventually(assertion, { timeout = 10000, interval = 25 } = {}) { + const start = Date.now() + let lastError + while (true) { + await metrics.getMeterProvider().forceFlush?.() + try { + assertion() + return + } catch (err) { + lastError = err + if (Date.now() - start >= timeout) throw lastError + await wait(interval) + } + } +} + const debugLog = (cds.log('telemetry').debug = jest.fn(() => {})) describe('queue metrics for single tenant service', () => { @@ -86,37 +106,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 }) } @@ -146,88 +172,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) + }) }) }) @@ -260,25 +285,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) + }) }) })