test: add ConsoleMetricExporter unit test + assert metrics via in-memory reader

test/bookshop/.cdsrc.json

@@ -30,6 +30,10 @@
         "metrics": {
           "config": {
             "exportIntervalMillis": 100
+          },
+          "exporter": {
+            "module": "./lib/MyInMemoryMetricReader.js",
+            "class": "MyInMemoryMetricReader"
           }
         }
       }

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()
+        })
+      })
+    })
+  })
+})

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)
+    })
   })
 })