fix: cleanup wrapping (#128)

closes #127

lib/tracing/cds.js

@@ -1,14 +1,11 @@
 const cds = require('@sap/cds')
-const LOG = cds.log('cds')
-const APPLOG = cds.log('app')
 
 const trace = require('./trace')
 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 })
         }
       })
     })

lib/tracing/cloud_sdk.js

@@ -12,28 +12,28 @@ 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
         }`,
         _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
         }`,
         _executeWithOrigin,
         this,
         arguments,
-        { /* loggerName: LOG.label, */ outbound: destination.name }
+        { outbound: destination.name }
       )
     }
   })

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

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

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;

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 */

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

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

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)

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 () => {})