fix: [seconds, nanoseconds] since unix epoch (#50)

closes #47

lib/tracing/index.js

@@ -122,6 +122,9 @@ module.exports = resource => {
   // REVISIT: better way to set/ pass tracer?
   cds._telemetry.tracer = trace.getTracer(cds._telemetry.name, cds._telemetry.version)
 
+  // REVISIT: only start tracing once served
+  cds.on('served', () => { cds._telemetry.tracer._active = true })
+
   /*
    * add CAP instrumentations
    */

lib/tracing/trace.js

@@ -1,23 +1,32 @@
 const cds = require('@sap/cds')
 
+const otel = require('@opentelemetry/api')
+const { SpanKind, SpanStatusCode, ROOT_CONTEXT } = otel
+const { SemanticAttributes } = require('@opentelemetry/semantic-conventions')
+
 const MASK_HEADERS = (cds.env.log.mask_headers || ['/authorization/i', '/cookie/i']).map(s => {
   const parts = s.match(/\/(.+)\/(\w*)/)
   if (parts) return new RegExp(parts[1], parts[2])
   return new RegExp(s)
 })
 
-const otel = require('@opentelemetry/api')
-const { SpanKind, SpanStatusCode, ROOT_CONTEXT } = otel
-const { SemanticAttributes } = require('@opentelemetry/semantic-conventions')
+const HRTIME = cds.env.requires.telemetry.tracing.hrtime
+const EPOCH_OFFSET = Math.floor(Date.now() / 1000) - process.hrtime()[0]
+
+// returns [seconds, nanoseconds] since unix epoch
+function _hrtime() {
+  const hrtime = process.hrtime()
+  return [hrtime[0] + EPOCH_OFFSET, hrtime[1]]
+}
 
-function _getParentSpan(HRTIME) {
+function _getParentSpan() {
   if (!cds.context) return
   if (!cds.context._otelctx) {
     cds.context._otelKey = otel.createContextKey(cds.context.id)
     cds.context._otelctx = otel.context.active()
     const parent = otel.trace.getSpan(cds.context._otelctx)
     if (HRTIME && parent && !parent.__adjusted) {
-      parent.startTime = process.hrtime()
+      parent.startTime = _hrtime()
       parent.__adjusted = true
     }
     if (!parent?._is_async) cds.context._otelctx.setValue(cds.context._otelKey, parent)
@@ -156,12 +165,13 @@ function _setAttributes(span, attributes) {
 }
 
 function trace(name, fn, targetObj, args, options = {}) {
-  const HRTIME = cds.env.requires.telemetry.tracing.hrtime
+  // REVISIT: only start tracing once served
+  if (!cds._telemetry.tracer._active) return fn.apply(targetObj, args)
 
   /*
    * create span
    */
-  const parentSpan = _getParentSpan(HRTIME)
+  const parentSpan = _getParentSpan()
   const isAsync = parentSpan?._is_async && !parentSpan?.name.match(/cds\.spawn/)
   const ctx = isAsync
     ? ROOT_CONTEXT
@@ -171,7 +181,7 @@ function trace(name, fn, targetObj, args, options = {}) {
   const spanOptions = {
     kind: _determineKind(targetObj, name?.phase, isAsync, options)
   }
-  if (HRTIME) spanOptions.startTime = process.hrtime()
+  if (HRTIME) spanOptions.startTime = _hrtime()
   if (isAsync) {
     spanOptions.links = [{ context: parentSpan.spanContext() }]
     spanOptions.parent = undefined
@@ -207,7 +217,7 @@ function trace(name, fn, targetObj, args, options = {}) {
       throw e
     }
     const onDone = () => {
-      if (span.status.code !== SpanStatusCode.UNSET && !span.ended) span.end(HRTIME ? process.hrtime() : undefined)
+      if (span.status.code !== SpanStatusCode.UNSET && !span.ended) span.end(HRTIME ? _hrtime() : undefined)
     }
 
     try {

package.json

@@ -103,7 +103,6 @@
         },
         "telemetry-to-jaeger": {
           "tracing": {
-            "hrtime": false,
             "exporter": {
               "module": "@opentelemetry/exporter-trace-otlp-proto",
               "class": "OTLPTraceExporter"

test/bookshop/package.json

@@ -1,5 +1,12 @@
 {
   "dependencies": {
     "@cap-js/telemetry": "*"
+  },
+  "_cds": {
+    "requires": {
+      "telemetry": {
+        "kind": "telemetry-to-jaeger"
+      }
+    }
   }
-}
+}

test/bookshop/test.http

@@ -0,0 +1,6 @@
+@host = http://localhost:4004
+
+###
+
+GET {{host}}/odata/v4/admin/Books
+Authorization: Basic alice:wonderland