fix: Keep SAP Passport up-to-date (#283)

Currently `SAP Passport` is only updated when `prepare` and `exec` are
called, but it is required to update every time the database is called.
Therefor this PR shifts the `SAP Passport` criteria to using `prom`.
Which is the re use function `@cap-js/hana` uses inside its generic
driver wrappers to promisify the native driver functions. Therefor by
tracing the `prom` function it traces _all_* driver calls and ensures
that the `SAP Passport` contains an unique trace ID which open telemetry
can anchor itself onto. As without the round trip specific parent trace
ID the open telemetry service provider will see the child trace
timestamps outside of the parent trace window and try to adjust the
timestamp into the parent trace time frame. Which gets especially
confusing when the parent time frame is smaller then the child time
frame.


![image](https://github.com/user-attachments/assets/e8a92aa3-7748-4089-a33e-eb2e99f05af6)

It still has to be investigated how well the `prom` wrapping approach
works for the `resultset streaming`
(cap-js/cds-dbs#702) feature.

---------

Co-authored-by: D050513 <[email protected]>

Author: BobdenOs

CHANGELOG.md

@@ -11,6 +11,9 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/).
 - Improved support for tracing messaging services and `cds.spawn`
 - 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`
+  - Requires `@cap-js/hana^1.7.0`
 
 ### Changed
 

lib/index.js

@@ -24,8 +24,8 @@ function _getInstrumentations() {
           module: '@opentelemetry/instrumentation-runtime-node'
         }
       }
-    } catch (e) {
-      LOG._debug && LOG.debug('Failed to automatically add @opentelemetry/instrumentation-runtime-node:', e)
+    } catch (err) {
+      LOG._debug && LOG.debug('Failed to automatically add @opentelemetry/instrumentation-runtime-node:', err)
     }
   }
 

lib/tracing/cds.js

@@ -1,4 +1,5 @@
 const cds = require('@sap/cds')
+const LOG = cds.log('telemetry')
 
 const { SpanKind } = require('@opentelemetry/api')
 
@@ -79,8 +80,32 @@ module.exports = () => {
 
   const impl = cds.env.requires.db?.impl
   if (impl?.match(/^@cap-js\//)) {
-    const dbService = require(impl)
     cds.once('served', () => {
+      // HANA
+      if (impl === '@cap-js/hana' && cds.env.requires.telemetry.tracing._hana_prom) {
+        try {
+          const [major, minor] = require('@cap-js/hana/package.json').version.split('.')
+          if (major > 1 || (major === 1 && minor >= 7)) {
+            // REVISIT: when telemetry and hana are loaded from differen places this doesn't work
+            const hanaDriver = require('@cap-js/hana/lib/drivers/base.js')
+            const _prom = hanaDriver.prom
+            hanaDriver.prom = function (dbc, func) {
+              const fn = _prom(dbc, func)
+              dbc = dbc._parentConnection || dbc
+              const driver = dbc.constructor.name === 'Client' ? 'hdb' : '@sap/hana-client'
+              return function prom() {
+                return trace(`${driver} - ${func}`, fn, this, arguments, { dbc, fn: func, kind: SpanKind.CLIENT })
+              }
+            }
+            return
+          }
+        } catch (err) {
+          LOG._warning && LOG.warning('Failed to wrap hana driver due to error:', err)
+        }
+      }
+
+      // other DBs
+      const dbService = cds.db.constructor
       const { prepare: _prepare, exec: _exec } = dbService.prototype
       dbService.prototype.prepare = wrap(_prepare, {
         wrapper: function prepare(sql) {

lib/tracing/okra.js

@@ -8,8 +8,8 @@ module.exports = () => {
   let OKRAService
   try {
     OKRAService = require('@sap/cds/libx/_runtime/cds-services/adapter/odata-v4/okra/odata-server/core/Service')
-  } catch (e) {
-    LOG._warn && LOG.warn('Unable to instrument Okra due to error:', e)
+  } catch (err) {
+    LOG._warn && LOG.warn('Unable to instrument Okra due to error:', err)
     return
   }
 

lib/tracing/trace.js

@@ -163,11 +163,11 @@ function _getDynamicDBAttributes(options, args, parent) {
   //       the second time, args is the string query -> we need to get event and target from the previous invocation (i.e., parentSpan).
   const dbAttributes = new Map()
   const db_statement =
-    options.sql || (typeof args[0].query === 'string' && args[0].query) || (typeof args[0] === 'string' && args[0])
+    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 || parent?.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 || parent?.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
 }
@@ -200,31 +200,30 @@ function _addAttributes(span, fn, that, options, args, parent) {
     _setAttributes(span, _getDynamicDBAttributes(options, args, parent))
 
     // SAP Passport
-    if (process.env.SAP_PASSPORT && that.dbc?.constructor.name in { HDBDriver: 1, HANAClientDriver: 1 }) {
+    if (process.env.SAP_PASSPORT && that.dbc?.set) {
       const { spanId, traceId } = span.spanContext()
+      // REVISIT: @sap/dsrpassport uses '0226' for VARPARTOFFSET
       // prettier-ignore
-      let passport = [
-        /* EYECATCHER      */ '2A54482A',
-        /* VERSION         */ '03',
-        /* LENGTH          */ '00E6',
-        /* TRACELEVEL      */ '0000',
-        /* COMPONENTID     */ '2020202020202020202020202020202020202020202020202020202020202020',
-        /* SERVICE         */ '0000',
-        /* USER            */ '2020202020202020202020202020202020202020202020202020202020202020',
-        /* ACTION          */ '20202020202020202020202020202020202020202020202020202020202020202020202020202020',
-        /* ACTIONTYPE      */ '0000',
-        /* PREVCOMPONENTID */ Buffer.from(span.resource.attributes['service.name'].substr(0, 32).padEnd(32, ' ')).toString('hex'),
-        /* TRANSACTIONID   */ Buffer.from(traceId.toUpperCase()).toString('hex'),
-        /* CLIENT          */ '202020',
-        /* COMPONENTTYPE   */ '0000',
-        /* ROOTCONTEXTID   */ traceId.toUpperCase(),
-        /* CONNECTIONID    */ '0000000000000001' + spanId.toUpperCase(),
-        /* CONNECTIONCNT   */ '00000001',
-        /* VARPARTCOUNT    */ '0000',
-        /* VARPARTOFFSET   */ '0000', // REVISIT: @sap/dsrpassport uses '0226'
-        /* EYECATCHER      */ '2A54482A'
-      ]
-      passport = passport.join('')
+      const passport = `${
+        /* EYECATCHER      */ '2A54482A'}${
+        /* VERSION         */ '03'}${
+        /* LENGTH          */ '00E6'}${
+        /* TRACELEVEL      */ '0000'}${
+        /* COMPONENTID     */ '2020202020202020202020202020202020202020202020202020202020202020'}${
+        /* SERVICE         */ '0000'}${
+        /* USER            */ '2020202020202020202020202020202020202020202020202020202020202020'}${
+        /* ACTION          */ '20202020202020202020202020202020202020202020202020202020202020202020202020202020'}${
+        /* ACTIONTYPE      */ '0000'}${
+        /* PREVCOMPONENTID */ Buffer.from(span.resource.attributes['service.name'].substr(0, 32).padEnd(32, ' ')).toString('hex')}${
+        /* TRANSACTIONID   */ Buffer.from(traceId.toUpperCase()).toString('hex')}${
+        /* CLIENT          */ '202020'}${
+        /* COMPONENTTYPE   */ '0000'}${
+        /* ROOTCONTEXTID   */ traceId.toUpperCase()}${
+        /* CONNECTIONID    */ '0000000000000001' + spanId.toUpperCase()}${
+        /* CONNECTIONCNT   */ '00000001'}${
+        /* VARPARTCOUNT    */ '0000'}${
+        /* VARPARTOFFSET   */ '0000' }${
+        /* EYECATCHER      */ '2A54482A'}`
       LOG._debug && LOG.debug('Setting SAP Passport:', passport)
       that.dbc.set({ SAP_PASSPORT: passport })
     }

lib/utils.js

@@ -162,9 +162,9 @@ function _require(name) {
   name = Array.isArray(name) ? name[0] : name
   try {
     return require(name.startsWith('./') ? cds.utils.path.join(cds.root, name) : name)
-  } catch (e) {
-    e.message = `Cannot find module '${name}'. Make sure to install it with 'npm i ${name}'\n` + e.message
-    throw e
+  } catch (err) {
+    err.message = `Cannot find module '${name}'. Make sure to install it with 'npm i ${name}'\n` + err.message
+    throw err
   }
 }