From e4dceea2baa1a7e90264d9357db26c42bfce8963 Mon Sep 17 00:00:00 2001 From: D050513 Date: Wed, 6 Nov 2024 11:53:33 +0100 Subject: [PATCH 01/15] feat: enable exporting logs via otel --- lib/index.js | 8 +++- lib/logging/index.js | 104 +++++++++++++++++++++++++++++++++++++++++++ lib/metrics/index.js | 1 + lib/tracing/index.js | 7 +-- 4 files changed, 116 insertions(+), 4 deletions(-) create mode 100644 lib/logging/index.js diff --git a/lib/index.js b/lib/index.js index 4675553..4e2b529 100644 --- a/lib/index.js +++ b/lib/index.js @@ -7,6 +7,7 @@ const { SEMRESATTRS_SERVICE_NAME, SEMRESATTRS_SERVICE_VERSION } = require('@open const tracing = require('./tracing') const metrics = require('./metrics') +const logging = require('./logging') const { getDiagLogLevel, getResource, _require } = require('./utils') function _getInstrumentations() { @@ -63,13 +64,18 @@ module.exports = function () { */ const meterProvider = metrics(resource) + /* + * setup logging + */ + const loggerProvider = logging(resource) + /* * register instrumentations */ registerInstrumentations({ tracerProvider, meterProvider, - // loggerProvider, + loggerProvider, instrumentations: _getInstrumentations() }) } diff --git a/lib/logging/index.js b/lib/logging/index.js new file mode 100644 index 0000000..31d75a7 --- /dev/null +++ b/lib/logging/index.js @@ -0,0 +1,104 @@ +const cds = require('@sap/cds') +const LOG = cds.log('telemetry') + +const { getEnv, getEnvWithoutDefaults } = require('@opentelemetry/core') + +const { getCredsForCLSAsUPS, augmentCLCreds, _require } = require('../utils') + +const _protocol2module = { + grpc: '@opentelemetry/exporter-logs-otlp-grpc', + 'http/protobuf': '@opentelemetry/exporter-logs-otlp-proto', + 'http/json': '@opentelemetry/exporter-logs-otlp-http' +} + +function _getExporter() { + let { + kind, + logging: { exporter: loggingExporter }, + credentials + } = cds.env.requires.telemetry + + // for kind telemetry-to-otlp based on env vars + if (loggingExporter === 'env') { + const otlp_env = getEnvWithoutDefaults() + const dflt_env = getEnv() + const protocol = + otlp_env.OTEL_EXPORTER_OTLP_LOGS_PROTOCOL ?? + otlp_env.OTEL_EXPORTER_OTLP_PROTOCOL ?? + dflt_env.OTEL_EXPORTER_OTLP_LOGS_PROTOCOL ?? + dflt_env.OTEL_EXPORTER_OTLP_PROTOCOL + loggingExporter = { module: _protocol2module[protocol], class: 'OTLPLogExporter' } + } + + // use _require for better error message + const loggingExporterModule = _require(loggingExporter.module) + if (!loggingExporterModule[loggingExporter.class]) + throw new Error(`Unknown logs exporter "${loggingExporter.class}" in module "${loggingExporter.module}"`) + const loggingConfig = { ...(loggingExporter.config || {}) } + + if (kind.match(/to-cloud-logging$/)) { + if (!credentials) credentials = getCredsForCLSAsUPS() + if (!credentials) throw new Error('No SAP Cloud Logging credentials found.') + augmentCLCreds(credentials) + loggingConfig.url ??= credentials.url + loggingConfig.credentials ??= credentials.credentials + } + + const exporter = new loggingExporterModule[loggingExporter.class](loggingConfig) + LOG._debug && LOG.debug('Using logs exporter:', exporter) + + return exporter +} + +module.exports = resource => { + if (!cds.env.requires.telemetry.logging?.exporter) return + + const { logs, SeverityNumber } = require('@opentelemetry/api-logs') + const { LoggerProvider, BatchLogRecordProcessor } = require('@opentelemetry/sdk-logs') + + let loggerProvider = logs.getLoggerProvider() + if (!loggerProvider.getDelegateLogger()) { + loggerProvider = new LoggerProvider({ resource }) + logs.setGlobalLoggerProvider(loggerProvider) + } else { + LOG._warn && LOG.warn('LoggerProvider already initialized by a different module. It will be used as is.') + loggerProvider = loggerProvider.getDelegateLogger() + } + + const exporter = _getExporter() + loggerProvider.addLogRecordProcessor(new BatchLogRecordProcessor(exporter)) + + const loggers = {} + const l2s = { 1: 'ERROR', 2: 'WARN', 3: 'INFO', 4: 'DEBUG', 5: 'TRACE' } + + // intercept logs via format + const { format } = cds.log + cds.log.format = (module, level, ...args) => { + const res = format(module, level, ...args) + + let log + try { + log = res.length === 1 && res[0].startsWith?.('{"') && JSON.parse(res[0]) + } catch { + // ignore + } + if (log) { + const logger = loggers[module] || (loggers[module] = loggerProvider.getLogger(module)) + const severity = l2s[level] + // TODO: what to log? + logger.emit({ + severityNumber: SeverityNumber[severity], + severityText: severity, + body: log.msg, + attributes: { 'log.type': 'LogRecord' } + }) + } + + return res + } + + // clear cached loggers + cds.log.loggers = {} + + return loggerProvider +} diff --git a/lib/metrics/index.js b/lib/metrics/index.js index e708b66..a86bd6d 100644 --- a/lib/metrics/index.js +++ b/lib/metrics/index.js @@ -54,6 +54,7 @@ function _getExporter() { const exporter = new metricsExporterModule[metricsExporter.class](metricsConfig) LOG._debug && LOG.debug('Using metrics exporter:', exporter) + return exporter } diff --git a/lib/tracing/index.js b/lib/tracing/index.js index 0b0367c..0d0919e 100644 --- a/lib/tracing/index.js +++ b/lib/tracing/index.js @@ -80,7 +80,7 @@ function _getExporter() { const tracingExporterModule = tracingExporter.module === '@cap-js/telemetry' ? require('../exporter') : _require(tracingExporter.module) if (!tracingExporterModule[tracingExporter.class]) - throw new Error(`Unknown tracing exporter "${tracingExporter.class}" in module "${tracingExporter.module}"`) + throw new Error(`Unknown trace exporter "${tracingExporter.class}" in module "${tracingExporter.module}"`) const tracingConfig = { ...(tracingExporter.config || {}) } if (kind.match(/dynatrace/)) { @@ -105,7 +105,8 @@ function _getExporter() { } const exporter = new tracingExporterModule[tracingExporter.class](tracingConfig) - LOG._debug && LOG.debug('Using tracing exporter:', exporter) + LOG._debug && LOG.debug('Using trace exporter:', exporter) + return exporter } @@ -131,7 +132,7 @@ module.exports = resource => { !hasDependency('@opentelemetry/exporter-trace-otlp-proto') if (via_one_agent) { // if Dynatrace OneAgent is present, no exporter is needed - LOG._info && LOG.info('Dynatrace OneAgent detected, disabling tracing exporter') + LOG._info && LOG.info('Dynatrace OneAgent detected, disabling trace exporter') } else { const exporter = _getExporter() const spanProcessor = From 25740ce82ccbed5262615c58bc383e8191ddcc57 Mon Sep 17 00:00:00 2001 From: D050513 Date: Wed, 6 Nov 2024 12:12:38 +0100 Subject: [PATCH 02/15] changelog --- CHANGELOG.md | 19 ++++++++++++++----- 1 file changed, 14 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index dca6e29..92246ff 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,10 +9,19 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Added - Predefined kind `telemetry-to-otlp` that creates exporters based on OTLP exporter configuration via environment variables +- If `@opentelemetry/instrumentation-runtime-node` is in the project's dependencies but not in `cds.requires.telemetry.instrumentations`, it is registered automatically + - Disable via `cds.requires.telemetry.instrumentations.instrumentation-runtime-node = false` - Experimental!: Propagate W3C trace context to SAP HANA via session context `SAP_PASSPORT` - Enable via environment variable `SAP_PASSPORT` -- If `@opentelemetry/instrumentation-runtime-node` is in the project's dependencies but not in `cds.env.requires.telemetry.instrumentations`, it is registered automatically - - Disable via `cds.env.requires.telemetry.instrumentations.instrumentation-runtime-node = false` +- Experimental!: Intercept and export application logs (cf. `cds.log()`) via OpenTelemetry + - Enable by adding section `logging` to `cds.requires.telemetry` as follows (using `grpc` as an example): + ```json + "logging": { + "module": "@opentelemetry/exporter-logs-otlp-grpc", + "class": "OTLPLogExporter" + } + ``` + - Requires additional dependencies `@opentelemetry/api-logs`, `@opentelemetry/sdk-logs`, and the configured exporter module (`cds.requires.telemetry.logging.module`) ### Changed @@ -77,7 +86,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Added - Support for local modules (e.g., exporters) via `[...].module = ''` -- Disable pool metrics via `cds.env.requires.telemetry.metrics._db_pool = false` (beta) +- Disable pool metrics via `cds.requires.telemetry.metrics._db_pool = false` (beta) ### Fixed @@ -90,7 +99,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Added - Support for own, high resolution timestamps - - Enable via `cds.env.requires.telemetry.tracing.hrtime = true` + - Enable via `cds.requires.telemetry.tracing.hrtime = true` - Enabled by default in development profile ## Version 0.0.5 - 2024-03-11 @@ -107,7 +116,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). - Disable change via environment variable `HOST_METRICS_RETAIN_SYSTEM=true` - Metric exporter's property `temporalityPreference` always gets defaulted to `DELTA` - Was previously only done for kind `telemetry-to-dynatrace` - - Set custom value via `cds.env.requires.telemetry.metrics.exporter.config.temporalityPreference` + - Set custom value via `cds.requires.telemetry.metrics.exporter.config.temporalityPreference` ### Fixed From c10c3147a635718265a11f872ec8c3d35f337ad5 Mon Sep 17 00:00:00 2001 From: D050513 Date: Wed, 6 Nov 2024 12:17:11 +0100 Subject: [PATCH 03/15] fix cl --- CHANGELOG.md | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 92246ff..d65a2e6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -17,8 +17,10 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). - Enable by adding section `logging` to `cds.requires.telemetry` as follows (using `grpc` as an example): ```json "logging": { - "module": "@opentelemetry/exporter-logs-otlp-grpc", - "class": "OTLPLogExporter" + "exporter": { + "module": "@opentelemetry/exporter-logs-otlp-grpc", + "class": "OTLPLogExporter" + } } ``` - Requires additional dependencies `@opentelemetry/api-logs`, `@opentelemetry/sdk-logs`, and the configured exporter module (`cds.requires.telemetry.logging.module`) From 94cb036dd2ebe833b4c838e8538b60e6ee3f2b79 Mon Sep 17 00:00:00 2001 From: D050513 Date: Thu, 28 Nov 2024 10:59:12 +0100 Subject: [PATCH 04/15] test --- lib/logging/index.js | 8 ++++++-- test/bookshop/srv/admin-service.cds | 1 + test/bookshop/srv/admin-service.js | 4 ++++ test/logging.test.js | 29 +++++++++++++++++++++++++++++ 4 files changed, 40 insertions(+), 2 deletions(-) create mode 100644 test/logging.test.js diff --git a/lib/logging/index.js b/lib/logging/index.js index 31d75a7..3191563 100644 --- a/lib/logging/index.js +++ b/lib/logging/index.js @@ -54,7 +54,7 @@ module.exports = resource => { if (!cds.env.requires.telemetry.logging?.exporter) return const { logs, SeverityNumber } = require('@opentelemetry/api-logs') - const { LoggerProvider, BatchLogRecordProcessor } = require('@opentelemetry/sdk-logs') + const { LoggerProvider, BatchLogRecordProcessor, SimpleLogRecordProcessor } = require('@opentelemetry/sdk-logs') let loggerProvider = logs.getLoggerProvider() if (!loggerProvider.getDelegateLogger()) { @@ -66,7 +66,11 @@ module.exports = resource => { } const exporter = _getExporter() - loggerProvider.addLogRecordProcessor(new BatchLogRecordProcessor(exporter)) + const logProcessor = + process.env.NODE_ENV === 'production' + ? new BatchLogRecordProcessor(exporter) + : new SimpleLogRecordProcessor(exporter) + loggerProvider.addLogRecordProcessor(logProcessor) const loggers = {} const l2s = { 1: 'ERROR', 2: 'WARN', 3: 'INFO', 4: 'DEBUG', 5: 'TRACE' } diff --git a/test/bookshop/srv/admin-service.cds b/test/bookshop/srv/admin-service.cds index 2cacb2b..f3d2064 100644 --- a/test/bookshop/srv/admin-service.cds +++ b/test/bookshop/srv/admin-service.cds @@ -3,6 +3,7 @@ using { sap.capire.bookshop as my } from '../db/schema'; service AdminService @(requires:'admin') { entity Books as projection on my.Books; entity Authors as projection on my.Authors; + entity Genres as projection on my.Genres; action spawn(); } diff --git a/test/bookshop/srv/admin-service.js b/test/bookshop/srv/admin-service.js index 950caef..ea4a3c6 100644 --- a/test/bookshop/srv/admin-service.js +++ b/test/bookshop/srv/admin-service.js @@ -3,6 +3,10 @@ const cds = require('@sap/cds/lib') module.exports = class AdminService extends cds.ApplicationService { init(){ this.before ('NEW','Books.drafts', genid) + this.before('READ', 'Genres', () => { + cds.log('AdminService').info('Hello, World!') + }) + this.on('spawn', () => { cds.spawn({ after: 3 }, async () => { await SELECT.from('sap.capire.bookshop.Books') diff --git a/test/logging.test.js b/test/logging.test.js new file mode 100644 index 0000000..dc176c2 --- /dev/null +++ b/test/logging.test.js @@ -0,0 +1,29 @@ +/* eslint-disable no-console */ + +process.env.cds_requires_telemetry_logging_exporter_module = '@opentelemetry/sdk-logs' +process.env.cds_requires_telemetry_logging_exporter_class = 'ConsoleLogRecordExporter' +process.env.cds_log_format = 'json' + +const cds = require('@sap/cds') +const { expect, GET } = cds.test().in(__dirname + '/bookshop') + +describe('logging', () => { + const admin = { auth: { username: 'alice' } } + + const { dir } = console + beforeEach(() => { + console.dir = jest.fn() + }) + afterAll(() => { + console.dir = dir + }) + + test('it works', async () => { + const { status } = await GET('/odata/v4/admin/Genres', admin) + expect(status).to.equal(200) + const logs = console.dir.mock.calls.map(([log]) => log) + expect(logs.length).to.equal(2) + expect(logs[0]).to.include({ body: 'GET /odata/v4/admin/Genres ' }) //> why the trailing space? + expect(logs[1]).to.include({ body: 'Hello, World!' }) + }) +}) From b21d96ad1f440ecafa85d485e59e9dbbda271506 Mon Sep 17 00:00:00 2001 From: D050513 Date: Thu, 28 Nov 2024 13:13:59 +0100 Subject: [PATCH 05/15] custom processor --- lib/logging/index.js | 32 +++++++++++++++---- lib/metrics/index.js | 16 +++++----- lib/tracing/index.js | 14 ++++---- lib/tracing/trace.js | 3 +- .../lib/MySimpleLogRecordProcessor.js | 9 ++++++ test/logging.test.js | 7 +++- 6 files changed, 57 insertions(+), 24 deletions(-) create mode 100644 test/bookshop/lib/MySimpleLogRecordProcessor.js diff --git a/lib/logging/index.js b/lib/logging/index.js index 3191563..ca3ccfe 100644 --- a/lib/logging/index.js +++ b/lib/logging/index.js @@ -34,22 +34,40 @@ function _getExporter() { const loggingExporterModule = _require(loggingExporter.module) if (!loggingExporterModule[loggingExporter.class]) throw new Error(`Unknown logs exporter "${loggingExporter.class}" in module "${loggingExporter.module}"`) - const loggingConfig = { ...(loggingExporter.config || {}) } + const config = { ...(loggingExporter.config || {}) } if (kind.match(/to-cloud-logging$/)) { if (!credentials) credentials = getCredsForCLSAsUPS() if (!credentials) throw new Error('No SAP Cloud Logging credentials found.') augmentCLCreds(credentials) - loggingConfig.url ??= credentials.url - loggingConfig.credentials ??= credentials.credentials + config.url ??= credentials.url + config.credentials ??= credentials.credentials } - const exporter = new loggingExporterModule[loggingExporter.class](loggingConfig) + const exporter = new loggingExporterModule[loggingExporter.class](config) LOG._debug && LOG.debug('Using logs exporter:', exporter) return exporter } +function _getCustomProcessor(exporter) { + let { + logging: { processor: loggingProcessor } + } = cds.env.requires.telemetry + + if (!loggingProcessor) return + + // use _require for better error message + const loggingProcessorModule = _require(loggingProcessor.module) + if (!loggingProcessorModule[loggingProcessor.class]) + throw new Error(`Unknown logs processor "${loggingProcessor.class}" in module "${loggingProcessor.module}"`) + + const processor = new loggingProcessorModule[loggingProcessor.class](exporter) + LOG._debug && LOG.debug('Using logs processor:', processor) + + return processor +} + module.exports = resource => { if (!cds.env.requires.telemetry.logging?.exporter) return @@ -66,10 +84,12 @@ module.exports = resource => { } const exporter = _getExporter() + const logProcessor = - process.env.NODE_ENV === 'production' + _getCustomProcessor(exporter) || + (process.env.NODE_ENV === 'production' ? new BatchLogRecordProcessor(exporter) - : new SimpleLogRecordProcessor(exporter) + : new SimpleLogRecordProcessor(exporter)) loggerProvider.addLogRecordProcessor(logProcessor) const loggers = {} diff --git a/lib/metrics/index.js b/lib/metrics/index.js index f52e66c..09bb635 100644 --- a/lib/metrics/index.js +++ b/lib/metrics/index.js @@ -44,34 +44,34 @@ function _getExporter() { metricsExporter.module === '@cap-js/telemetry' ? require('../exporter') : _require(metricsExporter.module) if (!metricsExporterModule[metricsExporter.class]) throw new Error(`Unknown metrics exporter "${metricsExporter.class}" in module "${metricsExporter.module}"`) - const metricsConfig = { ...(metricsExporter.config || {}) } + const config = { ...(metricsExporter.config || {}) } if (kind.match(/to-dynatrace$/)) { if (!credentials) credentials = getCredsForDTAsUPS() if (!credentials) throw new Error('No Dynatrace credentials found.') - metricsConfig.url ??= `${credentials.apiurl}/v2/otlp/v1/metrics` - metricsConfig.headers ??= {} + config.url ??= `${credentials.apiurl}/v2/otlp/v1/metrics` + config.headers ??= {} // credentials.rest_apitoken?.token is deprecated and only supported for compatibility reasons const { token_name } = cds.env.requires.telemetry // metrics_apitoken for compatibility with previous releases const token = credentials[token_name] || credentials.metrics_apitoken || credentials.rest_apitoken?.token if (!token) throw new Error(`Neither "${token_name}" nor deprecated "rest_apitoken.token" found in Dynatrace credentials`) - metricsConfig.headers.authorization ??= `Api-Token ${token}` + config.headers.authorization ??= `Api-Token ${token}` } if (kind.match(/to-cloud-logging$/)) { if (!credentials) credentials = getCredsForCLSAsUPS() if (!credentials) throw new Error('No SAP Cloud Logging credentials found.') augmentCLCreds(credentials) - metricsConfig.url ??= credentials.url - metricsConfig.credentials ??= credentials.credentials + config.url ??= credentials.url + config.credentials ??= credentials.credentials } // default to DELTA - metricsConfig.temporalityPreference ??= AggregationTemporality.DELTA + config.temporalityPreference ??= AggregationTemporality.DELTA - const exporter = new metricsExporterModule[metricsExporter.class](metricsConfig) + const exporter = new metricsExporterModule[metricsExporter.class](config) LOG._debug && LOG.debug('Using metrics exporter:', exporter) return exporter diff --git a/lib/tracing/index.js b/lib/tracing/index.js index e7c3a90..53cdc23 100644 --- a/lib/tracing/index.js +++ b/lib/tracing/index.js @@ -100,30 +100,30 @@ function _getExporter() { tracingExporter.module === '@cap-js/telemetry' ? require('../exporter') : _require(tracingExporter.module) if (!tracingExporterModule[tracingExporter.class]) throw new Error(`Unknown trace exporter "${tracingExporter.class}" in module "${tracingExporter.module}"`) - const tracingConfig = { ...(tracingExporter.config || {}) } + const config = { ...(tracingExporter.config || {}) } if (kind.match(/to-dynatrace$/)) { if (!credentials) credentials = getCredsForDTAsUPS() if (!credentials) throw new Error('No Dynatrace credentials found') - tracingConfig.url ??= `${credentials.apiurl}/v2/otlp/v1/traces` - tracingConfig.headers ??= {} + config.url ??= `${credentials.apiurl}/v2/otlp/v1/traces` + config.headers ??= {} // credentials.rest_apitoken?.token is deprecated and only supported for compatibility reasons const { token_name } = cds.env.requires.telemetry const token = credentials[token_name] || credentials.rest_apitoken?.token if (!token) throw new Error(`Neither "${token_name}" nor deprecated "rest_apitoken.token" found in Dynatrace credentials`) - tracingConfig.headers.authorization ??= `Api-Token ${token}` + config.headers.authorization ??= `Api-Token ${token}` } if (kind.match(/to-cloud-logging$/)) { if (!credentials) credentials = getCredsForCLSAsUPS() if (!credentials) throw new Error('No SAP Cloud Logging credentials found') augmentCLCreds(credentials) - tracingConfig.url ??= credentials.url - tracingConfig.credentials ??= credentials.credentials + config.url ??= credentials.url + config.credentials ??= credentials.credentials } - const exporter = new tracingExporterModule[tracingExporter.class](tracingConfig) + const exporter = new tracingExporterModule[tracingExporter.class](config) LOG._debug && LOG.debug('Using trace exporter:', exporter) return exporter diff --git a/lib/tracing/trace.js b/lib/tracing/trace.js index a449a05..fcf0115 100644 --- a/lib/tracing/trace.js +++ b/lib/tracing/trace.js @@ -58,8 +58,7 @@ 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) } diff --git a/test/bookshop/lib/MySimpleLogRecordProcessor.js b/test/bookshop/lib/MySimpleLogRecordProcessor.js new file mode 100644 index 0000000..f274c97 --- /dev/null +++ b/test/bookshop/lib/MySimpleLogRecordProcessor.js @@ -0,0 +1,9 @@ +const { SimpleLogRecordProcessor } = require('@opentelemetry/sdk-logs') + +class MySimpleLogRecordProcessor extends SimpleLogRecordProcessor { + onEmit(logRecord) { + return super.onEmit(logRecord) + } +} + +module.exports = { MySimpleLogRecordProcessor } diff --git a/test/logging.test.js b/test/logging.test.js index dc176c2..5392c25 100644 --- a/test/logging.test.js +++ b/test/logging.test.js @@ -1,8 +1,13 @@ /* eslint-disable no-console */ +process.env.cds_log_format = 'json' + process.env.cds_requires_telemetry_logging_exporter_module = '@opentelemetry/sdk-logs' process.env.cds_requires_telemetry_logging_exporter_class = 'ConsoleLogRecordExporter' -process.env.cds_log_format = 'json' + +// experimental feature of the experimental feature!!! +process.env.cds_requires_telemetry_logging_processor_module = './lib/MySimpleLogRecordProcessor.js' +process.env.cds_requires_telemetry_logging_processor_class = 'MySimpleLogRecordProcessor' const cds = require('@sap/cds') const { expect, GET } = cds.test().in(__dirname + '/bookshop') From db7ac1beb852c98d0a6237f783127cf08ad6472f Mon Sep 17 00:00:00 2001 From: D050513 Date: Wed, 5 Feb 2025 21:55:15 +0100 Subject: [PATCH 06/15] TODO --- README.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/README.md b/README.md index 3d68bb7..374c14d 100644 --- a/README.md +++ b/README.md @@ -152,6 +152,8 @@ module.exports = cds.server ### Logs +// TODO! + Exporting logs via OpenTelemetry is not yet supported. From c04809fccfc53bd95262356c8fdd52e1d7878ab7 Mon Sep 17 00:00:00 2001 From: D050513 Date: Wed, 5 Feb 2025 21:58:25 +0100 Subject: [PATCH 07/15] on served --- lib/logging/index.js | 60 +++++++++++++++++++++++--------------------- 1 file changed, 31 insertions(+), 29 deletions(-) diff --git a/lib/logging/index.js b/lib/logging/index.js index ca3ccfe..e6a1924 100644 --- a/lib/logging/index.js +++ b/lib/logging/index.js @@ -92,37 +92,39 @@ module.exports = resource => { : new SimpleLogRecordProcessor(exporter)) loggerProvider.addLogRecordProcessor(logProcessor) - const loggers = {} - const l2s = { 1: 'ERROR', 2: 'WARN', 3: 'INFO', 4: 'DEBUG', 5: 'TRACE' } - - // intercept logs via format - const { format } = cds.log - cds.log.format = (module, level, ...args) => { - const res = format(module, level, ...args) - - let log - try { - log = res.length === 1 && res[0].startsWith?.('{"') && JSON.parse(res[0]) - } catch { - // ignore + cds.on('served', () => { + const loggers = {} + const l2s = { 1: 'ERROR', 2: 'WARN', 3: 'INFO', 4: 'DEBUG', 5: 'TRACE' } + + // intercept logs via format + const { format } = cds.log + cds.log.format = (module, level, ...args) => { + const res = format(module, level, ...args) + + let log + try { + log = res.length === 1 && res[0].startsWith?.('{"') && JSON.parse(res[0]) + } catch { + // ignore + } + if (log) { + const logger = loggers[module] || (loggers[module] = loggerProvider.getLogger(module)) + const severity = l2s[level] + // TODO: what to log? + logger.emit({ + severityNumber: SeverityNumber[severity], + severityText: severity, + body: log.msg, + attributes: { 'log.type': 'LogRecord' } + }) + } + + return res } - if (log) { - const logger = loggers[module] || (loggers[module] = loggerProvider.getLogger(module)) - const severity = l2s[level] - // TODO: what to log? - logger.emit({ - severityNumber: SeverityNumber[severity], - severityText: severity, - body: log.msg, - attributes: { 'log.type': 'LogRecord' } - }) - } - - return res - } - // clear cached loggers - cds.log.loggers = {} + // clear cached loggers + cds.log.loggers = {} + }) return loggerProvider } From 78526c92b4f7e281e1cbba1afb0a8c070b4028d8 Mon Sep 17 00:00:00 2001 From: D050513 Date: Wed, 5 Feb 2025 23:18:21 +0100 Subject: [PATCH 08/15] attributes + readme --- CHANGELOG.md | 25 +++++++++++++------------ README.md | 17 ++++++++++++++--- lib/index.js | 2 +- lib/logging/index.js | 19 +++++++++++++++---- test/bookshop/package.json | 9 +++++++++ test/bookshop/srv/admin-service.js | 5 +++++ test/bookshop/test.http | 5 +++++ 7 files changed, 62 insertions(+), 20 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8c848c7..f13fee0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,8 +12,20 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). - Support for adding custom spans to trace hierarchy via `tracer.startActiveSpan()` (beta) - Trace attribute `db.client.response.returned_rows` for queries via `cds.ql` - Experimental!: Trace HANA interaction via `@cap-js/hana`'s promisification of the driver API for increased accuracy - - Enable via config `cds.env.requires.telemetry.tracing._hana_prom` + - Enable via config `cds.requires.telemetry.tracing._hana_prom` - Requires `@cap-js/hana^1.7.0` +- Experimental!: Intercept and export application logs (cf. `cds.log()`) via OpenTelemetry + - Enable by adding section `logging` to `cds.requires.telemetry` as follows (using `grpc` as an example): + ```json + "logging": { + "exporter": { + "module": "@opentelemetry/exporter-logs-otlp-grpc", + "class": "OTLPLogExporter" + }, + "custom_fields": ["foo", "bar"] + } + ``` + - Requires additional dependencies `@opentelemetry/api-logs`, `@opentelemetry/sdk-logs`, and the configured exporter module (`cds.requires.telemetry.logging.module`) ### Changed @@ -44,17 +56,6 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). - Disable via `cds.requires.telemetry.instrumentations.instrumentation-runtime-node = false` - Experimental!: Propagate W3C trace context to SAP HANA via session context `SAP_PASSPORT` - Enable via environment variable `SAP_PASSPORT` -- Experimental!: Intercept and export application logs (cf. `cds.log()`) via OpenTelemetry - - Enable by adding section `logging` to `cds.requires.telemetry` as follows (using `grpc` as an example): - ```json - "logging": { - "exporter": { - "module": "@opentelemetry/exporter-logs-otlp-grpc", - "class": "OTLPLogExporter" - } - } - ``` - - Requires additional dependencies `@opentelemetry/api-logs`, `@opentelemetry/sdk-logs`, and the configured exporter module (`cds.requires.telemetry.logging.module`) ### Changed diff --git a/README.md b/README.md index 374c14d..6858ec8 100644 --- a/README.md +++ b/README.md @@ -152,9 +152,20 @@ module.exports = cds.server ### Logs -// TODO! - -Exporting logs via OpenTelemetry is not yet supported. +Exporting logs via OpenTelemetry is supported as an experimental opt-in feature. +Enable by adding section `logging` to `cds.requires.telemetry` as follows (using `grpc` as an example): +```json +"logging": { + "exporter": { + "module": "@opentelemetry/exporter-logs-otlp-grpc", + "class": "OTLPLogExporter" + }, + "custom_fields": [ + "foo", + "bar" + ] +} +``` diff --git a/lib/index.js b/lib/index.js index 6a2a285..9a7d311 100644 --- a/lib/index.js +++ b/lib/index.js @@ -60,7 +60,7 @@ module.exports = function () { /* * setup logging */ - const loggerProvider = logging(resource) + const loggerProvider = cds.env.requires.telemetry.logging ? logging(resource) : undefined /* * register instrumentations diff --git a/lib/logging/index.js b/lib/logging/index.js index e6a1924..5c80d47 100644 --- a/lib/logging/index.js +++ b/lib/logging/index.js @@ -96,10 +96,12 @@ module.exports = resource => { const loggers = {} const l2s = { 1: 'ERROR', 2: 'WARN', 3: 'INFO', 4: 'DEBUG', 5: 'TRACE' } + const custom_fields = cds.env.requires.telemetry.logging.custom_fields || [] + // intercept logs via format const { format } = cds.log - cds.log.format = (module, level, ...args) => { - const res = format(module, level, ...args) + cds.log.format = function (module, level, ...args) { + const res = format.call(this, module, level, ...args) let log try { @@ -110,12 +112,21 @@ module.exports = resource => { if (log) { const logger = loggers[module] || (loggers[module] = loggerProvider.getLogger(module)) const severity = l2s[level] - // TODO: what to log? + const attributes = { + 'log.type': 'LogRecord' + } + let e = args.find(a => a instanceof Error) + if (e) { + attributes['exception.message'] = e.message + attributes['exception.stacktrace'] = e.stack + attributes['exception.type'] = e.name + } + for (const field of custom_fields) if (field in log) attributes[field] = log[field] logger.emit({ severityNumber: SeverityNumber[severity], severityText: severity, body: log.msg, - attributes: { 'log.type': 'LogRecord' } + attributes }) } diff --git a/test/bookshop/package.json b/test/bookshop/package.json index fb79f48..9fcd80c 100644 --- a/test/bookshop/package.json +++ b/test/bookshop/package.json @@ -31,6 +31,15 @@ "module": "@opentelemetry/sdk-trace-base", "class": "ConsoleSpanExporter" } + }, + "_logging": { + "exporter": { + "module": "@opentelemetry/exporter-logs-otlp-grpc", + "class": "OTLPLogExporter" + }, + "custom_fields": [ + "tenant_id" + ] } }, "[multitenancy]": { diff --git a/test/bookshop/srv/admin-service.js b/test/bookshop/srv/admin-service.js index 93ab7b5..173c2dd 100644 --- a/test/bookshop/srv/admin-service.js +++ b/test/bookshop/srv/admin-service.js @@ -12,6 +12,11 @@ module.exports = class AdminService extends cds.ApplicationService { this.before('READ', 'Genres', () => { cds.log('AdminService').info('Hello, World!') + try { + this.doesnt.exist + } catch (err) { + cds.log('AdminService').error(err) + } }) this.on('test_spawn', () => { diff --git a/test/bookshop/test.http b/test/bookshop/test.http index 520ac47..370f1ef 100644 --- a/test/bookshop/test.http +++ b/test/bookshop/test.http @@ -59,3 +59,8 @@ Content-Type: application/json GET {{host}}/odata/v4/catalog/ListOfBooks Authorization: Basic alice:wonderland + +### + +GET {{host}}/odata/v4/admin/Genres +Authorization: Basic alice:wonderland From 5729b7853b249eaf7cecaf55beb1ec1ef32a12fc Mon Sep 17 00:00:00 2001 From: D050513 Date: Thu, 6 Feb 2025 11:05:32 +0100 Subject: [PATCH 09/15] replace format function of existing loggers --- lib/logging/index.js | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/lib/logging/index.js b/lib/logging/index.js index 5c80d47..36548aa 100644 --- a/lib/logging/index.js +++ b/lib/logging/index.js @@ -99,9 +99,9 @@ module.exports = resource => { const custom_fields = cds.env.requires.telemetry.logging.custom_fields || [] // intercept logs via format - const { format } = cds.log - cds.log.format = function (module, level, ...args) { - const res = format.call(this, module, level, ...args) + const { format: _format } = cds.log + const format = cds.log.format = function (module, level, ...args) { + const res = _format.call(this, module, level, ...args) let log try { @@ -133,8 +133,8 @@ module.exports = resource => { return res } - // clear cached loggers - cds.log.loggers = {} + // replace format function of existing loggers + for (const each in cds.log.loggers) cds.log.loggers[each].setFormat(format) }) return loggerProvider From ccbdfb0ea745c0b359545d75540a2361d96af6ce Mon Sep 17 00:00:00 2001 From: D050513 Date: Thu, 6 Feb 2025 11:05:46 +0100 Subject: [PATCH 10/15] better test --- test/bookshop/srv/admin-service.js | 3 ++- test/logging.test.js | 36 ++++++++++++++++++++++++------ 2 files changed, 31 insertions(+), 8 deletions(-) diff --git a/test/bookshop/srv/admin-service.js b/test/bookshop/srv/admin-service.js index 173c2dd..5923cf5 100644 --- a/test/bookshop/srv/admin-service.js +++ b/test/bookshop/srv/admin-service.js @@ -15,7 +15,8 @@ module.exports = class AdminService extends cds.ApplicationService { try { this.doesnt.exist } catch (err) { - cds.log('AdminService').error(err) + err.foo = 'bar' + cds.log('AdminService').error('Oh no!', err) } }) diff --git a/test/logging.test.js b/test/logging.test.js index 5392c25..6ec3416 100644 --- a/test/logging.test.js +++ b/test/logging.test.js @@ -2,12 +2,23 @@ process.env.cds_log_format = 'json' -process.env.cds_requires_telemetry_logging_exporter_module = '@opentelemetry/sdk-logs' -process.env.cds_requires_telemetry_logging_exporter_class = 'ConsoleLogRecordExporter' - -// experimental feature of the experimental feature!!! -process.env.cds_requires_telemetry_logging_processor_module = './lib/MySimpleLogRecordProcessor.js' -process.env.cds_requires_telemetry_logging_processor_class = 'MySimpleLogRecordProcessor' +process.env.cds_requires_telemetry = JSON.stringify({ + instrumentations: { + http: { config: { ignoreIncomingPaths: ['/odata/v4/admin/Genres'] } } + }, + logging: { + exporter: { + module: '@opentelemetry/sdk-logs', + class: 'ConsoleLogRecordExporter' + }, + custom_fields: ['foo'], + // experimental feature of the experimental feature!!! + processor: { + module: './lib/MySimpleLogRecordProcessor.js', + class: 'MySimpleLogRecordProcessor' + } + } +}) const cds = require('@sap/cds') const { expect, GET } = cds.test().in(__dirname + '/bookshop') @@ -27,8 +38,19 @@ describe('logging', () => { const { status } = await GET('/odata/v4/admin/Genres', admin) expect(status).to.equal(200) const logs = console.dir.mock.calls.map(([log]) => log) - expect(logs.length).to.equal(2) + expect(logs.length).to.equal(3) expect(logs[0]).to.include({ body: 'GET /odata/v4/admin/Genres ' }) //> why the trailing space? expect(logs[1]).to.include({ body: 'Hello, World!' }) + expect(logs[2]).to.deep.include({ + body: "Oh no! Cannot read properties of undefined (reading 'exist')", + attributes: { + 'log.type': 'LogRecord', + 'exception.message': "Cannot read properties of undefined (reading 'exist')", + 'exception.stacktrace': + "TypeError: Cannot read properties of undefined (reading 'exist')\n at AdminService.exist (/Users/d050513/git/cap-js/telemetry/test/bookshop/srv/admin-service.js:16:21)\n at /Users/d050513/git/cap-js/telemetry/node_modules/@sap/cds/lib/srv/srv-dispatch.js:59:59\n at Array.map ()\n at AdminService.handle (/Users/d050513/git/cap-js/telemetry/node_modules/@sap/cds/lib/srv/srv-dispatch.js:59:33)\n at processTicksAndRejections (node:internal/process/task_queues:105:5)\n at AdminService.handle (/Users/d050513/git/cap-js/telemetry/node_modules/@sap/cds/libx/_runtime/common/Service.js:84:16)", + 'exception.type': 'TypeError', + foo: 'bar' + } + }) }) }) From 036706c71e7d5c648598f6941fe4fe505a3c6948 Mon Sep 17 00:00:00 2001 From: D050513 Date: Thu, 6 Feb 2025 11:08:25 +0100 Subject: [PATCH 11/15] readme --- README.md | 1 + 1 file changed, 1 insertion(+) diff --git a/README.md b/README.md index 6858ec8..5957239 100644 --- a/README.md +++ b/README.md @@ -166,6 +166,7 @@ Enable by adding section `logging` to `cds.requires.telemetry` as follows (using ] } ``` +Additionally, `cds.log()`'s JSON log formatter must be active (the default in production but not in development). From 92697174f6d81522ce1144b485992e59e03e1ee0 Mon Sep 17 00:00:00 2001 From: sjvans <30337871+sjvans@users.noreply.github.com> Date: Thu, 6 Feb 2025 11:12:49 +0100 Subject: [PATCH 12/15] readme --- README.md | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index 5957239..4dbefbe 100644 --- a/README.md +++ b/README.md @@ -153,7 +153,7 @@ module.exports = cds.server ### Logs Exporting logs via OpenTelemetry is supported as an experimental opt-in feature. -Enable by adding section `logging` to `cds.requires.telemetry` as follows (using `grpc` as an example): +Enable it by adding section `logging` to `cds.requires.telemetry` as follows (using `grpc` as an example): ```json "logging": { "exporter": { @@ -166,7 +166,9 @@ Enable by adding section `logging` to `cds.requires.telemetry` as follows (using ] } ``` -Additionally, `cds.log()`'s JSON log formatter must be active (the default in production but not in development). +The property `custom_fields` allows to specify which properties of the log object shall be added as attributes to the `LogRecord`. + +In order for logs to be exported via OpenTelemetry, `cds.log()`'s JSON log formatter must be active, which is the default in production but not in development. From 50f0620c6b1ac80f63eeab113397000f69da997f Mon Sep 17 00:00:00 2001 From: D050513 Date: Thu, 6 Feb 2025 11:17:54 +0100 Subject: [PATCH 13/15] only own cl entry --- CHANGELOG.md | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f13fee0..1304820 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,7 +12,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). - Support for adding custom spans to trace hierarchy via `tracer.startActiveSpan()` (beta) - Trace attribute `db.client.response.returned_rows` for queries via `cds.ql` - Experimental!: Trace HANA interaction via `@cap-js/hana`'s promisification of the driver API for increased accuracy - - Enable via config `cds.requires.telemetry.tracing._hana_prom` + - Enable via config `cds.env.requires.telemetry.tracing._hana_prom` - Requires `@cap-js/hana^1.7.0` - Experimental!: Intercept and export application logs (cf. `cds.log()`) via OpenTelemetry - Enable by adding section `logging` to `cds.requires.telemetry` as follows (using `grpc` as an example): @@ -52,10 +52,10 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Added - Predefined kind `telemetry-to-otlp` that creates exporters based on OTLP exporter configuration via environment variables -- If `@opentelemetry/instrumentation-runtime-node` is in the project's dependencies but not in `cds.requires.telemetry.instrumentations`, it is registered automatically - - Disable via `cds.requires.telemetry.instrumentations.instrumentation-runtime-node = false` - Experimental!: Propagate W3C trace context to SAP HANA via session context `SAP_PASSPORT` - Enable via environment variable `SAP_PASSPORT` +- If `@opentelemetry/instrumentation-runtime-node` is in the project's dependencies but not in `cds.env.requires.telemetry.instrumentations`, it is registered automatically + - Disable via `cds.env.requires.telemetry.instrumentations.instrumentation-runtime-node = false` ### Changed @@ -120,7 +120,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Added - Support for local modules (e.g., exporters) via `[...].module = ''` -- Disable pool metrics via `cds.requires.telemetry.metrics._db_pool = false` (beta) +- Disable pool metrics via `cds.env.requires.telemetry.metrics._db_pool = false` (beta) ### Fixed @@ -133,7 +133,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). ### Added - Support for own, high resolution timestamps - - Enable via `cds.requires.telemetry.tracing.hrtime = true` + - Enable via `cds.env.requires.telemetry.tracing.hrtime = true` - Enabled by default in development profile ## Version 0.0.5 - 2024-03-11 @@ -150,7 +150,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). - Disable change via environment variable `HOST_METRICS_RETAIN_SYSTEM=true` - Metric exporter's property `temporalityPreference` always gets defaulted to `DELTA` - Was previously only done for kind `telemetry-to-dynatrace` - - Set custom value via `cds.requires.telemetry.metrics.exporter.config.temporalityPreference` + - Set custom value via `cds.env.requires.telemetry.metrics.exporter.config.temporalityPreference` ### Fixed From 67f84f6f3457e41242612e38edf1b8d1322393b7 Mon Sep 17 00:00:00 2001 From: D050513 Date: Thu, 6 Feb 2025 14:09:53 +0100 Subject: [PATCH 14/15] relative paths --- test/logging.test.js | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/test/logging.test.js b/test/logging.test.js index 6ec3416..267b489 100644 --- a/test/logging.test.js +++ b/test/logging.test.js @@ -47,7 +47,13 @@ describe('logging', () => { 'log.type': 'LogRecord', 'exception.message': "Cannot read properties of undefined (reading 'exist')", 'exception.stacktrace': - "TypeError: Cannot read properties of undefined (reading 'exist')\n at AdminService.exist (/Users/d050513/git/cap-js/telemetry/test/bookshop/srv/admin-service.js:16:21)\n at /Users/d050513/git/cap-js/telemetry/node_modules/@sap/cds/lib/srv/srv-dispatch.js:59:59\n at Array.map ()\n at AdminService.handle (/Users/d050513/git/cap-js/telemetry/node_modules/@sap/cds/lib/srv/srv-dispatch.js:59:33)\n at processTicksAndRejections (node:internal/process/task_queues:105:5)\n at AdminService.handle (/Users/d050513/git/cap-js/telemetry/node_modules/@sap/cds/libx/_runtime/common/Service.js:84:16)", + `TypeError: Cannot read properties of undefined (reading 'exist') + at AdminService.exist (${cds.root}/srv/admin-service.js:16:21) + at ${cds.home}/lib/srv/srv-dispatch.js:59:59 + at Array.map () + at AdminService.handle (${cds.home}/lib/srv/srv-dispatch.js:59:33) + at processTicksAndRejections (node:internal/process/task_queues:105:5) + at AdminService.handle (${cds.home}/libx/_runtime/common/Service.js:84:16)`, 'exception.type': 'TypeError', foo: 'bar' } From 6f1946a05228831bffcf6a05b6041b4d8f8f883e Mon Sep 17 00:00:00 2001 From: D050513 Date: Thu, 6 Feb 2025 14:28:05 +0100 Subject: [PATCH 15/15] use to.containSubset from chai-subset --- test/logging.test.js | 11 ++--------- 1 file changed, 2 insertions(+), 9 deletions(-) diff --git a/test/logging.test.js b/test/logging.test.js index 267b489..f914625 100644 --- a/test/logging.test.js +++ b/test/logging.test.js @@ -41,19 +41,12 @@ describe('logging', () => { expect(logs.length).to.equal(3) expect(logs[0]).to.include({ body: 'GET /odata/v4/admin/Genres ' }) //> why the trailing space? expect(logs[1]).to.include({ body: 'Hello, World!' }) - expect(logs[2]).to.deep.include({ + expect(logs[2]).to.containSubset({ body: "Oh no! Cannot read properties of undefined (reading 'exist')", attributes: { 'log.type': 'LogRecord', 'exception.message': "Cannot read properties of undefined (reading 'exist')", - 'exception.stacktrace': - `TypeError: Cannot read properties of undefined (reading 'exist') - at AdminService.exist (${cds.root}/srv/admin-service.js:16:21) - at ${cds.home}/lib/srv/srv-dispatch.js:59:59 - at Array.map () - at AdminService.handle (${cds.home}/lib/srv/srv-dispatch.js:59:33) - at processTicksAndRejections (node:internal/process/task_queues:105:5) - at AdminService.handle (${cds.home}/libx/_runtime/common/Service.js:84:16)`, + 'exception.stacktrace': s => s.match(/^TypeError: .+(\n\s+at .+){6}$/), 'exception.type': 'TypeError', foo: 'bar' }