From 27cec3bf794cdaca773f02f425b00a4c5bf590b6 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 11:51:49 +0100 Subject: [PATCH 01/23] rm cds._telemetry --- lib/index.js | 12 ++++++------ lib/tracing/index.js | 12 ++++++------ 2 files changed, 12 insertions(+), 12 deletions(-) diff --git a/lib/index.js b/lib/index.js index d9d37f79..edec0902 100644 --- a/lib/index.js +++ b/lib/index.js @@ -3,7 +3,7 @@ const LOG = cds.log('telemetry') const { diag } = require('@opentelemetry/api') const { registerInstrumentations } = require('@opentelemetry/instrumentation') -const { ATTR_SERVICE_NAME, ATTR_SERVICE_VERSION } = require('@opentelemetry/semantic-conventions') +// const { ATTR_SERVICE_NAME, ATTR_SERVICE_VERSION } = require('@opentelemetry/semantic-conventions') const tracing = require('./tracing') const metrics = require('./metrics') @@ -47,11 +47,11 @@ module.exports = function () { const resource = getResource() - // REVISIT: better way to make available? - cds._telemetry = { - name: resource.attributes[ATTR_SERVICE_NAME], - version: resource.attributes[ATTR_SERVICE_VERSION] - } + // // REVISIT: better way to make available? + // cds._telemetry = { + // name: resource.attributes[ATTR_SERVICE_NAME], + // version: resource.attributes[ATTR_SERVICE_VERSION] + // } /* * setup tracing diff --git a/lib/tracing/index.js b/lib/tracing/index.js index 053d189a..7b10826f 100644 --- a/lib/tracing/index.js +++ b/lib/tracing/index.js @@ -158,13 +158,13 @@ module.exports = resource => { tracerProvider.addSpanProcessor(spanProcessor) } - // REVISIT: better way to set/ pass tracer? - cds._telemetry.tracer = trace.getTracer('@cap-js/telemetry', require('../../package.json').version) + // // REVISIT: better way to set/ pass tracer? + // cds._telemetry.tracer = trace.getTracer('@cap-js/telemetry', require('../../package.json').version) - // REVISIT: only start tracing once served - cds.on('served', () => { - cds._telemetry.tracer._active = true - }) + // // REVISIT: only start tracing once served + // cds.on('served', () => { + // cds._telemetry.tracer._active = true + // }) // clear sap passport for new tx if (process.env.SAP_PASSPORT) { From 1e779f0f2c64cb1ca449ae102530fdc7037e0af2 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 11:58:59 +0100 Subject: [PATCH 02/23] targetObj -> that --- lib/tracing/trace.js | 43 +++++++++++++++++++++---------------------- 1 file changed, 21 insertions(+), 22 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index f9296c23..8de3c5ad 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -58,38 +58,37 @@ function _getParentSpan() { // root span gets request attributes _setAttributes(parent, _getRequestAttributes()) if (HRTIME) parent.startTime = cds.context.http?.req?.__hrnow || _hrnow() - if (ADJUST_ROOT_NAME && parent.attributes[ATTR_URL_PATH]) - parent.name += ' ' + parent.attributes[ATTR_URL_PATH] + if (ADJUST_ROOT_NAME && parent.attributes[ATTR_URL_PATH]) parent.name += ' ' + parent.attributes[ATTR_URL_PATH] } if (!parent?._is_async) cds.context._otelctx.setValue(cds.context._otelKey, parent) } return otel.context.active().getValue(cds.context._otelKey) || cds.context._otelctx.getValue(cds.context._otelKey) } -function _getSpanName(arg, fn, targetObj) { +function _getSpanName(arg, fn, that) { const { phase, event, path } = arg - if (targetObj.dbc) { + if (that.dbc) { if (event === undefined) return `db - ${arg.query}` return `db - ${event}${!(event in { BEGIN: 1, COMMIT: 1, ROLLBACK: 1 }) ? ` ${arg.target?.name || arg.path}` : ''}` } - if (fn.name && targetObj.constructor.name !== 'OData') { - if (phase) return `${targetObj.name}.${fn.name} - ${phase} - ${event}${path ? ` ${path}` : ''}` - if (targetObj.name) return `${targetObj.name} - ${event}${path ? ` ${path}` : ''}` + if (fn.name && that.constructor.name !== 'OData') { + if (phase) return `${that.name}.${fn.name} - ${phase} - ${event}${path ? ` ${path}` : ''}` + if (that.name) return `${that.name} - ${event}${path ? ` ${path}` : ''}` return `${event}${path ? ` ${path}` : ''}` } - const trgt = targetObj.name ? `${targetObj.name} - ` : '' + const trgt = that.name ? `${that.name} - ` : '' const phs = phase ? `${phase} - ` : '' const pth = event.match(/cds\.spawn/) ? '' : path ? ` ${path}` : ' *' return `${trgt}${phs}${event}${pth}` } -function _determineKind(targetObj, phase, isAsyncConsumer, options) { +function _determineKind(that, phase, isAsyncConsumer, options) { // DB Calls & Remote calls are client calls - if (targetObj.dbc || targetObj.constructor.name === 'RemoteService' || options.outbound) return SpanKind.CLIENT - if (targetObj.constructor.name === 'cds' || phase === 'emit') + if (that.dbc || that.constructor.name === 'RemoteService' || options.outbound) return SpanKind.CLIENT + if (that.constructor.name === 'cds' || phase === 'emit') // cds.spawn or srv.emit return SpanKind.PRODUCER if (isAsyncConsumer) return SpanKind.CONSUMER @@ -185,9 +184,9 @@ function _setAttributes(span, attributes) { attributes.forEach((value, key) => span.setAttribute(key, value)) } -function trace(name, fn, targetObj, args, options = {}) { +function trace(name, fn, that, args, options = {}) { // REVISIT: only start tracing once served - if (!cds._telemetry.tracer._active) return fn.apply(targetObj, args) + if (!cds._telemetry.tracer._active) return fn.apply(that, args) /* * create span @@ -200,7 +199,7 @@ function trace(name, fn, targetObj, args, options = {}) { ? otel.trace.setSpan(otel.context.active(), parentSpan) : otel.context.active() const spanOptions = { - kind: _determineKind(targetObj, name?.phase, isAsync, options) + kind: _determineKind(that, name?.phase, isAsync, options) } // needed for sampling decision (cf. shouldSample) if (cds.context?.http?.req) { @@ -215,7 +214,7 @@ function trace(name, fn, targetObj, args, options = {}) { spanOptions.links = [{ context: parentSpan.spanContext() }] spanOptions.parent = undefined } - let spanName = typeof name === 'string' ? name : _getSpanName(name, fn, targetObj) + let spanName = typeof name === 'string' ? name : _getSpanName(name, fn, that) if (spanName.length > 80 && _truncate_span_name !== false) spanName = spanName.substring(0, 79) + '…' // REVISIT: better way to get tracer? const span = cds._telemetry.tracer.startSpan(spanName, spanOptions, ctx) @@ -223,18 +222,18 @@ function trace(name, fn, targetObj, args, options = {}) { // REVISIT: can we determine this earlier? // if the current request matches instrumentation-http's ignoreIncomingPaths, we get a NonRecordingSpan -> abort - if (span.constructor.name === 'NonRecordingSpan') return fn.apply(targetObj, args) + if (span.constructor.name === 'NonRecordingSpan') return fn.apply(that, args) /* * set attributes on span */ _setAttributes(span, _getStaticAttributes(fn)) - if (targetObj.dbc || options.sql) { - //> NOTE: !targetObj.dbc is the case during execution of a prepared statement + if (that.dbc || options.sql) { + //> NOTE: !that.dbc is the case during execution of a prepared statement if (cds.requires.multitenancy) { - const creds = targetObj?.dbc?._connection?._settings || targetObj?.dbc?._creds //> hdb vs. @sap/hana-client + const creds = that?.dbc?._connection?._settings || that?.dbc?._creds //> hdb vs. @sap/hana-client _setAttributes(span, _getStaticDBAttributes(cds.context?.tenant, creds)) } else { _setAttributes(span, _getStaticDBAttributes()) @@ -243,7 +242,7 @@ function trace(name, fn, targetObj, args, options = {}) { _setAttributes(span, _getDynamicDBAttributes(options, args, parentSpan)) // SAP Passport - if (process.env.SAP_PASSPORT && targetObj.dbc?.constructor.name in { HDBDriver: 1, HANAClientDriver: 1 }) { + if (process.env.SAP_PASSPORT && that.dbc?.constructor.name in { HDBDriver: 1, HANAClientDriver: 1 }) { const { spanId, traceId } = span.spanContext() // prettier-ignore let passport = [ @@ -269,7 +268,7 @@ function trace(name, fn, targetObj, args, options = {}) { ] passport = passport.join('') LOG._debug && LOG.debug('Setting SAP Passport:', passport) - targetObj.dbc.set({ SAP_PASSPORT: passport }) + that.dbc.set({ SAP_PASSPORT: passport }) } // augment db.statement at parent, if necessary @@ -305,7 +304,7 @@ function trace(name, fn, targetObj, args, options = {}) { } try { - const res = fn.apply(targetObj, args) + const res = fn.apply(that, args) if (res instanceof Promise) return res.then(onSuccess).catch(onFailure).finally(onDone) return onSuccess(res) } catch (e) { From b15ed8137630a93f2666ce210531d807a5b3daec Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 12:03:03 +0100 Subject: [PATCH 03/23] minor --- lib/tracing/trace.js | 29 ++++++++++++++--------------- 1 file changed, 14 insertions(+), 15 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index 8de3c5ad..67f005bb 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -88,9 +88,8 @@ function _getSpanName(arg, fn, that) { function _determineKind(that, phase, isAsyncConsumer, options) { // DB Calls & Remote calls are client calls if (that.dbc || that.constructor.name === 'RemoteService' || options.outbound) return SpanKind.CLIENT - if (that.constructor.name === 'cds' || phase === 'emit') - // cds.spawn or srv.emit - return SpanKind.PRODUCER + // cds.spawn or srv.emit + if (that.constructor.name === 'cds' || phase === 'emit') return SpanKind.PRODUCER if (isAsyncConsumer) return SpanKind.CONSUMER return SpanKind.INTERNAL } @@ -164,7 +163,7 @@ function _getStaticDBAttributes(tenant = '', creds) { return module.exports.__dbAttributes.get(tenant) } -function _getDynamicDBAttributes(options, args, parentSpan) { +function _getDynamicDBAttributes(options, args, parent) { // NOTE: cds.run(query) comes through here multiple times. // the first time, args has event, target, and sometimes a string query. // the second time, args is the string query -> we need to get event and target from the previous invocation (i.e., parentSpan). @@ -172,9 +171,9 @@ function _getDynamicDBAttributes(options, args, parentSpan) { const db_statement = options.sql || (typeof args[0].query === 'string' && args[0].query) || (typeof args[0] === 'string' && args[0]) if (db_statement) dbAttributes.set(ATTR_DB_STATEMENT, db_statement) - const db_operation = args[0].event || parentSpan?.attributes[ATTR_DB_OPERATION] + const db_operation = args[0].event || parent?.attributes[ATTR_DB_OPERATION] if (db_operation) dbAttributes.set(ATTR_DB_OPERATION, db_operation) - const db_sql_table = args[0].target?.name || parentSpan?.attributes[ATTR_DB_SQL_TABLE] + const db_sql_table = args[0].target?.name || parent?.attributes[ATTR_DB_SQL_TABLE] if (db_sql_table) dbAttributes.set(ATTR_DB_SQL_TABLE, db_sql_table) return dbAttributes } @@ -191,12 +190,12 @@ function trace(name, fn, that, args, options = {}) { /* * create span */ - const parentSpan = _getParentSpan() - const isAsync = parentSpan?._is_async && !parentSpan?.name.match(/cds\.spawn/) + const parent = _getParentSpan() + const isAsync = parent?._is_async && !parent?.name.match(/cds\.spawn/) const ctx = isAsync ? ROOT_CONTEXT - : parentSpan - ? otel.trace.setSpan(otel.context.active(), parentSpan) + : parent + ? otel.trace.setSpan(otel.context.active(), parent) : otel.context.active() const spanOptions = { kind: _determineKind(that, name?.phase, isAsync, options) @@ -211,7 +210,7 @@ function trace(name, fn, that, args, options = {}) { } if (HRTIME) spanOptions.startTime = _hrnow() if (isAsync) { - spanOptions.links = [{ context: parentSpan.spanContext() }] + spanOptions.links = [{ context: parent.spanContext() }] spanOptions.parent = undefined } let spanName = typeof name === 'string' ? name : _getSpanName(name, fn, that) @@ -239,7 +238,7 @@ function trace(name, fn, that, args, options = {}) { _setAttributes(span, _getStaticDBAttributes()) } - _setAttributes(span, _getDynamicDBAttributes(options, args, parentSpan)) + _setAttributes(span, _getDynamicDBAttributes(options, args, parent)) // SAP Passport if (process.env.SAP_PASSPORT && that.dbc?.constructor.name in { HDBDriver: 1, HANAClientDriver: 1 }) { @@ -274,10 +273,10 @@ function trace(name, fn, that, args, options = {}) { // augment db.statement at parent, if necessary if ( span.attributes[ATTR_DB_STATEMENT] && - parentSpan?.attributes[ATTR_DB_SYSTEM] && - !parentSpan.attributes[ATTR_DB_STATEMENT] + parent?.attributes[ATTR_DB_SYSTEM] && + !parent.attributes[ATTR_DB_STATEMENT] ) { - parentSpan.setAttribute(ATTR_DB_STATEMENT, span.attributes[ATTR_DB_STATEMENT]) + parent.setAttribute(ATTR_DB_STATEMENT, span.attributes[ATTR_DB_STATEMENT]) } } From e27c0f6e68ff611e2fe253a1ea8fa9b7d06f3c70 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 12:05:20 +0100 Subject: [PATCH 04/23] __attributes -> $reqattrs --- lib/tracing/trace.js | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index 67f005bb..1bb569d4 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -44,6 +44,8 @@ const { hrtime, adjust_root_name, _truncate_span_name } = cds.env.requires.telem const HRTIME = hrtime && hrtime !== 'false' const ADJUST_ROOT_NAME = adjust_root_name && adjust_root_name !== 'false' +const $reqattrs = Symbol('@cap-js/telemetry:reqattrs') + // attach a hr time to incoming requests for later adjustment of span start time in _getParentSpan() if (HRTIME) cds.on('listening', ({ server }) => server.on('request', req => (req.__hrnow = _hrnow()))) @@ -95,7 +97,7 @@ function _determineKind(that, phase, isAsyncConsumer, options) { } function _getStaticAttributes(fn) { - if (!fn.__attributes) { + if (!fn[$reqattrs]) { const attributes = new Map() if (fn.name) attributes.set(ATTR_CODE_FUNCTION, fn.name) @@ -115,16 +117,16 @@ function _getStaticAttributes(fn) { attributes.set('server.port', VCAP_APPLICATION.port) } - fn.__attributes = attributes + fn[$reqattrs] = attributes } - return fn.__attributes + return fn[$reqattrs] } function _getRequestAttributes() { if (!cds.context?.http?.req) return - if (!cds.context.http.req.__attributes) { + if (!cds.context.http.req[$reqattrs]) { const req = cds.context.http.req const attributes = new Map() @@ -142,10 +144,10 @@ function _getRequestAttributes() { else attributes.set(`http.request.header.${key}`, value.split(';')) } - cds.context.http.req.__attributes = attributes + cds.context.http.req[$reqattrs] = attributes } - return cds.context.http.req.__attributes + return cds.context.http.req[$reqattrs] } function _getStaticDBAttributes(tenant = '', creds) { From 789de43e91d3988fa685a2c38b9a45d82e3ddc3c Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 12:08:25 +0100 Subject: [PATCH 05/23] __hrnow -> $hrnow --- lib/tracing/trace.js | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index 1bb569d4..1a09a61f 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -44,10 +44,11 @@ const { hrtime, adjust_root_name, _truncate_span_name } = cds.env.requires.telem const HRTIME = hrtime && hrtime !== 'false' const ADJUST_ROOT_NAME = adjust_root_name && adjust_root_name !== 'false' +const $hrnow = Symbol('@cap-js/telemetry:hrnow') const $reqattrs = Symbol('@cap-js/telemetry:reqattrs') // attach a hr time to incoming requests for later adjustment of span start time in _getParentSpan() -if (HRTIME) cds.on('listening', ({ server }) => server.on('request', req => (req.__hrnow = _hrnow()))) +if (HRTIME) cds.on('listening', ({ server }) => server.on('request', req => (req[$hrnow] = _hrnow()))) function _getParentSpan() { if (!cds.context) return @@ -59,7 +60,7 @@ function _getParentSpan() { parent.__adjusted = true // root span gets request attributes _setAttributes(parent, _getRequestAttributes()) - if (HRTIME) parent.startTime = cds.context.http?.req?.__hrnow || _hrnow() + if (HRTIME) parent.startTime = cds.context.http?.req?.[$hrnow] || _hrnow() if (ADJUST_ROOT_NAME && parent.attributes[ATTR_URL_PATH]) parent.name += ' ' + parent.attributes[ATTR_URL_PATH] } if (!parent?._is_async) cds.context._otelctx.setValue(cds.context._otelKey, parent) From 33587a3efed0d59af78de46eed3e008b23849d8f Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 13:28:04 +0100 Subject: [PATCH 06/23] __adjusted -> $adjusted --- lib/tracing/trace.js | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index 1a09a61f..6b4fea99 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -45,6 +45,7 @@ const HRTIME = hrtime && hrtime !== 'false' const ADJUST_ROOT_NAME = adjust_root_name && adjust_root_name !== 'false' const $hrnow = Symbol('@cap-js/telemetry:hrnow') +const $adjusted = Symbol('@cap-js/telemetry:adjusted') const $reqattrs = Symbol('@cap-js/telemetry:reqattrs') // attach a hr time to incoming requests for later adjustment of span start time in _getParentSpan() @@ -56,8 +57,8 @@ function _getParentSpan() { cds.context._otelKey = otel.createContextKey(cds.context.id) cds.context._otelctx = otel.context.active() const parent = otel.trace.getSpan(cds.context._otelctx) - if (parent && !parent.__adjusted) { - parent.__adjusted = true + if (parent && !parent[$adjusted]) { + parent[$adjusted] = true // root span gets request attributes _setAttributes(parent, _getRequestAttributes()) if (HRTIME) parent.startTime = cds.context.http?.req?.[$hrnow] || _hrnow() From bb5562b24ce57e8a5654bcc4749f63a05556cfcb Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 13:40:18 +0100 Subject: [PATCH 07/23] better way to get tracer + only trace once served and there is a cds.context --- lib/tracing/trace.js | 20 +++++++++++++------- 1 file changed, 13 insertions(+), 7 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index 6b4fea99..ac8ba2fa 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -48,8 +48,15 @@ const $hrnow = Symbol('@cap-js/telemetry:hrnow') const $adjusted = Symbol('@cap-js/telemetry:adjusted') const $reqattrs = Symbol('@cap-js/telemetry:reqattrs') -// attach a hr time to incoming requests for later adjustment of span start time in _getParentSpan() -if (HRTIME) cds.on('listening', ({ server }) => server.on('request', req => (req[$hrnow] = _hrnow()))) +let tracer +cds.on('served', () => { + tracer = otel.trace.getTracer('@cap-js/telemetry', require('../../package.json').version) + + if (HRTIME) { + // attach a hr time to incoming requests for later adjustment of the root span start time + cds.on('listening', ({ server }) => server.on('request', req => (req[$hrnow] = _hrnow()))) + } +}) function _getParentSpan() { if (!cds.context) return @@ -126,7 +133,7 @@ function _getStaticAttributes(fn) { } function _getRequestAttributes() { - if (!cds.context?.http?.req) return + if (!cds.context.http?.req) return if (!cds.context.http.req[$reqattrs]) { const req = cds.context.http.req @@ -188,8 +195,8 @@ function _setAttributes(span, attributes) { } function trace(name, fn, that, args, options = {}) { - // REVISIT: only start tracing once served - if (!cds._telemetry.tracer._active) return fn.apply(that, args) + // only trace once served and there is a cds.context + if (!tracer || !cds.context) return fn.apply(that, args) /* * create span @@ -219,8 +226,7 @@ function trace(name, fn, that, args, options = {}) { } let spanName = typeof name === 'string' ? name : _getSpanName(name, fn, that) if (spanName.length > 80 && _truncate_span_name !== false) spanName = spanName.substring(0, 79) + '…' - // REVISIT: better way to get tracer? - const span = cds._telemetry.tracer.startSpan(spanName, spanOptions, ctx) + const span = tracer.startSpan(spanName, spanOptions, ctx) if (name.event?.match(/^cds\.spawn/) || name?.phase === 'emit') span._is_async = true // REVISIT: can we determine this earlier? From 06f227cac2fd629cde8000ed6de671197bce9cb7 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 13:58:20 +0100 Subject: [PATCH 08/23] externalize set attributes on span --- lib/tracing/trace.js | 89 +++++++++++++++++++++++++------------------- 1 file changed, 50 insertions(+), 39 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index ac8ba2fa..d1e6fd91 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -194,49 +194,15 @@ function _setAttributes(span, attributes) { attributes.forEach((value, key) => span.setAttribute(key, value)) } -function trace(name, fn, that, args, options = {}) { - // only trace once served and there is a cds.context - if (!tracer || !cds.context) return fn.apply(that, args) +function _addAttributes(span, fn, that, options, args, parent) { + _setAttributes(span, _getStaticAttributes(fn)) - /* - * create span - */ - const parent = _getParentSpan() - const isAsync = parent?._is_async && !parent?.name.match(/cds\.spawn/) - const ctx = isAsync - ? ROOT_CONTEXT - : parent - ? otel.trace.setSpan(otel.context.active(), parent) - : otel.context.active() - const spanOptions = { - kind: _determineKind(that, name?.phase, isAsync, options) - } // needed for sampling decision (cf. shouldSample) - if (cds.context?.http?.req) { + if (cds.context.http?.req) { const url_path = cds.context.http.req.baseUrl + cds.context.http.req.path - spanOptions.attributes = { - 'url.path': url_path, - 'http.target': url_path //> http.target is deprecated - } - } - if (HRTIME) spanOptions.startTime = _hrnow() - if (isAsync) { - spanOptions.links = [{ context: parent.spanContext() }] - spanOptions.parent = undefined + span.setAttribute('url.path', url_path) + span.setAttribute('http.target', url_path) //> http.target is deprecated } - let spanName = typeof name === 'string' ? name : _getSpanName(name, fn, that) - if (spanName.length > 80 && _truncate_span_name !== false) spanName = spanName.substring(0, 79) + '…' - const span = tracer.startSpan(spanName, spanOptions, ctx) - if (name.event?.match(/^cds\.spawn/) || name?.phase === 'emit') span._is_async = true - - // REVISIT: can we determine this earlier? - // if the current request matches instrumentation-http's ignoreIncomingPaths, we get a NonRecordingSpan -> abort - if (span.constructor.name === 'NonRecordingSpan') return fn.apply(that, args) - - /* - * set attributes on span - */ - _setAttributes(span, _getStaticAttributes(fn)) if (that.dbc || options.sql) { //> NOTE: !that.dbc is the case during execution of a prepared statement @@ -294,6 +260,51 @@ function trace(name, fn, that, args, options = {}) { if (cds.context?.tenant) otherAttributes.set('sap.tenancy.tenant_id', cds.context.tenant) if (options.outbound) otherAttributes.set('sap.btp.destination', options.outbound) _setAttributes(span, otherAttributes) +} + +function trace(name, fn, that, args, options = {}) { + // only trace once served and there is a cds.context + if (!tracer || !cds.context) return fn.apply(that, args) + + /* + * create span + */ + const parent = _getParentSpan() + const isAsync = parent?._is_async && !parent?.name.match(/cds\.spawn/) + const ctx = isAsync + ? ROOT_CONTEXT + : parent + ? otel.trace.setSpan(otel.context.active(), parent) + : otel.context.active() + const spanOptions = { + kind: _determineKind(that, name?.phase, isAsync, options) + } + // needed for sampling decision (cf. shouldSample) + if (cds.context?.http?.req) { + const url_path = cds.context.http.req.baseUrl + cds.context.http.req.path + spanOptions.attributes = { + 'url.path': url_path, + 'http.target': url_path //> http.target is deprecated + } + } + if (HRTIME) spanOptions.startTime = _hrnow() + if (isAsync) { + spanOptions.links = [{ context: parent.spanContext() }] + spanOptions.parent = undefined + } + let spanName = typeof name === 'string' ? name : _getSpanName(name, fn, that) + if (spanName.length > 80 && _truncate_span_name !== false) spanName = spanName.substring(0, 79) + '…' + const span = tracer.startSpan(spanName, spanOptions, ctx) + if (name.event?.match(/^cds\.spawn/) || name?.phase === 'emit') span._is_async = true + + // REVISIT: can we determine this earlier? + // if the current request matches instrumentation-http's ignoreIncomingPaths, we get a NonRecordingSpan -> abort + if (span.constructor.name === 'NonRecordingSpan') return fn.apply(that, args) + + /* + * set attributes on span + */ + _addAttributes(span, fn, that, options, args, parent) /* * call original function and subsequently end trace in callback From 16e1956f0177970c3a73cde67652f1af798fc81a Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 14:00:44 +0100 Subject: [PATCH 09/23] minor --- lib/tracing/trace.js | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index d1e6fd91..90534b08 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -208,7 +208,7 @@ function _addAttributes(span, fn, that, options, args, parent) { //> NOTE: !that.dbc is the case during execution of a prepared statement if (cds.requires.multitenancy) { - const creds = that?.dbc?._connection?._settings || that?.dbc?._creds //> hdb vs. @sap/hana-client + const creds = that.dbc?._connection?._settings || that.dbc?._creds //> hdb vs. @sap/hana-client _setAttributes(span, _getStaticDBAttributes(cds.context?.tenant, creds)) } else { _setAttributes(span, _getStaticDBAttributes()) @@ -262,7 +262,7 @@ function _addAttributes(span, fn, that, options, args, parent) { _setAttributes(span, otherAttributes) } -function trace(name, fn, that, args, options = {}) { +function trace(req, fn, that, args, opts = {}) { // only trace once served and there is a cds.context if (!tracer || !cds.context) return fn.apply(that, args) @@ -277,7 +277,7 @@ function trace(name, fn, that, args, options = {}) { ? otel.trace.setSpan(otel.context.active(), parent) : otel.context.active() const spanOptions = { - kind: _determineKind(that, name?.phase, isAsync, options) + kind: _determineKind(that, req?.phase, isAsync, opts) } // needed for sampling decision (cf. shouldSample) if (cds.context?.http?.req) { @@ -292,10 +292,10 @@ function trace(name, fn, that, args, options = {}) { spanOptions.links = [{ context: parent.spanContext() }] spanOptions.parent = undefined } - let spanName = typeof name === 'string' ? name : _getSpanName(name, fn, that) + let spanName = typeof req === 'string' ? req : _getSpanName(req, fn, that) if (spanName.length > 80 && _truncate_span_name !== false) spanName = spanName.substring(0, 79) + '…' const span = tracer.startSpan(spanName, spanOptions, ctx) - if (name.event?.match(/^cds\.spawn/) || name?.phase === 'emit') span._is_async = true + if (req.event?.match(/^cds\.spawn/) || req?.phase === 'emit') span._is_async = true // REVISIT: can we determine this earlier? // if the current request matches instrumentation-http's ignoreIncomingPaths, we get a NonRecordingSpan -> abort @@ -304,7 +304,7 @@ function trace(name, fn, that, args, options = {}) { /* * set attributes on span */ - _addAttributes(span, fn, that, options, args, parent) + _addAttributes(span, fn, that, opts, args, parent) /* * call original function and subsequently end trace in callback From 6517d4fe6721494664b7c39c01b1eb5a490f3659 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 14:05:11 +0100 Subject: [PATCH 10/23] async callback --- lib/tracing/trace.js | 31 ++++++++++++------------------- 1 file changed, 12 insertions(+), 19 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index 90534b08..100f27c2 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -309,28 +309,21 @@ function trace(req, fn, that, args, opts = {}) { /* * call original function and subsequently end trace in callback */ - return otel.context.with(cds.context?._otelctx.setValue(cds.context._otelKey, span), () => { - const onSuccess = res => { + return otel.context.with(cds.context?._otelctx.setValue(cds.context._otelKey, span), async () => { + try { + let res = fn.apply(that, args) + if (res instanceof Promise) res = await res span.setStatus({ code: SpanStatusCode.OK }) return res - } - const onFailure = e => { - span.recordException(e) - span.setStatus(Object.assign({ code: SpanStatusCode.ERROR }, e.message ? { message: e.message } : undefined)) - throw e - } - const onDone = () => { - if (span.status.code !== SpanStatusCode.UNSET && !span.ended) span.end(HRTIME ? _hrnow() : undefined) - } - - try { - const res = fn.apply(that, args) - if (res instanceof Promise) return res.then(onSuccess).catch(onFailure).finally(onDone) - return onSuccess(res) - } catch (e) { - onFailure(e) + } catch (err) { + span.recordException(err) + const status = { code: SpanStatusCode.ERROR } + if (err.message) status.message = err.message + span.setStatus(status) + throw err } finally { - onDone() + const unfinished = span.status.code !== SpanStatusCode.UNSET && !span.ended + if (unfinished) span.end(HRTIME ? _hrnow() : undefined) } }) } From f3419a62e2bb0d3afbb0035d23d424de0cffcc3c Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 7 Jan 2025 14:12:59 +0100 Subject: [PATCH 11/23] otel.context.with() -> tracer.startActiveSpan() --- lib/tracing/trace.js | 128 +++++++++++++++++++++++++------------------ 1 file changed, 74 insertions(+), 54 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index 100f27c2..c708ed09 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -2,7 +2,7 @@ const cds = require('@sap/cds') const LOG = cds.log('telemetry') const otel = require('@opentelemetry/api') -const { SpanKind, SpanStatusCode, ROOT_CONTEXT } = otel +const { SpanKind, SpanStatusCode } = otel const { ATTR_SERVER_ADDRESS, ATTR_URL_FULL, @@ -53,28 +53,40 @@ cds.on('served', () => { tracer = otel.trace.getTracer('@cap-js/telemetry', require('../../package.json').version) if (HRTIME) { + // monkey patch startActiveSpan to set a hr time as startTime (if none was provided) + const { startActiveSpan } = tracer + tracer.startActiveSpan = function (name, options, fn) { + options.startTime ??= _hrnow() + return startActiveSpan.call(this, name, options, fn) + } + // attach a hr time to incoming requests for later adjustment of the root span start time cds.on('listening', ({ server }) => server.on('request', req => (req[$hrnow] = _hrnow()))) } }) -function _getParentSpan() { - if (!cds.context) return - if (!cds.context._otelctx) { - cds.context._otelKey = otel.createContextKey(cds.context.id) - cds.context._otelctx = otel.context.active() - const parent = otel.trace.getSpan(cds.context._otelctx) - if (parent && !parent[$adjusted]) { - parent[$adjusted] = true - // root span gets request attributes - _setAttributes(parent, _getRequestAttributes()) - if (HRTIME) parent.startTime = cds.context.http?.req?.[$hrnow] || _hrnow() - if (ADJUST_ROOT_NAME && parent.attributes[ATTR_URL_PATH]) parent.name += ' ' + parent.attributes[ATTR_URL_PATH] - } - if (!parent?._is_async) cds.context._otelctx.setValue(cds.context._otelKey, parent) - } - return otel.context.active().getValue(cds.context._otelKey) || cds.context._otelctx.getValue(cds.context._otelKey) -} +// // attach a hr time to incoming requests for later adjustment of span start time in _getParentSpan() +// if (HRTIME) { +// cds.on('listening', ({ server }) => server.on('request', req => (req[$hrnow] = _hrnow()))) +// } + +// function _getParentSpan() { +// if (!cds.context) return +// if (!cds.context._otelctx) { +// cds.context._otelKey = otel.createContextKey(cds.context.id) +// cds.context._otelctx = otel.context.active() +// const parent = otel.trace.getSpan(cds.context._otelctx) +// if (parent && !parent.__adjusted) { +// parent.__adjusted = true +// // root span gets request attributes +// _setAttributes(parent, _getRequestAttributes()) +// if (HRTIME) parent.startTime = cds.context.http?.req?.[$hrnow] || _hrnow() +// if (ADJUST_ROOT_NAME && parent.attributes[ATTR_URL_PATH]) parent.name += ' ' + parent.attributes[ATTR_URL_PATH] +// } +// if (!parent?._is_async) cds.context._otelctx.setValue(cds.context._otelKey, parent) +// } +// return otel.context.active().getValue(cds.context._otelKey) || cds.context._otelctx.getValue(cds.context._otelKey) +// } function _getSpanName(arg, fn, that) { const { phase, event, path } = arg @@ -266,50 +278,58 @@ function trace(req, fn, that, args, opts = {}) { // only trace once served and there is a cds.context if (!tracer || !cds.context) return fn.apply(that, args) + const parent = otel.trace.getActiveSpan() + + // if the current request matches instrumentation-http's ignoreIncomingPaths -> abort + if (parent?.isRecording() === false) return fn.apply(that, args) + + // augment root span with request attributes, overwrite start time, and adjust root name + if (parent?.instrumentationLibrary.name === '@opentelemetry/instrumentation-http' && !parent[$adjusted]) { + parent[$adjusted] = true + _setAttributes(parent, _getRequestAttributes()) + if (cds.context.http?.req?.[$hrnow]) parent.startTime = cds.context.http.req[$hrnow] + if (ADJUST_ROOT_NAME && parent.attributes[ATTR_URL_PATH]) parent.name += ' ' + parent.attributes[ATTR_URL_PATH] + } + /* * create span */ - const parent = _getParentSpan() - const isAsync = parent?._is_async && !parent?.name.match(/cds\.spawn/) - const ctx = isAsync - ? ROOT_CONTEXT - : parent - ? otel.trace.setSpan(otel.context.active(), parent) - : otel.context.active() - const spanOptions = { - kind: _determineKind(that, req?.phase, isAsync, opts) - } - // needed for sampling decision (cf. shouldSample) - if (cds.context?.http?.req) { - const url_path = cds.context.http.req.baseUrl + cds.context.http.req.path - spanOptions.attributes = { - 'url.path': url_path, - 'http.target': url_path //> http.target is deprecated - } + + // const parentSpan = _getParentSpan() + // if (parentSpan) debugger + // const isAsync = parentSpan?._is_async && !parentSpan?.name.match(/cds\.spawn/) + // const ctx = isAsync + // ? ROOT_CONTEXT + // : parentSpan + // ? otel.trace.setSpan(otel.context.active(), parentSpan) + // : otel.context.active() + + let name = typeof req === 'string' ? req : _getSpanName(req, fn, that) + if (name.length > 80 && _truncate_span_name !== false) name = name.substring(0, 79) + '…' + + const options = { + kind: _determineKind(that, req?.phase, /* isAsync */ undefined, opts), + attributes: {} } - if (HRTIME) spanOptions.startTime = _hrnow() - if (isAsync) { - spanOptions.links = [{ context: parent.spanContext() }] - spanOptions.parent = undefined + + // TODO: improve attributes handling + const collector = { + attributes: options.attributes, + setAttribute: (k, v) => (options.attributes[k] = v) } - let spanName = typeof req === 'string' ? req : _getSpanName(req, fn, that) - if (spanName.length > 80 && _truncate_span_name !== false) spanName = spanName.substring(0, 79) + '…' - const span = tracer.startSpan(spanName, spanOptions, ctx) - if (req.event?.match(/^cds\.spawn/) || req?.phase === 'emit') span._is_async = true + _addAttributes(collector, fn, that, opts, args, parent) - // REVISIT: can we determine this earlier? - // if the current request matches instrumentation-http's ignoreIncomingPaths, we get a NonRecordingSpan -> abort - if (span.constructor.name === 'NonRecordingSpan') return fn.apply(that, args) + // TODO: what's this for? + // if (isAsync) { + // spanOptions.links = [{ context: parentSpan.spanContext() }] + // spanOptions.parent = undefined + // } - /* - * set attributes on span - */ - _addAttributes(span, fn, that, opts, args, parent) + // TODO: what's this for? + // if (name.event?.match(/^cds\.spawn/) || name?.phase === 'emit') span._is_async = true - /* - * call original function and subsequently end trace in callback - */ - return otel.context.with(cds.context?._otelctx.setValue(cds.context._otelKey, span), async () => { + // start a new active span, call the original function, and finally end the span + return tracer.startActiveSpan(name, options, async span => { try { let res = fn.apply(that, args) if (res instanceof Promise) res = await res From 3329bbdf5735c1b9bc1a3e90a24ccffc7c0c6d88 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 14 Jan 2025 20:13:06 +0100 Subject: [PATCH 12/23] in case the span is non-recording, just call the original function --- lib/tracing/trace.js | 3 +++ 1 file changed, 3 insertions(+) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index f783768e..cfe7df1b 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -347,6 +347,9 @@ function trace(req, fn, that, args, opts = {}) { // start a new active span, call the original function, and finally end the span return tracer.startActiveSpan(name, options, async span => { + // in case the span is non-recording, just call the original function + if (span.constructor.name === 'NonRecordingSpan') return fn.apply(that, args) + try { let res = fn.apply(that, args) if (res instanceof Promise) res = await res From a16d8282805692bfa95ad7587abc1ebcfc392f15 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 14 Jan 2025 23:14:27 +0100 Subject: [PATCH 13/23] cds.spawn gets new root contexts --- lib/tracing/trace.js | 30 ++++++------------------------ 1 file changed, 6 insertions(+), 24 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index cfe7df1b..67655a6d 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -295,10 +295,12 @@ function trace(req, fn, that, args, opts = {}) { // only trace once served and there is a cds.context if (!tracer || !cds.context) return fn.apply(that, args) + const root = opts.event === 'cds.spawn' + const parent = otel.trace.getActiveSpan() // if the current request matches instrumentation-http's ignoreIncomingPaths -> abort - if (parent?.isRecording() === false) return fn.apply(that, args) + if (!root && parent?.isRecording() === false) return fn.apply(that, args) // augment root span with request attributes, overwrite start time, and adjust root name if (parent?.instrumentationLibrary.name === '@opentelemetry/instrumentation-http' && !parent[$adjusted]) { @@ -308,26 +310,15 @@ function trace(req, fn, that, args, opts = {}) { if (ADJUST_ROOT_NAME && parent.attributes[ATTR_URL_PATH]) parent.name += ' ' + parent.attributes[ATTR_URL_PATH] } - /* - * create span - */ - - // const parentSpan = _getParentSpan() - // if (parentSpan) debugger - // const isAsync = parentSpan?._is_async && !parentSpan?.name.match(/cds\.spawn/) - // const ctx = isAsync - // ? ROOT_CONTEXT - // : parentSpan - // ? otel.trace.setSpan(otel.context.active(), parentSpan) - // : otel.context.active() - let name = typeof req === 'string' ? req : _getSpanName(req, fn, that) if (name.length > 80 && _truncate_span_name !== false) name = name.substring(0, 79) + '…' const options = { kind: _determineKind(that, req?.phase, /* isAsync */ undefined, opts), - attributes: {} + attributes: {}, + root } + if (root && parent) options.links = [{ context: parent.spanContext() }] // TODO: improve attributes handling const collector = { @@ -336,15 +327,6 @@ function trace(req, fn, that, args, opts = {}) { } _addAttributes(collector, fn, that, opts, args, parent) - // TODO: what's this for? - // if (isAsync) { - // spanOptions.links = [{ context: parentSpan.spanContext() }] - // spanOptions.parent = undefined - // } - - // TODO: what's this for? - // if (name.event?.match(/^cds\.spawn/) || name?.phase === 'emit') span._is_async = true - // start a new active span, call the original function, and finally end the span return tracer.startActiveSpan(name, options, async span => { // in case the span is non-recording, just call the original function From acda92c323076a1ddd74124d044f971689f490c0 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 28 Jan 2025 12:00:43 +0100 Subject: [PATCH 14/23] intermediate --- .gitignore | 2 ++ lib/exporter/ConsoleSpanExporter.js | 2 +- lib/tracing/cds.js | 18 +++++++++----- lib/tracing/cloud_sdk.js | 6 +++-- lib/tracing/trace.js | 37 +++++++++++++++++++---------- test/bookshop/package.json | 5 ++++ test/bookshop/srv/admin-service.cds | 13 ++++++---- test/bookshop/srv/admin-service.js | 34 +++++++++++++++++--------- test/bookshop/test.http | 10 +++++++- test/tracing.test.js | 19 ++++++++++++++- 10 files changed, 108 insertions(+), 38 deletions(-) diff --git a/.gitignore b/.gitignore index 185ca17f..4e29e56a 100644 --- a/.gitignore +++ b/.gitignore @@ -130,3 +130,5 @@ dist .pnp.* .npmrc + +test/msg-box diff --git a/lib/exporter/ConsoleSpanExporter.js b/lib/exporter/ConsoleSpanExporter.js index 443d0607..d59a6bf6 100644 --- a/lib/exporter/ConsoleSpanExporter.js +++ b/lib/exporter/ConsoleSpanExporter.js @@ -101,7 +101,7 @@ class ConsoleSpanExporter /* implements SpanExporter */ { _sendSpans(spans, done) { for (const span of spans) { const w3c_parent_id = cds.context?.http?.req.headers.traceparent?.split('-')[2] - if (!span.parentSpanId || span.parentSpanId === w3c_parent_id || span.name === 'cds.spawn') { + if (!span.parentSpanId || span.parentSpanId === w3c_parent_id) { let toLog = 'elapsed times:' toLog += _span2line(span) const children = this._temporaryStorage.get(span.spanContext().traceId) diff --git a/lib/tracing/cds.js b/lib/tracing/cds.js index e4e0f4f4..48698127 100644 --- a/lib/tracing/cds.js +++ b/lib/tracing/cds.js @@ -1,5 +1,7 @@ const cds = require('@sap/cds') +const { SpanKind } = require('@opentelemetry/api') + const trace = require('./trace') const wrap = require('./wrap') @@ -18,7 +20,7 @@ const _wrapStmt = (stmt, impl, sql) => { stmt[fn] = wrap(it, { no_locate: true, wrapper: function () { - return trace(`${impl} - stmt.${fn} ${sql}`, it, this, arguments, { sql, fn }) + return trace(`${impl} - stmt.${fn} ${sql}`, it, this, arguments, { sql, fn, kind: SpanKind.CLIENT }) } }) } @@ -30,7 +32,7 @@ module.exports = () => { cds.Service.prototype.emit = wrap(_emit, { wrapper: function emit() { const event = arguments[0]?.event || arguments[0] - return trace({ phase: 'emit', event }, _emit, this, arguments, {}) + return trace({ phase: 'emit', event }, _emit, this, arguments, { kind: SpanKind.PRODUCER }) } }) cds.Service.prototype.handle = wrap(_handle, { @@ -45,10 +47,10 @@ module.exports = () => { cds.spawn = wrap(_spawn, { wrapper: function spawn() { const handlerFn = typeof arguments[0] === 'function' ? arguments[0] : arguments[1] - const wrappedFn = wrap(handlerFn, { event: 'cds.spawn' }) + const wrappedFn = wrap(handlerFn, { event: 'cds.spawn', kind: SpanKind.CONSUMER }) if (typeof arguments[0] === 'function') arguments[0] = wrappedFn else arguments[1] = wrappedFn - return _spawn.apply(this, arguments) + return trace('cds.spawn', _spawn, this, arguments, { kind: SpanKind.PRODUCER }) } }) @@ -68,7 +70,11 @@ module.exports = () => { const { prepare: _prepare, exec: _exec } = dbService.prototype dbService.prototype.prepare = wrap(_prepare, { wrapper: function prepare(sql) { - const stmt = trace(`${impl} - prepare ${sql}`, _prepare, this, arguments, { sql, fn: 'prepare' }) + const stmt = trace(`${impl} - prepare ${sql}`, _prepare, this, arguments, { + sql, + fn: 'prepare', + kind: SpanKind.CLIENT + }) if (stmt instanceof Promise) return stmt.then(stmt => _wrapStmt(stmt, impl, sql)) return _wrapStmt(stmt, impl, sql) } @@ -77,7 +83,7 @@ module.exports = () => { wrapper: function exec(sql) { if (!cds.env.requires.telemetry.tracing._tx && sql in { BEGIN: 1, COMMIT: 1, ROLLBACK: 1 }) return _exec.apply(this, arguments) - return trace(`${impl} - exec ${sql}`, _exec, this, arguments, { sql, fn: 'exec' }) + return trace(`${impl} - exec ${sql}`, _exec, this, arguments, { sql, fn: 'exec', kind: SpanKind.CLIENT }) } }) }) diff --git a/lib/tracing/cloud_sdk.js b/lib/tracing/cloud_sdk.js index 1595e4d3..77a2c9b7 100644 --- a/lib/tracing/cloud_sdk.js +++ b/lib/tracing/cloud_sdk.js @@ -1,3 +1,5 @@ +const { SpanKind } = require('@opentelemetry/api') + const trace = require('./trace') const wrap = require('./wrap') @@ -20,7 +22,7 @@ module.exports = () => { _execute, this, arguments, - { outbound: destination.name } + { kind: SpanKind.CLIENT, outbound: destination.name } ) } }) @@ -33,7 +35,7 @@ module.exports = () => { _executeWithOrigin, this, arguments, - { outbound: destination.name } + { kind: SpanKind.CLIENT, outbound: destination.name } ) } }) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index 67655a6d..5fcfdb12 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -108,14 +108,17 @@ function _getSpanName(arg, fn, that) { return `${trgt}${phs}${event}${pth}` } -function _determineKind(that, phase, isAsyncConsumer, options) { - // DB Calls & Remote calls are client calls - if (that.dbc || that.constructor.name === 'RemoteService' || options.outbound) return SpanKind.CLIENT - // cds.spawn or srv.emit - if (that.constructor.name === 'cds' || phase === 'emit') return SpanKind.PRODUCER - if (isAsyncConsumer) return SpanKind.CONSUMER - return SpanKind.INTERNAL -} +// function _determineKind(that, phase, options) { +// // DB Calls & Remote calls are client calls +// if (that.dbc || that.constructor.name === 'RemoteService' || options.outbound) return SpanKind.CLIENT + +// if (that instanceof cds.MessagingService) return SpanKind.CONSUMER + +// // // cds.spawn or srv.emit +// // if (that.constructor.name === 'cds' || phase === 'emit') return SpanKind.PRODUCER + +// return SpanKind.INTERNAL +// } function _getStaticAttributes(fn) { if (!fn[$reqattrs]) { @@ -295,6 +298,15 @@ function trace(req, fn, that, args, opts = {}) { // only trace once served and there is a cds.context if (!tracer || !cds.context) return fn.apply(that, args) + // note: SpanKind.PRODUCER always passed in opts + let kind = opts.kind + if (kind == null) { + if (that instanceof cds.RemoteService) kind = SpanKind.CLIENT + else if (that instanceof cds.MessagingService) kind = SpanKind.CONSUMER + else kind = SpanKind.INTERNAL + } + + // cds.spawn gets a new root context const root = opts.event === 'cds.spawn' const parent = otel.trace.getActiveSpan() @@ -314,13 +326,14 @@ function trace(req, fn, that, args, opts = {}) { if (name.length > 80 && _truncate_span_name !== false) name = name.substring(0, 79) + '…' const options = { - kind: _determineKind(that, req?.phase, /* isAsync */ undefined, opts), + kind, + root, attributes: {}, - root + links: root && parent ? [{ context: parent.spanContext() }] : undefined } - if (root && parent) options.links = [{ context: parent.spanContext() }] - // TODO: improve attributes handling + // REVISIT: improve attributes handling + // coding relies on setting attributes on the existing span, but now we create it later (cf. startActiveSpan) const collector = { attributes: options.attributes, setAttribute: (k, v) => (options.attributes[k] = v) diff --git a/test/bookshop/package.json b/test/bookshop/package.json index b67fac78..2f7d8d4b 100644 --- a/test/bookshop/package.json +++ b/test/bookshop/package.json @@ -52,6 +52,11 @@ } } } + }, + "messaging": { + "kind": "local-messaging", + "_kind": "file-based-messaging", + "file": "../msg-box" } }, "fiori": { diff --git a/test/bookshop/srv/admin-service.cds b/test/bookshop/srv/admin-service.cds index 2cacb2b0..d8edb269 100644 --- a/test/bookshop/srv/admin-service.cds +++ b/test/bookshop/srv/admin-service.cds @@ -1,8 +1,13 @@ -using { sap.capire.bookshop as my } from '../db/schema'; +using {sap.capire.bookshop as my} from '../db/schema'; -service AdminService @(requires:'admin') { - entity Books as projection on my.Books; +service AdminService @(requires: 'admin') { + entity Books as projection on my.Books; entity Authors as projection on my.Authors; - action spawn(); + action test_spawn(); + action test_emit(); + + event foo { + bar : String; + }; } diff --git a/test/bookshop/srv/admin-service.js b/test/bookshop/srv/admin-service.js index 950caef4..8585a976 100644 --- a/test/bookshop/srv/admin-service.js +++ b/test/bookshop/srv/admin-service.js @@ -1,20 +1,32 @@ const cds = require('@sap/cds/lib') -module.exports = class AdminService extends cds.ApplicationService { init(){ - this.before ('NEW','Books.drafts', genid) - - this.on('spawn', () => { - cds.spawn({ after: 3 }, async () => { +module.exports = class AdminService extends cds.ApplicationService { + async init() { + const messaging = await cds.connect.to('messaging') + messaging.on('foo', async () => { await SELECT.from('sap.capire.bookshop.Books') await cds.services.AdminService.read('Authors') }) - }) - return super.init() -}} + this.before('NEW', 'Books.drafts', genid) + + this.on('test_spawn', () => { + cds.spawn({ after: 3 }, async () => { + await SELECT.from('sap.capire.bookshop.Books') + await cds.services.AdminService.read('Authors') + }) + }) + + this.on('test_emit', async () => { + await messaging.emit('foo', { bar: 'baz' }) + }) + + return super.init() + } +} /** Generate primary keys for target entity in request */ -async function genid (req) { - const {ID} = await cds.tx(req).run (SELECT.one.from(req.target.actives).columns('max(ID) as ID')) - req.data.ID = ID - ID % 100 + 100 + 1 +async function genid(req) { + const { ID } = await cds.tx(req).run(SELECT.one.from(req.target.actives).columns('max(ID) as ID')) + req.data.ID = ID - (ID % 100) + 100 + 1 } diff --git a/test/bookshop/test.http b/test/bookshop/test.http index 42d3b51f..e266af25 100644 --- a/test/bookshop/test.http +++ b/test/bookshop/test.http @@ -41,7 +41,15 @@ Content-Type: application/json ### -POST {{host}}/odata/v4/admin/spawn +POST {{host}}/odata/v4/admin/test_spawn +Authorization: Basic alice:wonderland +Content-Type: application/json + +{} + +### + +POST {{host}}/odata/v4/admin/test_emit Authorization: Basic alice:wonderland Content-Type: application/json diff --git a/test/tracing.test.js b/test/tracing.test.js index a634ca70..708a0f94 100644 --- a/test/tracing.test.js +++ b/test/tracing.test.js @@ -7,6 +7,15 @@ const sleep = require('util').promisify(setTimeout) describe('tracing', () => { const admin = { auth: { username: 'alice' } } + afterAll(async () => { + await sleep(100) + try { + require('fs').rmSync(require('path').join(__dirname, 'msg-box')) + } catch { + // ignore + } + }) + beforeEach(log.clear) test('GET is traced', async () => { @@ -52,12 +61,20 @@ describe('tracing', () => { }) test('cds.spawn is traced', async () => { - await POST('/odata/v4/admin/spawn', {}, admin) + await POST('/odata/v4/admin/test_spawn', {}, admin) await sleep(30) // 2: action + spawned action expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(2) }) + test('emit is traced', async () => { + await POST('/odata/v4/admin/test_emit', {}, admin) + await sleep(1000) + // TODO: how many roots? + // 2: emitting action + message consumption + expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(2) + }) + describe('db', () => { describe('ql', () => { test('SELECT is traced', async () => { From 073be84c7057c518c4e4c9e0e3af8e17f62d04e4 Mon Sep 17 00:00:00 2001 From: D050513 Date: Mon, 3 Feb 2025 23:13:28 +0100 Subject: [PATCH 15/23] emit + outbox + cleanup --- lib/tracing/cds.js | 42 +++++++++++++++- lib/tracing/trace.js | 117 +++++++++++++++++++++++-------------------- 2 files changed, 103 insertions(+), 56 deletions(-) diff --git a/lib/tracing/cds.js b/lib/tracing/cds.js index 48698127..4bd88b62 100644 --- a/lib/tracing/cds.js +++ b/lib/tracing/cds.js @@ -32,7 +32,7 @@ module.exports = () => { cds.Service.prototype.emit = wrap(_emit, { wrapper: function emit() { const event = arguments[0]?.event || arguments[0] - return trace({ phase: 'emit', event }, _emit, this, arguments, { kind: SpanKind.PRODUCER }) + return trace({ phase: 'emit', event }, _emit, this, arguments, {}) } }) cds.Service.prototype.handle = wrap(_handle, { @@ -63,6 +63,46 @@ module.exports = () => { } }) + cds.on('connect', service => { + if (service instanceof cds.MessagingService) { + const unboxed = cds.unboxed(service) + const { handle: _unboxed_handle } = unboxed + unboxed.handle = wrap(_unboxed_handle, { + wrapper: function handle(msg) { + if (msg.inbound) { + // TODO: w3c trace context + return _unboxed_handle.apply(this, arguments) + } + const kind = service.kind !== 'local-messaging' ? SpanKind.PRODUCER : SpanKind.INTERNAL + return trace(msg, _unboxed_handle, this, arguments, { kind }) + } + }) + + // // TODO: w3c trace context + // if (unboxed !== service) { + // const { handle: _outboxed_handle } = service + // service.handle = wrap(_outboxed_handle, { + // wrapper: function handle(msg) { + // if (!msg.inbound) { + // const spanContext = otel_trace.getActiveSpan().spanContext() + // // taken from W3CTraceContextPropagator + // const traceParent = + // VERSION + + // '-' + + // spanContext.traceId + + // '-' + + // spanContext.spanId + + // '-0' + + // Number(spanContext.traceFlags || TraceFlags.NONE).toString(16) + // msg.headers.traceparent = traceParent + // } + // return _outboxed_handle.apply(this, arguments) + // } + // }) + // } + } + }) + const impl = cds.env.requires.db?.impl if (impl?.match(/^@cap-js\//)) { const dbService = require(impl) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index 5fcfdb12..01554288 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -40,6 +40,8 @@ const MASK_HEADERS = (cds.env.log.mask_headers || ['/authorization/i', '/cookie/ return new RegExp(s) }) +const CRUD = { CREATE: 1, READ: 1, UPDATE: 1, DELETE: 1 } + const { hrtime, adjust_root_name, _truncate_span_name } = cds.env.requires.telemetry.tracing const HRTIME = hrtime && hrtime !== 'false' const ADJUST_ROOT_NAME = adjust_root_name && adjust_root_name !== 'false' @@ -65,29 +67,6 @@ cds.on('served', () => { } }) -// // attach a hr time to incoming requests for later adjustment of span start time in _getParentSpan() -// if (HRTIME) { -// cds.on('listening', ({ server }) => server.on('request', req => (req[$hrnow] = _hrnow()))) -// } - -// function _getParentSpan() { -// if (!cds.context) return -// if (!cds.context._otelctx) { -// cds.context._otelKey = otel.createContextKey(cds.context.id) -// cds.context._otelctx = otel.context.active() -// const parent = otel.trace.getSpan(cds.context._otelctx) -// if (parent && !parent.__adjusted) { -// parent.__adjusted = true -// // root span gets request attributes -// _setAttributes(parent, _getRequestAttributes()) -// if (HRTIME) parent.startTime = cds.context.http?.req?.[$hrnow] || _hrnow() -// if (ADJUST_ROOT_NAME && parent.attributes[ATTR_URL_PATH]) parent.name += ' ' + parent.attributes[ATTR_URL_PATH] -// } -// if (!parent?._is_async) cds.context._otelctx.setValue(cds.context._otelKey, parent) -// } -// return otel.context.active().getValue(cds.context._otelKey) || cds.context._otelctx.getValue(cds.context._otelKey) -// } - function _getSpanName(arg, fn, that) { const { phase, event, path } = arg @@ -97,8 +76,8 @@ function _getSpanName(arg, fn, that) { } if (fn.name && that.constructor.name !== 'OData') { - if (phase) return `${that.name}.${fn.name} - ${phase} - ${event}${path ? ` ${path}` : ''}` - if (that.name) return `${that.name} - ${event}${path ? ` ${path}` : ''}` + if (phase) return `${that.name} - ${phase} ${event}${path ? ` ${path}` : ''}` + if (that.name) return `${that.name} - ${event in CRUD ? event : `handle ${event}`}${path ? ` ${path}` : ''}` return `${event}${path ? ` ${path}` : ''}` } @@ -108,18 +87,6 @@ function _getSpanName(arg, fn, that) { return `${trgt}${phs}${event}${pth}` } -// function _determineKind(that, phase, options) { -// // DB Calls & Remote calls are client calls -// if (that.dbc || that.constructor.name === 'RemoteService' || options.outbound) return SpanKind.CLIENT - -// if (that instanceof cds.MessagingService) return SpanKind.CONSUMER - -// // // cds.spawn or srv.emit -// // if (that.constructor.name === 'cds' || phase === 'emit') return SpanKind.PRODUCER - -// return SpanKind.INTERNAL -// } - function _getStaticAttributes(fn) { if (!fn[$reqattrs]) { const attributes = new Map() @@ -298,19 +265,34 @@ function trace(req, fn, that, args, opts = {}) { // only trace once served and there is a cds.context if (!tracer || !cds.context) return fn.apply(that, args) - // note: SpanKind.PRODUCER always passed in opts + const parent = otel.trace.getActiveSpan() + + // cds.spawn gets a new root context + let root = opts.event === 'cds.spawn' + let kind = opts.kind if (kind == null) { + kind = SpanKind.INTERNAL //> default + if (that instanceof cds.RemoteService) kind = SpanKind.CLIENT - else if (that instanceof cds.MessagingService) kind = SpanKind.CONSUMER - else kind = SpanKind.INTERNAL + else if (that instanceof cds.MessagingService) { + const { kind: msg_kind, outbox: msg_outbox } = cds.env.requires.messaging + if (msg_kind !== 'local-messaging') { + const outboxed = msg_outbox && cds.outboxed(that) === that + if (outboxed || fn.name === 'handle') { + // default -> nothing to do + } else if (!parent) { + kind = SpanKind.CONSUMER + root = true + } else if (!outboxed && fn.name === 'emit') { + // default -> nothing to do + } else { + kind = SpanKind.PRODUCER + } + } + } } - // cds.spawn gets a new root context - const root = opts.event === 'cds.spawn' - - const parent = otel.trace.getActiveSpan() - // if the current request matches instrumentation-http's ignoreIncomingPaths -> abort if (!root && parent?.isRecording() === false) return fn.apply(that, args) @@ -323,6 +305,7 @@ function trace(req, fn, that, args, opts = {}) { } let name = typeof req === 'string' ? req : _getSpanName(req, fn, that) + if (name === 'cds.spawn') name += kind === SpanKind.CONSUMER ? ' - run task' : ' - schedule task' if (name.length > 80 && _truncate_span_name !== false) name = name.substring(0, 79) + '…' const options = { @@ -341,26 +324,50 @@ function trace(req, fn, that, args, opts = {}) { _addAttributes(collector, fn, that, opts, args, parent) // start a new active span, call the original function, and finally end the span - return tracer.startActiveSpan(name, options, async span => { + return tracer.startActiveSpan(name, options, span => { // in case the span is non-recording, just call the original function if (span.constructor.name === 'NonRecordingSpan') return fn.apply(that, args) - try { - let res = fn.apply(that, args) - if (res instanceof Promise) res = await res - _addDbRowCount(span, res) - span.setStatus({ code: SpanStatusCode.OK }) - return res - } catch (err) { + const _on_error = (err, reject) => { span.recordException(err) const status = { code: SpanStatusCode.ERROR } if (err.message) status.message = err.message span.setStatus(status) - throw err - } finally { + if (reject) reject(err) + else throw err + } + + const _on_finally = () => { const unfinished = span.status.code !== SpanStatusCode.UNSET && !span.ended if (unfinished) span.end(HRTIME ? _hrnow() : undefined) } + + let res + try { + res = fn.apply(that, args) + if (!(res instanceof Promise)) { + span.setStatus({ code: SpanStatusCode.OK }) + return res + } + } catch (err) { + _on_error(err) + } finally { + _on_finally() + } + + // eslint-disable-next-line no-async-promise-executor + return new Promise(async (resolve, reject) => { + try { + res = await res + _addDbRowCount(span, res) + span.setStatus({ code: SpanStatusCode.OK }) + resolve(res) + } catch (err) { + _on_error(err, reject) + } finally { + _on_finally() + } + }) }) } From 0029b12f9f328651da21e79f542965b27c42dcbe Mon Sep 17 00:00:00 2001 From: D050513 Date: Mon, 3 Feb 2025 23:33:15 +0100 Subject: [PATCH 16/23] cleanup --- lib/index.js | 7 ------- lib/tracing/index.js | 8 -------- 2 files changed, 15 deletions(-) diff --git a/lib/index.js b/lib/index.js index edec0902..166daf01 100644 --- a/lib/index.js +++ b/lib/index.js @@ -3,7 +3,6 @@ const LOG = cds.log('telemetry') const { diag } = require('@opentelemetry/api') const { registerInstrumentations } = require('@opentelemetry/instrumentation') -// const { ATTR_SERVICE_NAME, ATTR_SERVICE_VERSION } = require('@opentelemetry/semantic-conventions') const tracing = require('./tracing') const metrics = require('./metrics') @@ -47,12 +46,6 @@ module.exports = function () { const resource = getResource() - // // REVISIT: better way to make available? - // cds._telemetry = { - // name: resource.attributes[ATTR_SERVICE_NAME], - // version: resource.attributes[ATTR_SERVICE_VERSION] - // } - /* * setup tracing */ diff --git a/lib/tracing/index.js b/lib/tracing/index.js index 7b10826f..026eeb9a 100644 --- a/lib/tracing/index.js +++ b/lib/tracing/index.js @@ -158,14 +158,6 @@ module.exports = resource => { tracerProvider.addSpanProcessor(spanProcessor) } - // // REVISIT: better way to set/ pass tracer? - // cds._telemetry.tracer = trace.getTracer('@cap-js/telemetry', require('../../package.json').version) - - // // REVISIT: only start tracing once served - // cds.on('served', () => { - // cds._telemetry.tracer._active = true - // }) - // clear sap passport for new tx if (process.env.SAP_PASSPORT) { cds.on('served', () => { From b92c4678d9453c18a57873d89a8aa31fdcb1d0ec Mon Sep 17 00:00:00 2001 From: D050513 Date: Mon, 3 Feb 2025 23:54:56 +0100 Subject: [PATCH 17/23] streamline --- lib/tracing/trace.js | 32 +++++++++++--------------------- 1 file changed, 11 insertions(+), 21 deletions(-) diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index a0e2ed65..087b38f4 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -67,6 +67,7 @@ cds.on('served', () => { } }) +// REVISIT: needs a cleanup function _getSpanName(arg, fn, that) { const { phase, event, path } = arg @@ -323,13 +324,18 @@ function trace(req, fn, that, args, opts = {}) { // in case the span is non-recording, just call the original function if (span.constructor.name === 'NonRecordingSpan') return fn.apply(that, args) - const _on_error = (err, reject) => { + const _on_success = res => { + _addDbRowCount(span, res) + span.setStatus({ code: SpanStatusCode.OK }) + return res + } + + const _on_error = err => { span.recordException(err) const status = { code: SpanStatusCode.ERROR } if (err.message) status.message = err.message span.setStatus(status) - if (reject) reject(err) - else throw err + throw err } const _on_finally = () => { @@ -340,29 +346,13 @@ function trace(req, fn, that, args, opts = {}) { let res try { res = fn.apply(that, args) - if (!(res instanceof Promise)) { - span.setStatus({ code: SpanStatusCode.OK }) - return res - } + if (res instanceof Promise) return res.then(_on_success, _on_error).finally(_on_finally) + return _on_success(res) } catch (err) { _on_error(err) } finally { _on_finally() } - - // eslint-disable-next-line no-async-promise-executor - return new Promise(async (resolve, reject) => { - try { - res = await res - _addDbRowCount(span, res) - span.setStatus({ code: SpanStatusCode.OK }) - resolve(res) - } catch (err) { - _on_error(err, reject) - } finally { - _on_finally() - } - }) }) } From 92cdfce9f742d4c9642a8e14deebba6ec1e051e5 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 4 Feb 2025 23:03:01 +0100 Subject: [PATCH 18/23] tests --- lib/tracing/trace.js | 2 ++ test/bookshop/package.json | 3 ++ test/metrics.test.js | 5 ++- test/tracing-messaging-with-outbox.test.js | 18 ++++++++++ ...g-messaging-with-persistent-outbox.test.js | 22 ++++++++++++ test/tracing-messaging-without-outbox.test.js | 17 +++++++++ test/tracing-messaging.js | 36 +++++++++++++++++++ test/tracing.test.js | 18 ++-------- 8 files changed, 103 insertions(+), 18 deletions(-) create mode 100644 test/tracing-messaging-with-outbox.test.js create mode 100644 test/tracing-messaging-with-persistent-outbox.test.js create mode 100644 test/tracing-messaging-without-outbox.test.js create mode 100644 test/tracing-messaging.js diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index 087b38f4..f3fbe87e 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -302,6 +302,8 @@ function trace(req, fn, that, args, opts = {}) { let name = typeof req === 'string' ? req : _getSpanName(req, fn, that) if (name === 'cds.spawn') name += kind === SpanKind.CONSUMER ? ' - run task' : ' - schedule task' + else if (name.startsWith('messaging - emit')) + name = name.replace('messaging - emit', `messaging - emit ${kind === SpanKind.CONSUMER ? 'incoming' : 'outgoing'}`) if (name.length > 80 && _truncate_span_name !== false) name = name.substring(0, 79) + '…' const options = { diff --git a/test/bookshop/package.json b/test/bookshop/package.json index 2f7d8d4b..fb79f481 100644 --- a/test/bookshop/package.json +++ b/test/bookshop/package.json @@ -57,6 +57,9 @@ "kind": "local-messaging", "_kind": "file-based-messaging", "file": "../msg-box" + }, + "_outbox": { + "kind": "persistent-outbox" } }, "fiori": { diff --git a/test/metrics.test.js b/test/metrics.test.js index 61fdd218..6cd54cf2 100644 --- a/test/metrics.test.js +++ b/test/metrics.test.js @@ -1,9 +1,8 @@ -const cds = require('@sap/cds') - // process.env.HOST_METRICS_RETAIN_SYSTEM = 'true' //> with this the test would fail process.env.HOST_METRICS_LOG_SYSTEM = 'true' -cds.env.requires.telemetry.metrics.config.exportIntervalMillis = 100 +process.env.cds_requires_telemetry_metrics_config = JSON.stringify({ exportIntervalMillis: 100 }) +const cds = require('@sap/cds') const { expect, GET } = cds.test().in(__dirname + '/bookshop') const log = cds.test.log() diff --git a/test/tracing-messaging-with-outbox.test.js b/test/tracing-messaging-with-outbox.test.js new file mode 100644 index 00000000..6da1fa01 --- /dev/null +++ b/test/tracing-messaging-with-outbox.test.js @@ -0,0 +1,18 @@ +const CASE = 'with_outbox' + +const env = { + kind: 'file-based-messaging', + outbox: true, + file: `../${CASE}` +} +process.env.cds_requires_messaging = JSON.stringify(env) + +const CHECK = (log, expect) => { + // 2: no outbox -> consumer gets new root context + // REVISIT: for some reason, the emit done in the on succeeded callback gets a new root context when running in jest + expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(3) //> actually 2 +} + +describe(`tracing messaging - ${CASE}`, () => { + require('./tracing-messaging')(CASE, CHECK) +}) diff --git a/test/tracing-messaging-with-persistent-outbox.test.js b/test/tracing-messaging-with-persistent-outbox.test.js new file mode 100644 index 00000000..6744a4b1 --- /dev/null +++ b/test/tracing-messaging-with-persistent-outbox.test.js @@ -0,0 +1,22 @@ +const CASE = 'with_persistent-outbox' + +const env = { + kind: 'file-based-messaging', + outbox: true, + file: `../${CASE}` +} +process.env.cds_requires_messaging = JSON.stringify(env) +process.env.cds_requires_outbox = JSON.stringify({ kind: 'persistent-outbox' }) + +process.env.cds_requires_telemetry_metrics = null + +const CHECK = (log, expect) => { + // 3: outbox -> consumers get new root context + // REVISIT: for some reason, span "cds.spawn run task" has no parent when running in jest + expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(4) //> actually 3 + expect(log.output.match(/cds.spawn - schedule task/g).length).to.equal(1) +} + +describe(`tracing messaging - ${CASE}`, () => { + require('./tracing-messaging')(CASE, CHECK) +}) diff --git a/test/tracing-messaging-without-outbox.test.js b/test/tracing-messaging-without-outbox.test.js new file mode 100644 index 00000000..cc941b6c --- /dev/null +++ b/test/tracing-messaging-without-outbox.test.js @@ -0,0 +1,17 @@ +const CASE = 'without_outbox' + +const env = { + kind: 'file-based-messaging', + outbox: false, + file: `../${CASE}` +} +process.env.cds_requires_messaging = JSON.stringify(env) + +const CHECK = (log, expect) => { + // 2: no outbox -> consumer gets new root context + expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(2) +} + +describe(`tracing messaging - ${CASE}`, () => { + require('./tracing-messaging')(CASE, CHECK) +}) diff --git a/test/tracing-messaging.js b/test/tracing-messaging.js new file mode 100644 index 00000000..57f51841 --- /dev/null +++ b/test/tracing-messaging.js @@ -0,0 +1,36 @@ +module.exports = (CASE, CHECK) => { + const cds = require('@sap/cds') + const { expect, POST } = cds.test().in(__dirname + '/bookshop') + const log = cds.test.log() + + const sleep = require('util').promisify(setTimeout) + + const admin = { auth: { username: 'alice' } } + + const rm = () => { + try { + require('fs').rmSync(require('path').join(__dirname, CASE)) + } catch { + // ignore + } + } + + beforeAll(async () => { + rm() + await sleep(100) + }) + + afterAll(async () => { + await sleep(100) + rm() + }) + + beforeEach(log.clear) + + test('emit is traced', async () => { + await POST('/odata/v4/admin/test_emit', {}, admin) + await sleep(1000) + // execute case specific check + CHECK(log, expect) + }) +} diff --git a/test/tracing.test.js b/test/tracing.test.js index 708a0f94..78b893c4 100644 --- a/test/tracing.test.js +++ b/test/tracing.test.js @@ -7,15 +7,6 @@ const sleep = require('util').promisify(setTimeout) describe('tracing', () => { const admin = { auth: { username: 'alice' } } - afterAll(async () => { - await sleep(100) - try { - require('fs').rmSync(require('path').join(__dirname, 'msg-box')) - } catch { - // ignore - } - }) - beforeEach(log.clear) test('GET is traced', async () => { @@ -69,10 +60,9 @@ describe('tracing', () => { test('emit is traced', async () => { await POST('/odata/v4/admin/test_emit', {}, admin) - await sleep(1000) - // TODO: how many roots? - // 2: emitting action + message consumption - expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(2) + await sleep(100) + // 1: local-messaging remains in same context + expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(1) }) describe('db', () => { @@ -102,7 +92,5 @@ describe('tracing', () => { test.skip('individual handlers are traced', async () => {}) - test.skip('srv.emit is traced', async () => {}) - test.skip('remote is traced', async () => {}) }) From fc0e0031790a2d6b126538a39fc9f2887c05e581 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 4 Feb 2025 23:33:28 +0100 Subject: [PATCH 19/23] custom spans --- test/bookshop/srv/cat-service.js | 57 +++++++++++++++++++++----------- test/bookshop/test.http | 5 +++ test/tracing.test.js | 6 ++++ 3 files changed, 49 insertions(+), 19 deletions(-) diff --git a/test/bookshop/srv/cat-service.js b/test/bookshop/srv/cat-service.js index 84c5cf6d..35af4224 100644 --- a/test/bookshop/srv/cat-service.js +++ b/test/bookshop/srv/cat-service.js @@ -1,26 +1,45 @@ const cds = require('@sap/cds') -const { Books } = cds.entities ('sap.capire.bookshop') +const { Books } = cds.entities('sap.capire.bookshop') -class CatalogService extends cds.ApplicationService { init(){ +const { trace, SpanStatusCode } = require('@opentelemetry/api') - // Reduce stock of ordered books if available stock suffices - this.on ('submitOrder', async req => { - const {book,quantity} = req.data - let {stock} = await SELECT `stock` .from (Books,book) - if (stock >= quantity) { - await UPDATE (Books,book) .with (`stock -=`, quantity) - await this.emit ('OrderedBook', { book, quantity, buyer:req.user.id }) - return { stock } - } - else return req.error (409,`${quantity} exceeds stock for book #${book}`) - }) +class CatalogService extends cds.ApplicationService { + init() { + // Reduce stock of ordered books if available stock suffices + this.on('submitOrder', async req => { + const { book, quantity } = req.data + let { stock } = await SELECT`stock`.from(Books, book) + if (stock >= quantity) { + await UPDATE(Books, book).with(`stock -=`, quantity) + await this.emit('OrderedBook', { book, quantity, buyer: req.user.id }) + return { stock } + } else return req.error(409, `${quantity} exceeds stock for book #${book}`) + }) - // Add some discount for overstocked books - this.after ('READ','ListOfBooks', each => { - if (each.stock > 111) each.title += ` -- 11% discount!` - }) + let tracer + this.on('READ', 'ListOfBooks', async function (req, next) { + tracer ??= trace.getTracer('CatalogService') + const name = 'my custom span' + const options = { + attributes: { + foo: 'bar' + } + } + return tracer.startActiveSpan(name, options, async span => { + const res = await next() + span.setStatus({ code: SpanStatusCode.OK }) + span.end() + return res + }) + }) - return super.init() -}} + // Add some discount for overstocked books + this.after('READ', 'ListOfBooks', each => { + if (each.stock > 111) each.title += ` -- 11% discount!` + }) + + return super.init() + } +} module.exports = { CatalogService } diff --git a/test/bookshop/test.http b/test/bookshop/test.http index e266af25..520ac47c 100644 --- a/test/bookshop/test.http +++ b/test/bookshop/test.http @@ -54,3 +54,8 @@ Authorization: Basic alice:wonderland Content-Type: application/json {} + +### + +GET {{host}}/odata/v4/catalog/ListOfBooks +Authorization: Basic alice:wonderland diff --git a/test/tracing.test.js b/test/tracing.test.js index 78b893c4..8bfa2bed 100644 --- a/test/tracing.test.js +++ b/test/tracing.test.js @@ -88,6 +88,12 @@ describe('tracing', () => { }) }) + test('custom spans are supported', async () => { + await GET('/odata/v4/catalog/ListOfBooks', {}, admin) + await sleep(100) + expect(log.output.match(/my custom span/g).length).to.equal(1) + }) + // --- TODO --- test.skip('individual handlers are traced', async () => {}) From 6f893c64eb39d79a5a636b70d0c3c134c6607d17 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 4 Feb 2025 23:34:34 +0100 Subject: [PATCH 20/23] 1.2.0-beta.0 --- package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/package.json b/package.json index 78d301ba..e6e3cdd4 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "@cap-js/telemetry", - "version": "1.2.0", + "version": "1.2.0-beta.0", "description": "CDS plugin providing observability features, incl. automatic OpenTelemetry instrumentation.", "repository": { "type": "git", From 75a4ea3ed4ecf57f32c8ad4d0143a5b0151b71c5 Mon Sep 17 00:00:00 2001 From: D050513 Date: Tue, 4 Feb 2025 23:38:16 +0100 Subject: [PATCH 21/23] changelog --- CHANGELOG.md | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0e09df6e..6a2a35a8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,9 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Added - Trace attribute `db.client.response.returned_rows` for queries via `cds.ql` +- TODO: custom spans +- TODO: messaging +- TODO: span kinds ### Changed @@ -16,6 +19,8 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Removed +- TODO: `cds._telemetry` + ## Version 1.1.2 - 2024-12-10 ### Fixed From f2cb9742ac2536f42cef63778a584ec641ab3020 Mon Sep 17 00:00:00 2001 From: D050513 Date: Wed, 5 Feb 2025 11:38:43 +0100 Subject: [PATCH 22/23] cleanup --- CHANGELOG.md | 8 ++++---- test/bookshop/srv/cat-service.js | 2 ++ 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6a2a35a8..29796a8e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,9 +9,9 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Added - Trace attribute `db.client.response.returned_rows` for queries via `cds.ql` -- TODO: custom spans -- TODO: messaging -- TODO: span kinds +- Support for adding custom spans to trace hierarchy via `tracer.startActiveSpan()` + + See https://open-telemetry.github.io/opentelemetry-js/interfaces/_opentelemetry_api.Tracer.html#startActiveSpan +- Improved support for tracing messaging services and `cds.spawn` ### Changed @@ -19,7 +19,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Removed -- TODO: `cds._telemetry` +- Internal `cds._telemetry` ## Version 1.1.2 - 2024-12-10 diff --git a/test/bookshop/srv/cat-service.js b/test/bookshop/srv/cat-service.js index 35af4224..0ca9beca 100644 --- a/test/bookshop/srv/cat-service.js +++ b/test/bookshop/srv/cat-service.js @@ -26,6 +26,8 @@ class CatalogService extends cds.ApplicationService { } } return tracer.startActiveSpan(name, options, async span => { + // NOTE: this ignores error handling!!! + // for details, check https://open-telemetry.github.io/opentelemetry-js/interfaces/_opentelemetry_api.Tracer.html#startActiveSpan const res = await next() span.setStatus({ code: SpanStatusCode.OK }) span.end() From 46528072a58e510eac43046ad74abad4bd1301fb Mon Sep 17 00:00:00 2001 From: D050513 Date: Wed, 5 Feb 2025 11:56:45 +0100 Subject: [PATCH 23/23] Custom Spans (beta) --- CHANGELOG.md | 6 +++--- README.md | 34 +++++++++++++++++++++++++++++----- 2 files changed, 32 insertions(+), 8 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 29796a8e..35baee7a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,10 +8,10 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Added -- Trace attribute `db.client.response.returned_rows` for queries via `cds.ql` -- Support for adding custom spans to trace hierarchy via `tracer.startActiveSpan()` - + See https://open-telemetry.github.io/opentelemetry-js/interfaces/_opentelemetry_api.Tracer.html#startActiveSpan - Improved support for tracing messaging services and `cds.spawn` +- Support for adding custom spans to trace hierarchy via `tracer.startActiveSpan()` (beta) + + See https://open-telemetry.github.io/opentelemetry-js/interfaces/_opentelemetry_api.Tracer.html#startActiveSpan +- Trace attribute `db.client.response.returned_rows` for queries via `cds.ql` ### Changed diff --git a/README.md b/README.md index f20839d7..3d68bb77 100644 --- a/README.md +++ b/README.md @@ -4,7 +4,7 @@ -## About this project +## About This Project `@cap-js/telemetry` is a CDS plugin providing observability features, including [automatic OpenTelemetry instrumentation](https://opentelemetry.io/docs/concepts/instrumentation/automatic). @@ -14,7 +14,7 @@ Documentation can be found at [cap.cloud.sap](https://cap.cloud.sap/docs) and [o ## Table of Contents -- [About this project](#about-this-project) +- [About This Project](#about-this-project) - [Requirements](#requirements) - [Setup](#setup) - [Telemetry Signals](#telemetry-signals) @@ -33,7 +33,9 @@ Documentation can be found at [cap.cloud.sap](https://cap.cloud.sap/docs) and [o - [Sampler](#sampler) - [Propagators](#propagators) - [Exporters](#exporters) - - [Environment variables](#environment-variables) + - [High Resolution Timestamps (beta)](#high-resolution-timestamps) + - [Environment Variables](#environment-variables) +- [Custom Spans (beta)](#custom-spans) - [Support, Feedback, Contributing](#support-feedback-contributing) - [Code of Conduct](#code-of-conduct) - [Licensing](#licensing) @@ -79,6 +81,7 @@ The following briefly describes, how each is addressed in `@cap-js/telemetry`. For more information on signals in general, please refer to https://opentelemetry.io/docs/concepts/signals. + ### Traces Traces allow you to analyze how a request, message, task, etc. is being processed throughout your distributed system. @@ -93,6 +96,7 @@ An example trace printed to the console can be found in [`telemetry-to-console`] In environments where Dynatrace OneAgent is installed (e.g., SAP BTP CF), no OpenTelemetry exporter is needed to transport the traces to Dynatrace. `@cap-js/telemetry` recognizes this and ignores any exporter config if the predefined kind [`telemetry-to-dynatrace`](#telemetry-to-dynatrace) is used. + ### Metrics Metrics are "measurements captured at runtime", which help you understand your app's health and performance. @@ -145,6 +149,7 @@ cds.on('listening', () => { module.exports = cds.server ``` + ### Logs Exporting logs via OpenTelemetry is not yet supported. @@ -155,6 +160,7 @@ Exporting logs via OpenTelemetry is not yet supported. There are three predefined kinds as follows: + ### `telemetry-to-console` Prints traces and metrics to the console as previously depicted (traces in [Setup](#setup) and metrics in [Telemetry Signals - Metrics](#metrics)). @@ -162,6 +168,7 @@ Prints traces and metrics to the console as previously depicted (traces in [Setu No additional dependencies are needed. This is the default kind in both development and production. + ### `telemetry-to-dynatrace` Exports traces and metrics to Dynatrace. @@ -207,6 +214,7 @@ Hence, additional dependency `@opentelemetry/exporter-trace-otlp-proto` and scop This is actually the perferred operating model for `telemetry-to-dynatrace` as it provides a better experience than exporting via OpenTelemetry. If dependency `@opentelemetry/exporter-trace-otlp-proto` is present anyway, `@cap-js/telemetry` will export the traces via OpenTelemetry as well. + ### `telemetry-to-cloud-logging` Exports traces and metrics to SAP Cloud Logging. @@ -228,6 +236,7 @@ In order to receive OpenTelemetry credentials in the binding to the SAP Cloud Lo } ``` + ### `telemetry-to-jaeger` Exports traces to Jaeger. @@ -263,6 +272,7 @@ Run Jaeger locally via [docker](https://www.docker.com): - With this, no custom credentials are needed - Open `localhost:16686` to see the traces + ### `telemetry-to-otlp` Exports traces and metrics to an OTLP/gRPC or OTLP/HTTP endpoint based on [environment variables](https://opentelemetry.io/docs/languages/sdk-configuration/otlp-exporter). @@ -280,6 +290,7 @@ Please note that `@cap-js/telemetry` does not validate the configuration via env ## Detailed Configuration Options + ### Configuration Pass Through In general, you can influence the configuration of a used module via the respective `config` node in `cds.env.requires.telemetry`. @@ -302,6 +313,7 @@ For example, it is possible to specify the `temporalityPreference` setting of th } ``` + ### Instrumentations Configure via `cds.requires.telemetry.instrumentations = { : { module, class, config? } }` @@ -321,6 +333,7 @@ Default: } ``` + ### Sampler Configure via `cds.requires.telemetry.tracing.sampler = { kind, root?, ratio? }` @@ -333,6 +346,7 @@ Default: } ``` + ### Propagators Configure via `cds.requires.telemetry.tracing.propagators = [ | { module, class, config? }]` @@ -342,6 +356,7 @@ Default: ["W3CTraceContextPropagator"] ``` + ### Exporters Configure via: @@ -441,14 +456,16 @@ Default: } ``` -### High resolution timestamps (beta) + +### High Resolution Timestamps (beta) {#high-resolution-timestamps} By default, the start time of a span is taken from `Date.now()` and, hence, has only millisecond resolution. Via `cds.requires.telemetry.tracing.hrtime = true`, you can instruct the plugin to specify the start and end times of spans, which it does with nanosecond resolution. This may result in minor drifts, especially for spans created by other instrumentations such as `@opentelemetry/instrumentation-http`. Hence, the `hrtime` mode is on by default in development but not in production. -### Environment variables + +### Environment Variables - `NO_TELEMETRY`: Disables the plugin - `NO_LOCATE`: Disables function location in tracing @@ -463,6 +480,13 @@ Please note that `process.env.VCAP_APPLICATION` and `process.env.CF_INSTANCE_GUI +## Custom Spans (beta) {#custom-spans} + +Custom spans can be added to the trace hierarchy via [`tracer.startActiveSpan()`](https://open-telemetry.github.io/opentelemetry-js/interfaces/_opentelemetry_api.Tracer.html#startActiveSpan). +For this, you need to create your own tracer via [TraceAPI.getTracer()](https://open-telemetry.github.io/opentelemetry-js/classes/_opentelemetry_api.TraceAPI.html#getTracer). + + + ## Support, Feedback, Contributing This project is open to feature requests/suggestions, bug reports etc. via [GitHub issues](https://github.com/cap-js/telemetry/issues). Contribution and feedback are encouraged and always welcome. For more information about how to contribute, the project structure, as well as additional contribution information, see our [Contribution Guidelines](CONTRIBUTING.md).