fix logging when extracting from w3c traceparent (#5227)

Author: rochdev

packages/dd-trace/src/opentracing/propagation/text_map.js

@@ -32,11 +32,13 @@ const b3HeaderExpr = /^(([0-9a-f]{16}){1,2}-[0-9a-f]{16}(-[01d](-[0-9a-f]{16})?)
 const baggageExpr = new RegExp(`^${baggagePrefix}(.+)$`)
 const tagKeyExpr = /^_dd\.p\.[\x21-\x2b\x2d-\x7e]+$/ // ASCII minus spaces and commas
 const tagValueExpr = /^[\x20-\x2b\x2d-\x7e]*$/ // ASCII minus commas
-const ddKeys = [traceKey, spanKey, samplingKey, originKey]
-const b3Keys = [b3TraceKey, b3SpanKey, b3ParentKey, b3SampledKey, b3FlagsKey, b3HeaderKey]
-const logKeys = ddKeys.concat(b3Keys)
 const traceparentExpr = /^([a-f0-9]{2})-([a-f0-9]{32})-([a-f0-9]{16})-([a-f0-9]{2})(-.*)?$/i
 const traceparentKey = 'traceparent'
+const tracestateKey = 'tracestate'
+const ddKeys = [traceKey, spanKey, samplingKey, originKey]
+const b3Keys = [b3TraceKey, b3SpanKey, b3ParentKey, b3SampledKey, b3FlagsKey, b3HeaderKey]
+const w3cKeys = [traceparentKey, tracestateKey]
+const logKeys = ddKeys.concat(b3Keys, w3cKeys)
 // Origin value in tracestate replaces '~', ',' and ';' with '_"
 const tracestateOriginFilter = /[^\x20-\x2b\x2d-\x3a\x3c-\x7d]/g
 // Tag keys in tracestate replace ' ', ',' and '=' with '_'
@@ -77,7 +79,12 @@ class TextMapPropagator {
       extractCh.publish({ spanContext, carrier })
     }
 
-    log.debug(() => `Extract from carrier: ${JSON.stringify(pick(carrier, logKeys))}.`)
+    log.debug(() => {
+      const keys = JSON.stringify(pick(carrier, logKeys))
+      const styles = this._config.tracePropagationStyle.extract.join(', ')
+
+      return `Extract from carrier (${styles}): ${keys}.`
+    })
 
     return spanContext
   }

packages/dd-trace/test/opentracing/propagation/text_map.spec.js

@@ -21,6 +21,7 @@ describe('TextMapPropagator', () => {
   let textMap
   let baggageItems
   let config
+  let log
 
   const createContext = (params = {}) => {
     const trace = { started: [], finished: [], tags: {} }
@@ -40,7 +41,12 @@ describe('TextMapPropagator', () => {
   }
 
   beforeEach(() => {
-    TextMapPropagator = require('../../../src/opentracing/propagation/text_map')
+    log = {
+      debug: sinon.spy()
+    }
+    TextMapPropagator = proxyquire('../src/opentracing/propagation/text_map', {
+      '../../log': log
+    })
     config = new Config({ tagsHeaderMaxLength: 512 })
     propagator = new TextMapPropagator(config)
     textMap = {
@@ -782,6 +788,18 @@ describe('TextMapPropagator', () => {
       expect(first._links[0].attributes.context_headers).to.equal('datadog')
     })
 
+    it('should log extraction', () => {
+      const carrier = textMap
+
+      propagator.extract(carrier)
+
+      expect(log.debug).to.have.been.called
+      expect(log.debug.firstCall.args[0]()).to.equal([
+        'Extract from carrier (datadog, tracecontext, baggage):',
+        '{"x-datadog-trace-id":"123","x-datadog-parent-id":"456"}.'
+      ].join(' '))
+    })
+
     describe('with B3 propagation as multiple headers', () => {
       beforeEach(() => {
         config.tracePropagationStyle.extract = ['b3multi']
@@ -857,6 +875,19 @@ describe('TextMapPropagator', () => {
 
         expect(spanContext).to.be.null
       })
+
+      it('should log extraction', () => {
+        textMap['x-b3-traceid'] = '0000000000000123'
+        textMap['x-b3-spanid'] = '0000000000000456'
+
+        propagator.extract(textMap)
+
+        expect(log.debug).to.have.been.called
+        expect(log.debug.firstCall.args[0]()).to.equal([
+          'Extract from carrier (b3multi):',
+          '{"x-b3-traceid":"0000000000000123","x-b3-spanid":"0000000000000456"}.'
+        ].join(' '))
+      })
     })
 
     describe('with B3 propagation as a single header', () => {
@@ -991,6 +1022,17 @@ describe('TextMapPropagator', () => {
           spanId: id('456', 16)
         }))
       })
+
+      it('should log extraction', () => {
+        textMap.b3 = '0000000000000123-0000000000000456'
+
+        propagator.extract(textMap)
+
+        expect(log.debug).to.have.been.called
+        expect(log.debug.firstCall.args[0]()).to.equal(
+          `Extract from carrier (b3 single header): {"b3":"${textMap.b3}"}.`
+        )
+      })
     })
 
     describe('With traceparent propagation as single header', () => {
@@ -1119,6 +1161,21 @@ describe('TextMapPropagator', () => {
         expect(carrier['x-datadog-tags']).to.include('_dd.p.dm=-0')
         expect(spanContext._trace.tags['_dd.p.dm']).to.eql('-0')
       })
+
+      it('should log extraction', () => {
+        const traceparent = textMap.traceparent = '00-1111aaaa2222bbbb3333cccc4444dddd-5555eeee6666ffff-01'
+        const tracestate = textMap.tracestate = 'other=bleh,dd=t.foo_bar_baz_:abc_!@#$%^&*()_+`-~;s:2;o:foo;t.dm:-4'
+
+        config.tracePropagationStyle.extract = ['tracecontext']
+
+        propagator.extract(textMap)
+
+        expect(log.debug).to.have.been.called
+        expect(log.debug.firstCall.args[0]()).to.equal([
+          'Extract from carrier (tracecontext):',
+          `{"traceparent":"${traceparent}","tracestate":"${tracestate}"}.`
+        ].join(' '))
+      })
     })
   })
 })