diff --git a/lib/tracing/cds.js b/lib/tracing/cds.js index ce383da..8eefdd9 100644 --- a/lib/tracing/cds.js +++ b/lib/tracing/cds.js @@ -1,6 +1,4 @@ const cds = require('@sap/cds') -const LOG = cds.log('cds') -const APPLOG = cds.log('app') const trace = require('./trace') const wrap = require('./wrap') @@ -8,7 +6,6 @@ const wrap = require('./wrap') function _wrapHandler(handler) { const phase = handler.on ? 'on' : handler.before ? 'before' : 'after' handler.handler = wrap(handler.handler, { - // loggerName: APPLOG.label, phase: phase, event: handler[phase] }) @@ -29,73 +26,58 @@ const _wrapStmt = (stmt, impl, sql) => { } module.exports = () => { - const { emit, handle } = cds.Service.prototype - cds.Service.prototype.emit = wrap(emit, { - wrapper: function () { + const { emit: _emit, handle: _handle } = cds.Service.prototype + 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, {}) } }) - cds.Service.prototype.handle = wrap(handle, { - wrapper: function (req) { + cds.Service.prototype.handle = wrap(_handle, { + wrapper: function handle(req) { if (!cds.env.requires.telemetry.tracing._tx && req.event in { BEGIN: 1, COMMIT: 1, ROLLBACK: 1 }) - return handle.apply(this, arguments) - return trace(req, handle, this, arguments, {}) + return _handle.apply(this, arguments) + return trace(req, _handle, this, arguments, {}) } }) - const { spawn } = cds - cds.spawn = wrap(spawn, { - wrapper: function () { + const { spawn: _spawn } = cds + cds.spawn = wrap(_spawn, { + wrapper: function spawn() { const handlerFn = typeof arguments[0] === 'function' ? arguments[0] : arguments[1] const wrappedFn = wrap(handlerFn, { event: 'cds.spawn Handler' }) if (typeof arguments[0] === 'function') arguments[0] = wrappedFn else arguments[1] = wrappedFn - return trace({ phase: '', event: 'Background Process' }, spawn, cds, arguments, {}) + return trace({ phase: '', event: 'Background Process' }, _spawn, cds, arguments, {}) } }) - // REVISIT: inofficial @cds.tracing: true/ false cds.on('serving', service => { - // Do trace event handler either when - // Logging is enabled for all and it is not explicitly disabled for this service - // Or tracing is explicitly enabled and the general setting is not silent - if ( - cds.env.requires.telemetry.tracing?.level === 'debug' || - (APPLOG._trace && service.definition['@cds.tracing'] !== false) || - (service.definition['@cds.tracing'] && APPLOG.level !== 0) - ) { + // trace individual event handlers -> INOFFICIAL! + if (cds.env.requires.telemetry.tracing?.level === 'debug') { for (const each of ['_error', '_initial', 'on', 'before', 'after']) { service._handlers[each].forEach(_wrapHandler) } } - - // If tracing is explicitly disabled for this service - // Or if tracing in general is disabled for services and not explicitly enabled for this one - // Remove tracing - if ((!LOG._info && service.definition['@cds.tracing'] !== true) || service.definition['@cds.tracing'] === false) { - service.emit = service.emit.__original - service.handle = service.handle.__original - } }) const impl = cds.env.requires.db?.impl if (impl?.match(/^@cap-js\//)) { const dbService = require(impl) cds.once('served', () => { - const { prepare, exec } = dbService.prototype - dbService.prototype.prepare = wrap(prepare, { - wrapper: function (sql) { - const stmt = trace(`${impl} - prepare ${sql}`, prepare, this, arguments, { sql }) + 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 }) if (stmt instanceof Promise) return stmt.then(stmt => _wrapStmt(stmt, impl, sql)) return _wrapStmt(stmt, impl, sql) } }) - dbService.prototype.exec = wrap(exec, { - wrapper: function (sql) { + dbService.prototype.exec = wrap(_exec, { + 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 }) + return _exec.apply(this, arguments) + return trace(`${impl} - exec ${sql}`, _exec, this, arguments, { sql }) } }) }) diff --git a/lib/tracing/cloud_sdk.js b/lib/tracing/cloud_sdk.js index 0678f39..1595e4d 100644 --- a/lib/tracing/cloud_sdk.js +++ b/lib/tracing/cloud_sdk.js @@ -12,7 +12,7 @@ module.exports = () => { const cloudSDK = require('@sap-cloud-sdk/http-client') const { executeHttpRequest: _execute, executeHttpRequestWithOrigin: _executeWithOrigin } = cloudSDK cloudSDK.executeHttpRequest = wrap(_execute, { - wrapper: function (destination, requestConfig) { + wrapper: function executeHttpRequest(destination, requestConfig) { return trace( `${destination?.name ? destination?.name + ' ' : ''}${requestConfig?.method || 'GET'} ${ destination.url || requestConfig?.url @@ -20,12 +20,12 @@ module.exports = () => { _execute, this, arguments, - { /* loggerName: LOG.label, */ outbound: destination.name } + { outbound: destination.name } ) } }) cloudSDK.executeHttpRequestWithOrigin = wrap(_executeWithOrigin, { - wrapper: function (destination, requestConfig) { + wrapper: function executeHttpRequestWithOrigin(destination, requestConfig) { return trace( `${destination?.name ? destination?.name + ' ' : ''}${requestConfig?.method || 'GET'} ${ destination.url || requestConfig?.url @@ -33,7 +33,7 @@ module.exports = () => { _executeWithOrigin, this, arguments, - { /* loggerName: LOG.label, */ outbound: destination.name } + { outbound: destination.name } ) } }) diff --git a/lib/tracing/okra.js b/lib/tracing/okra.js index 11269b4..c91aa5e 100644 --- a/lib/tracing/okra.js +++ b/lib/tracing/okra.js @@ -30,6 +30,6 @@ module.exports = () => { OKRAService.prototype.process = function (request) { if (!request._ctx && cds.context) request._ctx = cds.context if (!cds.context) cds.context = request?._batchContext?._incomingODataRequest?._inRequest?._ctx - return trace(`${request.method} ${request.url}`, _process, this, arguments /*, { loggerName: LOG.label }*/) // REVISIT: Name is a bit shitty + return trace(`${request.method} ${request.url}`, _process, this, arguments) } } diff --git a/lib/tracing/wrap.js b/lib/tracing/wrap.js index a2d8af2..1c939f8 100644 --- a/lib/tracing/wrap.js +++ b/lib/tracing/wrap.js @@ -4,8 +4,8 @@ const trace = require('./trace') function wrap(fn, options) { if (!fn.__wrapped) { // locate the function - if (!options.no_locate && !process.env.NO_LOCATE) { - let __location + if (!options.no_locate && !process.env.NO_LOCATE && !fn.__location) { + let __location = {} locate(fn).then(location => { __location = location }) diff --git a/test/bookshop/srv/admin-service.cds b/test/bookshop/srv/admin-service.cds index ea9b073..ca92534 100644 --- a/test/bookshop/srv/admin-service.cds +++ b/test/bookshop/srv/admin-service.cds @@ -1,4 +1,5 @@ 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; diff --git a/test/bookshop/srv/cat-service.cds b/test/bookshop/srv/cat-service.cds index 3e96171..4c17ece 100644 --- a/test/bookshop/srv/cat-service.cds +++ b/test/bookshop/srv/cat-service.cds @@ -1,4 +1,5 @@ using { sap.capire.bookshop as my } from '../db/schema'; + service CatalogService { /** For displaying lists of Books */ diff --git a/test/bookshop/srv/genre-service.cds b/test/bookshop/srv/genre-service.cds new file mode 100644 index 0000000..611aebf --- /dev/null +++ b/test/bookshop/srv/genre-service.cds @@ -0,0 +1,6 @@ +using { sap.capire.bookshop as my } from '../db/schema'; + +service GenreService @(requires:'admin') { + @odata.draft.enabled + entity Genres as projection on my.Genres; +} diff --git a/test/bookshop/test.http b/test/bookshop/test.http index 9dd2899..3e0c10b 100644 --- a/test/bookshop/test.http +++ b/test/bookshop/test.http @@ -9,3 +9,11 @@ Authorization: Basic alice:wonderland GET {{host}}/odata/v4/admin/Authors Authorization: Basic alice:wonderland + +### + +POST {{host}}/odata/v4/genre/Genres +Authorization: Basic alice:wonderland +Content-Type: application/json + +{} diff --git a/test/metrics.test.js b/test/metrics.test.js index b6fc74a..61fdd21 100644 --- a/test/metrics.test.js +++ b/test/metrics.test.js @@ -17,7 +17,7 @@ describe('metrics', () => { test('system metrics are not collected by default', async () => { const { status } = await GET('/odata/v4/admin/Books', admin) expect(status).to.equal(200) - + await wait(100) expect(log.output).to.match(/process/i) diff --git a/test/tracing.test.js b/test/tracing.test.js index 9dd9032..312e660 100644 --- a/test/tracing.test.js +++ b/test/tracing.test.js @@ -24,9 +24,22 @@ describe('tracing', () => { expect(log.output).not.to.match(/telemetry/) }) - // --- TODO --- + test('$batch is traced', async () => { + await POST( + '/odata/v4/genre/$batch', + { + requests: [ + { id: 'r1', method: 'POST', url: '/Genres', headers: { 'content-type': 'application/json' }, body: {} }, + { id: 'r2', method: 'GET', url: '/Genres', headers: {} } + ] + }, + admin + ) + // 4: create/ new, read after write, read actives, read drafts + expect(log.output.match(/\[telemetry\] - elapsed times:/g).length).to.equal(4) + }) - test.skip('$batch is traced', async () => {}) + // --- TODO --- test.skip('individual handlers are traced', async () => {})