test: capture outbox+console metrics via in-memory reader & unit-test ConsoleMetricExporter - #479
Conversation
Replace the console.dir spy on ConsoleMetricExporter output in the three outbox-metrics suites with an in-memory OpenTelemetry metric reader (MyInMemoryMetricReader), mirroring MyInMemorySpanExporter. The reader is exporter-shaped so lib/metrics wraps it in a PeriodicExportingMetricReader, keeping exportIntervalMillis working; it captures ResourceMetrics into a module-level array with helpers to look up the latest datapoint by metric name and attributes (queue.name / tenant). Fold in PR #445's expectEventually() polling helper (hardened: forceFlush fails fast if the meter provider is not wired instead of silently no-op'ing) to replace the fixed wait() sleeps for metric collection. Wire the reader via the metrics-outbox / metrics-outbox-disabled profiles in .cdsrc.json.
SummaryThe following content is AI-generated and provides a summary of the pull request: test: Replace Console Spying with In-Memory Metric Reader + State-Based Polling in Outbox TestsTest🧪 Test Refactor: Replaces fragile Changes
GitHub Issues
PR Bot InformationVersion:
|
![hyperspace-pr-bot[bot]](https://avatars.githubusercontent.com/u/2531208?s=60&v=4){kind=small}
There was a problem hiding this comment.
The typo 'given a taget service that fails unrecoverably' (should be 'given a target service...') in test/metrics-outbox-multitenant.test.js was pre-existing and not in the diff, so it cannot be commented on inline.
Summary: The PR is a well-motivated refactor — replacing brittle console-spy polling with a proper in-memory OpenTelemetry metric reader and state-based polling. The key issues flagged are: (1) isCounter() dispatches solely based on whether counterSeries contains a name, which breaks on the very first poll after reset() clears captured but leaves counterSeries populated from earlier tests — a hard-coded set of counter metric names would be more reliable; and (2) in metrics-outbox-multitenant.test.js, the elapsed calculation immediately after timeOfInitialCall is always ~0ms and provides no real debounce for the wall-clock wait, effectively always sleeping the full 1500ms while giving a false impression of precision.
PR Bot Information
Version: 1.29.18
- LLM:
anthropic--claude-4.6-sonnet - Correlation ID:
0cbd0f50-955d-11f1-9359-9ad658e69c4a - Event Trigger:
pull_request.opened - File Content Strategy: Full file content
| function isCounter(metricName) { | ||
| const name = `queue.${metricName}` | ||
| for (const entry of counterSeries.values()) { | ||
| if (entry.name === name) return true | ||
| } | ||
| return false | ||
| } |
There was a problem hiding this comment.
Logic Error: isCounter can return a stale true after reset() causes incorrect dispatch in latestDataPointValue
reset() clears captured (gauge state) but intentionally leaves counterSeries intact. However, isCounter checks counterSeries, so if a metric name was ever a counter in a previous test, isCounter will permanently return true for it — meaning latestDataPointValue will always route to counterTotal for that name, even in a test where the counter hasn't been exported yet (e.g. the very first expectEventually poll). counterTotal then returns the stale running total from the prior test rather than null, and a gauge lookup is never attempted for that metric name in the same process run.
In practice this affects any metric that is both a counter (incoming_messages, outgoing_messages, processing_failures) and called with no matching attributes after reset(): counterTotal returns the old accumulated value instead of null. The found guard in counterTotal will still match because counterSeries was not cleared.
The design intent (counters intentionally accumulate across tests) seems correct, but isCounter driving the dispatch between two completely different lookup strategies is fragile. Consider making the metric type distinction explicit (a separate hard-coded set of counter names, or checking DataPointType at query time) rather than relying on whether counterSeries happens to contain the name.
| function isCounter(metricName) { | |
| const name = `queue.${metricName}` | |
| for (const entry of counterSeries.values()) { | |
| if (entry.name === name) return true | |
| } | |
| return false | |
| } | |
| // Names of metrics that are SUM (counter) instruments — the three counters the queue plugin | |
| // registers. Used to dispatch latestDataPointValue without relying on counterSeries being populated. | |
| 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}`) | |
| } |
Double-check suggestion before committing. Edit this comment for amendments.
Please provide feedback on the review comment by checking the appropriate box:
- 🌟 Awesome comment, a human might have missed that.
- ✅ Helpful comment
- 🤷 Neutral
- ❌ This comment is not helpful
| const elapsed = Date.now() - timeOfInitialCall | ||
| if (elapsed < 1500) await wait(1500 - elapsed) |
There was a problem hiding this comment.
Logic Error: elapsed is always ~0ms, making the 1500ms wall-clock wait ineffective
timeOfInitialCall is captured immediately after the await Promise.all([...]) GETs return. The very next two lines compute elapsed = Date.now() - timeOfInitialCall, which will always be essentially 0ms (a few microseconds of JavaScript execution). The conditional if (elapsed < 1500) await wait(1500 - elapsed) therefore always waits the full 1500ms — the elapsed subtraction provides no benefit and the comment "Reference time taken after GETs return" is misleading. The single-tenant test (metrics-outbox.test.js) has the same pattern but is correct because it does real work (two expectEventually polls) between capturing timeOfInitialCall and checking elapsed. Here there is no such work in between.
Consider removing the elapsed calculation and just using await wait(1500) directly, or moving timeOfInitialCall to before the GETs so the time the messages spent queuing (during the GET itself) counts toward the wait.
| const elapsed = Date.now() - timeOfInitialCall | |
| if (elapsed < 1500) await wait(1500 - elapsed) | |
| await wait(Math.max(0, 1500 - (Date.now() - timeOfInitialCall))) |
Double-check suggestion before committing. Edit this comment for amendments.
Please provide feedback on the review comment by checking the appropriate box:
- 🌟 Awesome comment, a human might have missed that.
- ✅ Helpful comment
- 🤷 Neutral
- ❌ This comment is not helpful
| // 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). | ||
| const counterSeries = new Map() |
There was a problem hiding this comment.
Logic Error: Module-level captured and counterSeries are shared across test files that run in the same worker process
Both captured and counterSeries are module-level singletons. When metrics-outbox.test.js and metrics-outbox-multitenant.test.js run in the same Vitest worker (or sequentially with --pool=forks but in the same process), they share these maps because Node.js module cache is process-wide. reset() only clears captured; counterSeries accumulates entries from both suites. If both files register counters for the same metric name under the same attribute set (e.g. no attribute overlap), counterTotal will return a sum that includes both suites' increments.
The existing design works only if Vitest isolates each test file in its own worker process. Consider documenting this assumption explicitly, or exporting a fullReset() that also clears counterSeries for use in a global test setup/teardown.
| // 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). | |
| const counterSeries = new Map() | |
| // 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: both `captured` and `counterSeries` are process-level singletons. This is safe only when | |
| // each test file runs in its own isolated worker process (Vitest's default with --pool=forks or | |
| // --isolate). If two test files sharing this module run in the same process, their counter totals | |
| // will bleed into each other. | |
| const counterSeries = new Map() |
Double-check suggestion before committing. Edit this comment for amendments.
Please provide feedback on the review comment by checking the appropriate box:
- 🌟 Awesome comment, a human might have missed that.
- ✅ Helpful comment
- 🤷 Neutral
- ❌ This comment is not helpful
| // Silence noisy debug logging without asserting on it here | ||
| cds.log('telemetry').debug = vi.fn(() => {}) |
There was a problem hiding this comment.
why is this necessary?
There was a problem hiding this comment.
Good catch — it wasn't. This mock only silenced debug noise and was never asserted on, so I removed it (and the now-orphaned vi import) in d24ebd3.
| } | ||
| } | ||
|
|
||
| const debugLog = (cds.log('telemetry').debug = vi.fn(() => {})) |
There was a problem hiding this comment.
why is this still needed?
There was a problem hiding this comment.
This one is still needed: unlike the multitenant file, debugLog here backs a real assertion at line ~313 — expect(debugLog.mock.calls.some(log => log[0].match(/unknown service/i))).to.be.true — verifying the 'unknown service' debug path. It's the one debug mock that's an assertion target, not just noise-silencing. If you'd rather assert that via the in-memory exporter instead (per #478), I can fold that in as a follow-up.
Addresses review on #479: the multitenant suite mocked cds.log('telemetry').debug purely to silence noise and never asserted on it — remove it (and the now-orphaned vi import). The single-tenant suite keeps its debug mock because it backs a real 'unknown service' assertion.
sjvans
changed the title
…er; drop tracing-attributes profile (#478) (#490) ## What Group 1 of #478. Converts the three tracing tests that still spied on `console.dir` to read structured `ReadableSpan` objects directly from the in-memory span exporter: - `test/tracing-remote-cloudsdk.test.js` - `test/tracing-remote-native.test.js` - `test/tracing-span-names.test.js` Each now uses `--profile tracing-in-memory` (which wires `MyInMemorySpanExporter` via `.cdsrc.json`) and reads over `captured` (the module-level array of `ReadableSpan`s) instead of the `console.dir` spy. `beforeEach(reset)` clears the buffer per test. All existing assertions are preserved verbatim — `instrumentationScope.name` filters (`@cap-js/telemetry`, `@opentelemetry/instrumentation-undici`), span names, and attributes (`code.function.name`, `db.query.text`, `sap.btp.destination`, the no-raw-SQL / no-URL-in-span-name checks). `captured` holds full ReadableSpans with `instrumentationScope`, so the filters just point at `captured`. No flush/poll was needed: the spans for these single request/DB ops appear synchronously in `captured` after the awaited call. In `tracing-span-names.test.js`, `data.reset()` is itself traced, so the buffer is cleared *after* reset (mirroring `tracing-attributes.test.js`). ## Why No more `console.dir` spying in the tracing tests. With all three files migrated, the `[tracing-attributes]` profile in `test/bookshop/.cdsrc.json` has no remaining consumers (verified: only these 3 used it; `tracing-attributes.test.js` despite its name already uses `tracing-in-memory`), so it is removed. This also resolves the deferred "rename tracing-attributes → tracing-console" note — the profile simply goes away. Test-only change. No lib change, no CHANGELOG. Refs #478 (group 1 only; group 2 done via #479, group 3 stays).
1 participant
What
Consolidates all outbox/metrics test-quality work into one PR (formerly split as #479 + the stacked #480).
test/bookshop/lib/MyInMemoryMetricReader.js, the metrics counterpart toMyInMemorySpanExporter(feat: trace queue worker transactions + structured span test infrastructure #465). Mirrors production DELTA temporality: SUM counters are accumulated across flushes into per-series running totals; GAUGE datapoints keep the latest absolute value. Wired via themetrics-outbox,metrics-outbox-disabled, andmetricsprofiles in.cdsrc.json.metrics-outbox*.test.jssuites drop theconsole.dirspy and fixedwait()sleeps in favor of the reader + anexpectEventually()force-flush polling helper (fails fast if the meter provider isn't wired). Folds in chore: more stable outbox metrics tests #445's polling approach.test/console-metric-exporter.test.js, a pure unit test of the exporter's formatting (db.pool table, queue table, other single-vs-array, tenant variants, host-metrics aggregation, shutdown→FAILED), mirroringconsole-span-exporter.test.js.metrics.test.jsconverted from scrapingcds.test.log()output to asserting on the in-memory reader's datapoints.Metrics testing now mirrors the tracing side exactly: a to-console unit test plus in-memory-exporter–based integration tests.
Why
Follow-up to #465 (span test infra): eliminate console/log spying in the metrics suite and give
ConsoleMetricExporterdirect unit coverage.Review addressed
COUNTER_METRIC_NAMESdispatch forisCounter; real wall-clock debounce in the multitenant test; isolation NOTE on the module-level singletons.debugLogmock — it backs a realunknown serviceassertion.Test-only change (no
lib/change), so no CHANGELOG entry — consistent with #465/#474/#476.closes #478
Supersedes #445 and #480 (both folded in here) — I'll close them once this merges.