Repository: honeycombio/beeline-nodejs (js)

Issue:
Update 3.1.0->3.2.0 breaks express instrumentation
**Versions**
Node: 16.3.1
Beeline: 3.2.0

**Steps to reproduce**
1. Instrument express app with 3.1.0 successfully
2. Update to 3.2.0 or 3.2.1
3. Traces start having a missing parent span

**Additional context**
The "request" span now has a `trace.parent_id` set, which refers to a nonexistent span.
![grafik](https://user-images.githubusercontent.com/3235163/148449749-ad82b32b-b0cc-40b0-96ac-aed22d332198.png)


Pull request:
Fix parser defaults
<!--
Thank you for contributing to the project! 💜
Please make sure to:
- Chat with us first if this is a big change
  - Open a new issue (or comment on an existing one)
  - We want to make sure you don't spend time implementing something we might have to say No to
- Add unit tests
- Mention any relevant issues in the PR description (e.g. "Fixes #123")

Please see our [OSS process document](https://github.com/honeycombio/home/blob/main/honeycomb-oss-lifecycle-and-practices.md#) to get an idea of how we operate.
-->

## Which problem is this PR solving?

- the `httpTraceParserHook` is supposed to be the way for users to deterministically tell the beeline which incoming headers to parse
- it was not working as expected, because we were always falling back to our own parsing logic, when the hook was not producing a value
- closes #531

## Short description of the changes

- only fall back to our parsing logic if no parser hook is configured
- adding deprecation warnings to related parts of the API that are making this code more complicated -- hopefully we can clean all this up in the next major release 😅 


Patch:
diff --git a/lib/instrumentation/express.js b/lib/instrumentation/express.js
index 5f42959..f38d5e6 100644
--- a/lib/instrumentation/express.js
+++ b/lib/instrumentation/express.js
@@ -77,103 +77,104 @@ function wrapErrMiddleware(middleware, debugWrap) {
   };
 }
 
-const getMagicMiddleware = ({ userContext, traceIdSource, parentIdSource, packageVersion }) => (
-  req,
-  res,
-  next
-) => {
-  // parse incoming trace headers into a span context
-  let spanContext = traceUtil.parseTraceHeader(traceIdSource, req);
-
-  // parentSpanId refers to the span id of the parent span
-  let parentSpanId = traceUtil.getParentSourceId(parentIdSource, req);
-  if (parentSpanId) {
-    spanContext.parentSpanId = parentSpanId;
-  }
-
-  // propagate trace level fields as-is, if there are any
-  let propagatedContext = {};
-  if (spanContext.customContext) {
-    propagatedContext = spanContext.customContext;
-  }
-
-  let fields = {
-    [schema.EVENT_TYPE]: "express",
-    [schema.PACKAGE_VERSION]: packageVersion,
-    [schema.TRACE_SPAN_NAME]: "request",
-    [schema.TRACE_ID_SOURCE]: spanContext.source,
-    "request.host": req.hostname,
-    "request.original_url": req.originalUrl,
-    "request.remote_addr": req.ip,
-    "request.secure": req.secure,
-    "request.method": req.method,
-    "request.scheme": req.protocol,
-    "request.path": req.path,
-    "request.query": req.query,
-    "request.http_version": `HTTP/${req.httpVersion}`,
-    "request.fresh": req.fresh,
-    "request.xhr": req.xhr,
-  };
-
-  for (let [key, value] of Object.entries(traceUtil.getInstrumentedRequestHeaders())) {
-    let header = req.get(key);
-    if (undefined != header) {
-      fields[value] = header;
+const getMagicMiddleware =
+  ({ userContext, traceIdSource, parentIdSource, packageVersion }) =>
+  (req, res, next) => {
+    // parse incoming trace headers into a span context
+    let spanContext = traceUtil.parseTraceHeader(traceIdSource, req);
+
+    // parentSpanId refers to the span id of the parent span
+    let parentSpanId = traceUtil.getParentSourceId(parentIdSource, req);
+    if (parentSpanId) {
+      spanContext.parentSpanId = parentSpanId;
     }
-  }
-
-  let rootSpan = api.startTrace(
-    fields,
-    spanContext.traceId,
-    spanContext.parentSpanId,
-    spanContext.dataset,
-    propagatedContext
-  );
 
-  if (!rootSpan) {
-    // sampler has decided that we shouldn't trace this request
-    next();
-    return;
-  }
+    // propagate trace level fields as-is, if there are any
+    let propagatedContext = {};
+    if (spanContext.customContext) {
+      propagatedContext = spanContext.customContext;
+    }
 
-  // we bind the method that finishes the request event so that we're guaranteed to get an event
-  // regardless of any lapses in context propagation.  Doing it this way also allows us to _detect_
-  // if there was a lapse, since `context` will be undefined in that case.
-  let boundFinisher = api.bindFunctionToTrace((response, context) => {
-    if (!context) {
-      api._askForIssue("we lost our tracking somewhere in the stack handling this request", debug);
+    let fields = {
+      [schema.EVENT_TYPE]: "express",
+      [schema.PACKAGE_VERSION]: packageVersion,
+      [schema.TRACE_SPAN_NAME]: "request",
+      [schema.TRACE_ID_SOURCE]: spanContext.source,
+      "request.host": req.hostname,
+      "request.original_url": req.originalUrl,
+      "request.remote_addr": req.ip,
+      "request.secure": req.secure,
+      "request.method": req.method,
+      "request.scheme": req.protocol,
+      "request.path": req.path,
+      "request.query": req.query,
+      "request.http_version": `HTTP/${req.httpVersion}`,
+      "request.fresh": req.fresh,
+      "request.xhr": req.xhr,
+    };
+
+    for (let [key, value] of Object.entries(traceUtil.getInstrumentedRequestHeaders())) {
+      let header = req.get(key);
+      if (undefined != header) {
+        fields[value] = header;
+      }
     }
 
-    let userEventContext = traceUtil.getUserContext(userContext, req);
-    if (userEventContext) {
-      rootSpan.addContext(userEventContext);
+    let rootSpan = api.startTrace(
+      fields,
+      spanContext.traceId,
+      spanContext.parentSpanId,
+      spanContext.dataset,
+      propagatedContext
+    );
+
+    if (!rootSpan) {
+      // sampler has decided that we shouldn't trace this request
+      next();
+      return;
     }
 
-    rootSpan.addContext({
-      "request.base_url": req.baseUrl,
-      "response.status_code": String(response.statusCode),
-    });
-    if (req.route) {
+    // we bind the method that finishes the request event so that we're guaranteed to get an event
+    // regardless of any lapses in context propagation.  Doing it this way also allows us to _detect_
+    // if there was a lapse, since `context` will be undefined in that case.
+    let boundFinisher = api.bindFunctionToTrace((response, context) => {
+      if (!context) {
+        api._askForIssue(
+          "we lost our tracking somewhere in the stack handling this request",
+          debug
+        );
+      }
+
+      let userEventContext = traceUtil.getUserContext(userContext, req);
+      if (userEventContext) {
+        rootSpan.addContext(userEventContext);
+      }
+
       rootSpan.addContext({
-        "request.route": req.route.path,
+        "request.base_url": req.baseUrl,
+        "response.status_code": String(response.statusCode),
       });
-    }
-    if (req.params) {
-      Object.keys(req.params).forEach((param) =>
+      if (req.route) {
         rootSpan.addContext({
-          [`request.param.${param}`]: req.params[param],
-        })
-      );
-    }
-
-    api.finishTrace(rootSpan);
-  });
+          "request.route": req.route.path,
+        });
+      }
+      if (req.params) {
+        Object.keys(req.params).forEach((param) =>
+          rootSpan.addContext({
+            [`request.param.${param}`]: req.params[param],
+          })
+        );
+      }
+
+      api.finishTrace(rootSpan);
+    });
 
-  onHeaders(res, function () {
-    return boundFinisher(this, tracker.getTracked());
-  });
-  next();
-};
+    onHeaders(res, function () {
+      return boundFinisher(this, tracker.getTracked());
+    });
+    next();
+  };
 
 let instrumentExpress = function (express, opts = {}) {
   let userContext, traceIdSource, parentIdSource;
@@ -189,6 +190,7 @@ let instrumentExpress = function (express, opts = {}) {
   }
 
   if (opts.traceIdSource) {
+    debug("traceIdSource option is deprecated, please use httpTraceParserHook");
     if (typeof opts.traceIdSource === "string" || typeof opts.traceIdSource === "function") {
       traceIdSource = opts.traceIdSource;
     } else {
@@ -199,6 +201,7 @@ let instrumentExpress = function (express, opts = {}) {
   }
 
   if (opts.parentIdSource) {
+    debug("parentIdSource option is deprecated, please use httpTraceParserHook");
     if (typeof opts.parentIdSource === "string" || typeof opts.traceIdSource === "function") {
       parentIdSource = opts.parentIdSource;
     } else {
diff --git a/lib/instrumentation/trace-util.js b/lib/instrumentation/trace-util.js
index d65a0a3..4a1b730 100644
--- a/lib/instrumentation/trace-util.js
+++ b/lib/instrumentation/trace-util.js
@@ -14,12 +14,13 @@ function _includeSource(context, key) {
   });
 }
 
+// in the next major release, consolidate everything around hooks
 exports.parseTraceHeader = (traceIdSource, req) => {
-  let parsed = propagation.parseFromRequest(req);
-  if (!parsed) {
-    parsed = exports.getTraceContext(traceIdSource, req);
+  if (propagation.hasCustomHttpParserHook()) {
+    let parsed = propagation.parseFromRequest(req);
+    return parsed ? parsed : {};
   }
-  return parsed;
+  return exports.getTraceContext(traceIdSource, req);
 };
 
 exports.propagateTraceHeader = () => {
@@ -36,7 +37,7 @@ exports.propagateTraceHeader = () => {
 };
 
 // parse a trace header and return object used to populate args to startTrace
-// deprecated: in the next major version this should get renamed to getSpanContext
+// deprecated: in the next major release convert this to a default parser hook, and update usage logic
 exports.getTraceContext = (traceIdSource, req) => {
   const { honeycomb, w3c, aws } = api;
   if (typeof traceIdSource === "undefined" || typeof traceIdSource === "string") {
diff --git a/lib/propagation/hooks.js b/lib/propagation/hooks.js
index eaa2ea9..6afecc4 100644
--- a/lib/propagation/hooks.js
+++ b/lib/propagation/hooks.js
@@ -12,6 +12,16 @@ function configure(opts = {}) {
   httpTracePropagationHook = opts.httpTracePropagationHook;
 }
 
+/**
+ * @deprecated internal use only
+ * this is a workaround until we clean up parser hooks
+ */
+exports.hasCustomHttpParserHook = hasCustomHttpParserHook;
+
+function hasCustomHttpParserHook() {
+  return httpTraceParserHook !== undefined;
+}
+
 exports.parseFromRequest = parseFromRequest;
 
 function parseFromRequest(req) {
diff --git a/lib/propagation/index.js b/lib/propagation/index.js
index 50b1e16..b5adc59 100644
--- a/lib/propagation/index.js
+++ b/lib/propagation/index.js
@@ -17,3 +17,5 @@ exports.configure = hooks.configure;
 
 exports.parseFromRequest = hooks.parseFromRequest;
 exports.headersFromContext = hooks.headersFromContext;
+
+exports.hasCustomHttpParserHook = hooks.hasCustomHttpParserHook;
diff --git a/lib/types.d.ts b/lib/types.d.ts
index 16f9d7a..5c00612 100644
--- a/lib/types.d.ts
+++ b/lib/types.d.ts
@@ -45,13 +45,17 @@ declare namespace beeline {
 
     express?: {
       userContext?: MetadataContext;
+      /** @deprecated use httpTraceParserHook */
       traceIdSource?: string | ((req: IncomingMessage) => string);
+      /** @deprecated use httpTraceParserHook */
       parentIdSource?: string | ((req: IncomingMessage) => string);
     };
 
     fastify?: {
       userContext?: MetadataContext;
+      /** @deprecated use httpTraceParserHook */
       traceIdSource?: string | ((req: IncomingMessage) => string);
+      /** @deprecated use httpTraceParserHook */
       parentIdSource?: string | ((req: IncomingMessage) => string);
     };
 


Test patch:
diff --git a/lib/instrumentation/trace-util.test.js b/lib/instrumentation/trace-util.test.js
index fa9bdac..863c443 100644
--- a/lib/instrumentation/trace-util.test.js
+++ b/lib/instrumentation/trace-util.test.js
@@ -3,6 +3,7 @@ const cases = require("jest-in-case"),
   http = require("http"),
   api = require("../api"),
   traceUtil = require("./trace-util");
+const { configure } = require("../propagation/hooks");
 
 function getRequestWithHeader(name, value) {
   const req = new http.IncomingMessage();
@@ -16,92 +17,144 @@ function getRequestWithHeaders(headers) {
   return req;
 }
 
-describe("getTraceContext", () => {
-  cases(
-    "beeline trace header",
-    (opts) => {
-      expect(
-        traceUtil.getTraceContext(
-          undefined,
-          getRequestWithHeader(api.honeycomb.TRACE_HTTP_HEADER, opts.headerVal)
-        )
-      ).toEqual(opts.expectedContext);
-    },
-    [
-      {
-        name: "v1 trace_id + parent_id, missing context",
-        headerVal: "1;trace_id=abcdef,parent_id=12345",
-        expectedContext: {
-          traceId: "abcdef",
-          parentSpanId: "12345",
-          customContext: undefined,
-          dataset: undefined,
-          source: "X-Honeycomb-Trace http header",
-        },
+describe("trace-utils", () => {
+  describe("getTraceContext", () => {
+    cases(
+      "beeline trace header",
+      (opts) => {
+        expect(
+          traceUtil.getTraceContext(
+            undefined,
+            getRequestWithHeader(api.honeycomb.TRACE_HTTP_HEADER, opts.headerVal)
+          )
+        ).toEqual(opts.expectedContext);
       },
-      {
-        name: "v1, missing trace_id",
-        contextStr: "1;parent_id=12345",
-        expectedContext: {},
-      },
-    ]
-  );
-  cases(
-    "w3c trace header fallback",
-    (opts) => {
-      expect(
-        traceUtil.getTraceContext(
-          undefined,
-          getRequestWithHeader(api.w3c.TRACE_HTTP_HEADER, opts.headerVal)
-        )
-      ).toEqual(opts.expectedContext);
-    },
-    [
-      {
-        name: "w3c trace_id + parent_id, missing context",
-        headerVal: "00-7f042f75651d9782dcff93a45fa99be0-c998e73e5420f609-01",
-        expectedContext: {
-          traceId: "7f042f75651d9782dcff93a45fa99be0",
-          parentSpanId: "c998e73e5420f609",
-          customContext: undefined,
-          dataset: undefined,
-          source: "traceparent http header",
+      [
+        {
+          name: "v1 trace_id + parent_id, missing context",
+          headerVal: "1;trace_id=abcdef,parent_id=12345",
+          expectedContext: {
+            traceId: "abcdef",
+            parentSpanId: "12345",
+            customContext: undefined,
+            dataset: undefined,
+            source: "X-Honeycomb-Trace http header",
+          },
         },
+        {
+          name: "v1, missing trace_id",
+          contextStr: "1;parent_id=12345",
+          expectedContext: {},
+        },
+      ]
+    );
+    cases(
+      "w3c trace header fallback",
+      (opts) => {
+        expect(
+          traceUtil.getTraceContext(
+            undefined,
+            getRequestWithHeader(api.w3c.TRACE_HTTP_HEADER, opts.headerVal)
+          )
+        ).toEqual(opts.expectedContext);
       },
-    ]
-  );
-  cases(
-    "if both honeycomb and w3c, choose honeycomb",
-    (opts) => {
-      expect(
-        traceUtil.getTraceContext(
-          undefined,
-          getRequestWithHeaders([
-            {
-              name: api.w3c.TRACE_HTTP_HEADER,
-              value: opts.w3cHeaderVal,
-            },
-            {
-              name: api.honeycomb.TRACE_HTTP_HEADER,
-              value: opts.beelineHeaderVal,
-            },
-          ])
-        )
-      ).toEqual(opts.expectedContext);
-    },
-    [
-      {
-        name: "we got both honeycomb and w3c, this should not happen",
-        w3cHeaderVal: "00-7f042f75651d9782dcff93a45fa99be0-c998e73e5420f609-01",
-        beelineHeaderVal: "1;trace_id=abcdefbeelineahh,parent_id=12345",
-        expectedContext: {
-          traceId: "abcdefbeelineahh",
-          parentSpanId: "12345",
-          customContext: undefined,
-          dataset: undefined,
-          source: "X-Honeycomb-Trace http header",
+      [
+        {
+          name: "w3c trace_id + parent_id, missing context",
+          headerVal: "00-7f042f75651d9782dcff93a45fa99be0-c998e73e5420f609-01",
+          expectedContext: {
+            traceId: "7f042f75651d9782dcff93a45fa99be0",
+            parentSpanId: "c998e73e5420f609",
+            customContext: undefined,
+            dataset: undefined,
+            source: "traceparent http header",
+          },
         },
+      ]
+    );
+    cases(
+      "if both honeycomb and w3c, choose honeycomb",
+      (opts) => {
+        expect(
+          traceUtil.getTraceContext(
+            undefined,
+            getRequestWithHeaders([
+              {
+                name: api.w3c.TRACE_HTTP_HEADER,
+                value: opts.w3cHeaderVal,
+              },
+              {
+                name: api.honeycomb.TRACE_HTTP_HEADER,
+                value: opts.beelineHeaderVal,
+              },
+            ])
+          )
+        ).toEqual(opts.expectedContext);
       },
-    ]
-  );
+      [
+        {
+          name: "we got both honeycomb and w3c, this should not happen",
+          w3cHeaderVal: "00-7f042f75651d9782dcff93a45fa99be0-c998e73e5420f609-01",
+          beelineHeaderVal: "1;trace_id=abcdefbeelineahh,parent_id=12345",
+          expectedContext: {
+            traceId: "abcdefbeelineahh",
+            parentSpanId: "12345",
+            customContext: undefined,
+            dataset: undefined,
+            source: "X-Honeycomb-Trace http header",
+          },
+        },
+      ]
+    );
+  });
+
+  describe("parseTraceHeader", () => {
+    afterEach(() => {
+      configure();
+    });
+
+    describe("when custom hook configured", () => {
+      test("uses parsed values from the hook", () => {
+        configure({
+          httpTraceParserHook: () => {
+            return {
+              traceId: "12345",
+              parentSpanId: "67890",
+            };
+          },
+        });
+
+        let parsed = traceUtil.parseTraceHeader(
+          undefined,
+          getRequestWithHeader("fancyfeast", "whatever")
+        );
+        expect(parsed.traceId).toEqual("12345");
+        expect(parsed.parentSpanId).toEqual("67890");
+      });
+
+      test("uses parsed values from the hook even when parsed value is blank", () => {
+        configure({
+          httpTraceParserHook: () => {},
+        });
+
+        let parsed = traceUtil.parseTraceHeader(
+          undefined,
+          getRequestWithHeader(api.honeycomb.TRACE_HTTP_HEADER, "1;trace_id=abcdef,parent_id=12345")
+        );
+        expect(parsed.traceId).toBeUndefined();
+        expect(parsed.parentSpanId).toBeUndefined();
+      });
+    });
+
+    describe("when custom hook not configured", () => {
+      test("falls back to getTraceContext", () => {
+        let parsed = traceUtil.parseTraceHeader(
+          undefined,
+          getRequestWithHeader(api.honeycomb.TRACE_HTTP_HEADER, "1;trace_id=abcdef,parent_id=12345")
+        );
+        expect(parsed.traceId).toEqual("abcdef");
+        expect(parsed.parentSpanId).toEqual("12345");
+      });
+    });
+  });
 });