diff --git a/CHANGELOG.md b/CHANGELOG.md index 071a449..1304820 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,18 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). - 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` - 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 diff --git a/README.md b/README.md index 3d68bb7..4dbefbe 100644 --- a/README.md +++ b/README.md @@ -152,7 +152,23 @@ module.exports = cds.server ### Logs -Exporting logs via OpenTelemetry is not yet supported. +Exporting logs via OpenTelemetry is supported as an experimental opt-in feature. +Enable it 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" + ] +} +``` +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. diff --git a/lib/index.js b/lib/index.js index 5a09c8f..9a7d311 100644 --- a/lib/index.js +++ b/lib/index.js @@ -6,6 +6,7 @@ const { registerInstrumentations } = require('@opentelemetry/instrumentation') const tracing = require('./tracing') const metrics = require('./metrics') +const logging = require('./logging') const { getDiagLogLevel, getResource, _require } = require('./utils') function _getInstrumentations() { @@ -56,13 +57,18 @@ module.exports = function () { */ const meterProvider = metrics(resource) + /* + * setup logging + */ + const loggerProvider = cds.env.requires.telemetry.logging ? logging(resource) : undefined + /* * 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..36548aa --- /dev/null +++ b/lib/logging/index.js @@ -0,0 +1,141 @@ +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 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) + config.url ??= credentials.url + config.credentials ??= credentials.credentials + } + + 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 + + const { logs, SeverityNumber } = require('@opentelemetry/api-logs') + const { LoggerProvider, BatchLogRecordProcessor, SimpleLogRecordProcessor } = 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() + + const logProcessor = + _getCustomProcessor(exporter) || + (process.env.NODE_ENV === 'production' + ? new BatchLogRecordProcessor(exporter) + : new SimpleLogRecordProcessor(exporter)) + loggerProvider.addLogRecordProcessor(logProcessor) + + cds.on('served', () => { + 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: _format } = cds.log + const format = cds.log.format = function (module, level, ...args) { + const res = _format.call(this, 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] + 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 + }) + } + + return res + } + + // replace format function of existing loggers + for (const each in cds.log.loggers) cds.log.loggers[each].setFormat(format) + }) + + return loggerProvider +} diff --git a/lib/metrics/index.js b/lib/metrics/index.js index ea1a943..09bb635 100644 --- a/lib/metrics/index.js +++ b/lib/metrics/index.js @@ -44,35 +44,36 @@ 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 026eeb9..5a3e9f0 100644 --- a/lib/tracing/index.js +++ b/lib/tracing/index.js @@ -99,32 +99,33 @@ 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}"`) - const tracingConfig = { ...(tracingExporter.config || {}) } + throw new Error(`Unknown trace exporter "${tracingExporter.class}" in module "${tracingExporter.module}"`) + 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) - LOG._debug && LOG.debug('Using tracing exporter:', exporter) + const exporter = new tracingExporterModule[tracingExporter.class](config) + LOG._debug && LOG.debug('Using trace exporter:', exporter) + return exporter } @@ -150,7 +151,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 = 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/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.cds b/test/bookshop/srv/admin-service.cds index d8edb26..97cb520 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 test_spawn(); action test_emit(); diff --git a/test/bookshop/srv/admin-service.js b/test/bookshop/srv/admin-service.js index 8585a97..5923cf5 100644 --- a/test/bookshop/srv/admin-service.js +++ b/test/bookshop/srv/admin-service.js @@ -10,6 +10,16 @@ module.exports = class AdminService extends cds.ApplicationService { this.before('NEW', 'Books.drafts', genid) + this.before('READ', 'Genres', () => { + cds.log('AdminService').info('Hello, World!') + try { + this.doesnt.exist + } catch (err) { + err.foo = 'bar' + cds.log('AdminService').error('Oh no!', err) + } + }) + this.on('test_spawn', () => { cds.spawn({ after: 3 }, async () => { await SELECT.from('sap.capire.bookshop.Books') 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 diff --git a/test/logging.test.js b/test/logging.test.js new file mode 100644 index 0000000..f914625 --- /dev/null +++ b/test/logging.test.js @@ -0,0 +1,55 @@ +/* eslint-disable no-console */ + +process.env.cds_log_format = 'json' + +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') + +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(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.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': s => s.match(/^TypeError: .+(\n\s+at .+){6}$/), + 'exception.type': 'TypeError', + foo: 'bar' + } + }) + }) +})