Repository: honeycombio/beeline-nodejs
Pull request #59 (2018-07-06 15:37:15)

trace propagation
marshal trace context (trace_id, parent_id, and custom context) into an http header in both http/https instrumentations, and unmarshal it in the express instrumentation.

The format of the header value is:

```
  ${VERSION};${PAYLOAD}
```

with version 1 of the payload looking like:

```
  trace_id=${incoming trace id},parent_id=${incoming parent span id},context=${base64 encoded stringified JSON object}
```

Both `trace_id` and `parent_id` are required.  `context` can be missing without error, and any other `key=value` is ignored.  If `trace_id` or `parent_id` is missing, or if `context` fails to decode/parse as JSON, the context is dropped.

toshok: Just remembered I need to add some additional logic for handling strings/options/urls in the http(s) instrumentation.
nathanleclaire: Any chance I could get you to post a quick little code snippet showing how this is meant to be used in code? Will we wrap and instrument common HTTP request modules, or simply provide a way to generate the custom header and leave it to the user to pass along with their request library of choice?
toshok: > Any chance I could get you to post a quick little code snippet demonstrating how this is meant to be used in code? Will we wrap and instrument common HTTP request modules, or simply provide a way to generate the custom header and leave it to the user to pass along with their request library of choice?

The intention is to support both use cases, although for http usage the automatic case should be all that's required (1 below)

1. The express instrumentation reads from the special `X-Honeycomb-Trace` header by default, and both `http`/`https` instrumentations add the header on outgoing requests.  This happens automatically without any additional programmer work.
2. For non-http transport cases, I've added most of what's needed: `marshalTraceContext`/`unmarshalTraceContext`.  There's likely some bikeshedding that needs to happen here, since I wanted to separate the act of unmarshaling the trace context from installing it at the root of a new trace subtree (which we currently have no API for.)
tredman: I'll take a look this week!
tredman: Are there any current examples of what the custom context would be used for?
toshok: Some snippets here talking about it:

https://github.com/honeycombio/beeline-nodejs/blob/master/docs/CustomContext.md
tredman: Ok that makes sense now (need to get the other beelines on the same page with how context is passed down to each event).

Regarding passing this along in the trace header: if this is going out with every http/https request, does it expose the user to accidental leaks of sensitive information? Thinking about the user that adds a field for, say, "user email", then makes an unrelated outbound call to some third-party API outside of their control. 
toshok: going to pull some of these changes (like the event_api refactor) out of this PR to make it a little easier to review.
toshok: alrighty, this should be a little easier to review (basically just has changes that need to be there for propagation to work.)
toshok: > LGTM. I like the separation of {,un}marshalTraceContext and start{Request,Event}. I don't understand the layout well enough yet - is the idea that {,un}marshal are part of the public API? That seems good, so people can write other instrumentations that can propagate our header format.

yeah, sorry about the lack of front-loading of api plans.  that's been somewhat intentional.  I've been procrastinating on what a public api might look like until all the pieces are in play.  going to have another PR shortly to start the bikeshedding :)

(Oh, and one more re: plugging possible leaks of sensitive information in the trace header payload.)

Re writing other instrumentations that can propagate our header format: it might be a good idea to separate out the header marshaling into a completely separate npm package with just that one .js file (but keep it in this repo) such that it's easier for folks doing manual tracing with just libhoney-js (or their own library) without pulling in the beeline.

Patch:
diff --git a/.gitignore b/.gitignore
index c2658d7..dd3d82b 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1,1 +1,2 @@
 node_modules/
+yarn-error.log
diff --git a/lib/event_api/index.js b/lib/event_api/index.js
index e2d4c87..baa192f 100644
--- a/lib/event_api/index.js
+++ b/lib/event_api/index.js
@@ -48,6 +48,9 @@ module.exports = {
   addContext(map) {
     return eventAPI.addContext(map);
   },
+  removeContext(key) {
+    return eventAPI.removeContext(key);
+  },
   customContext: {
     add(key, val) {
       eventAPI.addContext({ [schema.customContext(key)]: val });
diff --git a/lib/event_api/libhoney.js b/lib/event_api/libhoney.js
index 5364803..e33828f 100644
--- a/lib/event_api/libhoney.js
+++ b/lib/event_api/libhoney.js
@@ -45,11 +45,14 @@ module.exports = class LibhoneyEventAPI {
         optsWithoutSampleRate
       )
     );
-    this.honey.addField(schema.HOSTNAME, os.hostname());
+    this.honey.add({
+      [schema.HOSTNAME]: os.hostname(),
+      [schema.TRACE_SERVICE_NAME]: opts.serviceName,
+    });
   }
 
-  startRequest(metadataContext, traceId) {
-    let id = traceId || uuidv4();
+  startRequest(metadataContext, traceId, parentSpanId) {
+    const id = traceId || uuidv4();
 
     if (this.ds && !this.ds.sample(id)) {
       // don't create the context at all if this request isn't going to send a trace
@@ -61,7 +64,7 @@ module.exports = class LibhoneyEventAPI {
       customContext: {},
       stack: [],
     });
-    return this.startEvent(metadataContext, id);
+    return this.startEvent(metadataContext, id, parentSpanId);
   }
 
   finishRequest(ev) {
@@ -69,10 +72,12 @@ module.exports = class LibhoneyEventAPI {
     tracker.deleteTracked();
   }
 
-  startEvent(metadataContext, spanId = uuidv4()) {
+  startEvent(metadataContext, spanId = uuidv4(), parentId = undefined) {
     let context = tracker.getTracked();
-    let parentId;
     if (context.stack.length > 0) {
+      if (parentId) {
+        debug("parentId supplied when there are already spans.. wrong.");
+      }
       parentId = context.stack[context.stack.length - 1][schema.TRACE_SPAN_ID];
     }
     const eventPayload = Object.assign({}, metadataContext, {
diff --git a/lib/event_api/mock.js b/lib/event_api/mock.js
index 1a743f0..d188146 100644
--- a/lib/event_api/mock.js
+++ b/lib/event_api/mock.js
@@ -22,9 +22,8 @@ module.exports = class MockEventAPI {
     this.finishEvent(ev);
     tracker.deleteTracked();
   }
-  startEvent(metadataContext, spanId = undefined) {
+  startEvent(metadataContext, spanId = undefined, parentId = undefined) {
     let context = tracker.getTracked();
-    let parentId;
     if (context.stack.length > 0) {
       parentId = context.stack[context.stack.length - 1][schema.TRACE_SPAN_ID];
     }
diff --git a/lib/index.js b/lib/index.js
index 17093de..875a5e0 100644
--- a/lib/index.js
+++ b/lib/index.js
@@ -1,6 +1,7 @@
 /* eslint-env node */
 const event = require("./event_api"),
-  instrumentation = require("./instrumentation");
+  instrumentation = require("./instrumentation"),
+  propagation = require("./propagation");
 
 function configure(opts = {}) {
   event.configure(opts);
@@ -12,4 +13,7 @@ function configure(opts = {}) {
 configure.asyncTracker = require("./async_tracker");
 configure.customContext = event.customContext;
 
+configure.marshalTraceContext = propagation.marshalTraceContext;
+configure.unmarshalTraceContext = propagation.unmarshalTraceContext;
+
 module.exports = configure;
diff --git a/lib/instrumentation/express.js b/lib/instrumentation/express.js
index b4b5638..1f69d3c 100644
--- a/lib/instrumentation/express.js
+++ b/lib/instrumentation/express.js
@@ -3,6 +3,7 @@ const onHeaders = require("on-headers"),
   tracker = require("../async_tracker"),
   schema = require("../schema"),
   event = require("../event_api"),
+  propagation = require("../propagation"),
   path = require("path"),
   pkg = require(path.join(__dirname, "..", "..", "package.json")),
   debug = require("debug")(`${pkg.name}:express`);
@@ -27,26 +28,43 @@ const getValueFromHeaders = (req, headers) => {
   return undefined;
 };
 
-const getTraceId = (traceIdSource, req) => {
-  let traceId, source;
-
+const getTraceContext = (traceIdSource, req) => {
   if (typeof traceIdSource === "undefined" || typeof traceIdSource === "string") {
     let headers =
-      typeof traceIdSource === "undefined" ? ["X-Request-ID", "X-Amzn-Trace-Id"] : [traceIdSource];
-    let headerAndValue = getValueFromHeaders(req, headers);
+      typeof traceIdSource === "undefined"
+        ? [propagation.TRACE_HTTP_HEADER, "X-Request-ID", "X-Amzn-Trace-Id"]
+        : [traceIdSource];
+    let valueAndHeader = getValueFromHeaders(req, headers);
 
-    if (headerAndValue) {
-      traceId = headerAndValue.value;
-      source = `${headerAndValue.header} http header`;
+    if (!valueAndHeader) {
+      return {};
     }
-  } else {
-    traceId = traceIdSource(req);
-    if (traceId) {
-      source = "traceIdSource function";
+    let { value, header } = valueAndHeader;
+
+    switch (header) {
+      case propagation.TRACE_HTTP_HEADER: {
+        let parsed = propagation.unmarshalTraceContext(value);
+        if (!parsed) {
+          return {};
+        }
+        return Object.assign({}, parsed, {
+          source: `${header} http header`,
+        });
+      }
+
+      default: {
+        return {
+          traceId: value,
+          source: `${header} http header`,
+        };
+      }
     }
+  } else {
+    return {
+      traceId: traceIdSource(req),
+      source: "traceIdSource function",
+    };
   }
-
-  return { traceId, source };
 };
 
 const getUserContext = (userContext, req) => {
@@ -82,13 +100,13 @@ const getUserContext = (userContext, req) => {
 };
 
 const getMagicMiddleware = ({ userContext, traceIdSource, packageVersion }) => (req, res, next) => {
-  let traceIdContext = getTraceId(traceIdSource, req);
+  let traceContext = getTraceContext(traceIdSource, req);
   let ev = event.startRequest(
     {
       [schema.EVENT_TYPE]: "express",
       [schema.PACKAGE_VERSION]: packageVersion,
       [schema.TRACE_SPAN_NAME]: "request",
-      [schema.TRACE_ID_SOURCE]: traceIdContext.source,
+      [schema.TRACE_ID_SOURCE]: traceContext.source,
       "request.host": req.hostname,
       "request.base_url": req.baseUrl,
       "request.original_url": req.originalUrl,
@@ -103,9 +121,16 @@ const getMagicMiddleware = ({ userContext, traceIdSource, packageVersion }) => (
       "request.fresh": req.fresh,
       "request.xhr": req.xhr,
     },
-    traceIdContext.traceId
+    traceContext.traceId,
+    traceContext.spanId
   );
 
+  if (traceContext.customContext) {
+    Object.keys(traceContext.customContext).forEach(k =>
+      event.customContext.add(k, traceContext.customContext[k])
+    );
+  }
+
   if (!ev) {
     // sampler has decided that we shouldn't trace this request
     next();
diff --git a/lib/instrumentation/http.js b/lib/instrumentation/http.js
index e4b8b39..32888ec 100644
--- a/lib/instrumentation/http.js
+++ b/lib/instrumentation/http.js
@@ -2,7 +2,9 @@
 const url = require("url"),
   shimmer = require("shimmer"),
   event = require("../event_api"),
-  schema = require("../schema");
+  propagation = require("../propagation"),
+  schema = require("../schema"),
+  tracker = require("../async_tracker");
 
 let instrumentHTTP = (http, opts = {}) => {
   shimmer.wrap(http, "get", function(_original) {
@@ -25,6 +27,7 @@ let instrumentHTTP = (http, opts = {}) => {
       if (typeof options === "string") {
         options = url.parse(options);
       } else {
+        // shallow-clone options since we'll be modifying it below
         options = Object.assign({}, options);
       }
 
@@ -50,6 +53,11 @@ let instrumentHTTP = (http, opts = {}) => {
         }
       };
 
+      // shallow clone options.headers, adding our tracing headers in
+      options.headers = Object.assign({}, options.headers, {
+        [propagation.TRACE_HTTP_HEADER]: propagation.marshalTraceContext(tracker.getTracked()),
+      });
+
       if (cb) {
         return original.apply(this, [options, wrapped_cb]);
       } else {
diff --git a/lib/instrumentation/https.js b/lib/instrumentation/https.js
index 78cb819..bd8b1ee 100644
--- a/lib/instrumentation/https.js
+++ b/lib/instrumentation/https.js
@@ -2,7 +2,9 @@
 const url = require("url"),
   shimmer = require("shimmer"),
   event = require("../event_api"),
-  schema = require("../schema");
+  propagation = require("../propagation"),
+  schema = require("../schema"),
+  tracker = require("../async_tracker");
 
 let instrumentHTTPS = (https, opts = {}) => {
   shimmer.wrap(https, "get", function(_original) {
@@ -25,6 +27,7 @@ let instrumentHTTPS = (https, opts = {}) => {
       if (typeof options === "string") {
         options = url.parse(options);
       } else {
+        // shallow-clone options since we'll be modifying it below
         options = Object.assign({}, options);
       }
 
@@ -50,6 +53,11 @@ let instrumentHTTPS = (https, opts = {}) => {
         }
       };
 
+      // shallow clone options.headers, adding our tracing headers in
+      options.headers = Object.assign({}, options.headers, {
+        [propagation.TRACE_HTTP_HEADER]: propagation.marshalTraceContext(tracker.getTracked()),
+      });
+
       if (cb) {
         return original.apply(this, [options, wrapped_cb]);
       } else {
diff --git a/lib/propagation.js b/lib/propagation.js
new file mode 100644
index 0000000..35c821f
--- /dev/null
+++ b/lib/propagation.js
@@ -0,0 +1,93 @@
+/* global require, exports, Buffer, __dirname */
+const path = require("path"),
+  pkg = require(path.join(__dirname, "..", "package.json")),
+  debug = require("debug")(`${pkg.name}:propagation`),
+  schema = require("./schema");
+
+exports.TRACE_HTTP_HEADER = "X-Honeycomb-Trace";
+
+const VERSION = "1";
+exports.VERSION = VERSION;
+
+// assumes a header of the form:
+
+// VERSION;PAYLOAD
+
+// VERSION=1
+// =========
+// PAYLOAD is a list of comma-separated params (k=v pairs), with no spaces.  recognized
+// keys + value types:
+//
+//  trace_id=${traceId}    - traceId is an opaque ascii string which shall not include ','
+//  parent_id=${spanId}    - spanId is an opaque ascii string which shall not include ','
+//  context=${contextBlob} - contextBlob is a base64 encoded json object.
+//
+// ex: X-Honeycomb-Trace: 1;trace_id=weofijwoeifj,parent_id=owefjoweifj,context=SGVsbG8gV29ybGQ=
+
+exports.marshalTraceContext = marshalTraceContextv1;
+function marshalTraceContextv1(context) {
+  let traceId = context.id;
+  let spanId = context.stack[context.stack.length - 1][schema.TRACE_SPAN_ID];
+  let contextToSend = context.customContext || {};
+
+  return `${VERSION};trace_id=${traceId},parent_id=${spanId},context=${Buffer.from(
+    JSON.stringify(contextToSend)
+  ).toString("base64")}`;
+}
+
+exports.unmarshalTraceContext = unmarshalTraceContext;
+function unmarshalTraceContext(contextStr) {
+  let [version, payload] = contextStr.trim().split(";");
+  switch (version) {
+    case "1":
+      return unmarshalTraceContextv1(payload);
+  }
+  debug(`unrecognized trace context version ${version}.  ignoring.`);
+  return;
+}
+
+function unmarshalTraceContextv1(payload) {
+  let clauses = payload.split(",");
+
+  let traceId, spanId, contextb64;
+
+  clauses.forEach(cl => {
+    let [k, v] = cl.split("=");
+    switch (k) {
+      case "trace_id":
+        traceId = v;
+        break;
+      case "parent_id":
+        spanId = v;
+        break;
+      case "context":
+        contextb64 = v;
+        break;
+      default:
+        debug(`unrecognized key '${k}', skipping.`);
+        break;
+    }
+  });
+
+  if (!traceId) {
+    debug("no trace_id in header");
+    return;
+  }
+
+  if (!spanId) {
+    debug("no parent_id in header");
+    return;
+  }
+
+  let customContext;
+  if (contextb64) {
+    try {
+      customContext = JSON.parse(Buffer.from(contextb64, "base64").toString("ascii"));
+    } catch (e) {
+      debug("couldn't decode context", e);
+      return;
+    }
+  }
+
+  return { traceId, spanId, customContext };
+}
diff --git a/lib/schema.js b/lib/schema.js
index 07a4e2a..937951c 100644
--- a/lib/schema.js
+++ b/lib/schema.js
@@ -3,7 +3,8 @@
 exports.EVENT_TYPE = "meta.type"; // XXX(toshok) rename "type" to "source"?
 exports.NODE_VERSION = "meta.node_version";
 exports.BEELINE_VERSION = "meta.beeline_version";
-exports.PACKAGE_VERSION = "meta.version";
+exports.PACKAGE = "meta.package";
+exports.PACKAGE_VERSION = "meta.package_version";
 exports.INSTRUMENTATIONS = "meta.instrumentations";
 exports.INSTRUMENTATION_COUNT = "meta.instrumentation_count";
 exports.HOSTNAME = "meta.local_hostname";


Test patch:
diff --git a/lib/instrumentation/http.test.js b/lib/instrumentation/http.test.js
index 3189065..1f4535c 100644
--- a/lib/instrumentation/http.test.js
+++ b/lib/instrumentation/http.test.js
@@ -1,6 +1,7 @@
 /* eslint-env node, jest */
 const http = require("http"),
   instrumentHttp = require("./http"),
+  propagation = require("../propagation"),
   schema = require("../schema"),
   tracker = require("../async_tracker"),
   event = require("../event_api");
@@ -14,6 +15,10 @@ instrumentHttp(http);
 let server;
 beforeAll(() => {
   server = http.createServer((req, res) => {
+    res.setHeader(
+      propagation.TRACE_HTTP_HEADER,
+      req.headers[propagation.TRACE_HTTP_HEADER.toLowerCase()]
+    );
     res.end();
   });
 
@@ -35,7 +40,10 @@ afterEach(() => {
 test("url as a string", done => {
   tracker.setTracked(newMockContext());
 
-  http.get("http://localhost:9009", _res => {
+  http.get("http://localhost:9009", res => {
+    expect(res.headers[propagation.TRACE_HTTP_HEADER.toLowerCase()]).toBe(
+      "1;trace_id=0,parent_id=50001,context=e30="
+    );
     expect(event._apiForTesting().sentEvents).toMatchObject([
       {
         [schema.EVENT_TYPE]: "http",
@@ -55,7 +63,10 @@ test("url as options", done => {
       hostname: "localhost",
       port: 9009,
     },
-    _res => {
+    res => {
+      expect(res.headers[propagation.TRACE_HTTP_HEADER.toLowerCase()]).toBe(
+        "1;trace_id=0,parent_id=50001,context=e30="
+      );
       expect(event._apiForTesting().sentEvents).toEqual([
         expect.objectContaining({
           [schema.EVENT_TYPE]: "http",
diff --git a/lib/propagation.test.js b/lib/propagation.test.js
new file mode 100644
index 0000000..9554f04
--- /dev/null
+++ b/lib/propagation.test.js
@@ -0,0 +1,82 @@
+/* global require describe test expect */
+const propagation = require("./propagation"),
+  schema = require("./schema"),
+  cases = require("jest-in-case");
+
+// this context structure is the same as what the libhoney event api implementation generate.
+let testContext = {
+  id: "abcdef123456",
+  stack: [{ [schema.TRACE_SPAN_ID]: "0102030405" }],
+  customContext: {
+    userID: 1,
+    errorMsg: "failed to sign on",
+    toRetry: true,
+  },
+};
+
+describe("marshaling", () => {
+  test("version string prefix", () => {
+    expect(
+      propagation.marshalTraceContext(testContext).startsWith(`${propagation.VERSION};`)
+    ).toBeTruthy();
+  });
+});
+
+cases(
+  "unmarshaling",
+  opts => expect(propagation.unmarshalTraceContext(opts.contextStr)).toEqual(opts.value),
+  [
+    {
+      name: "unsupported version",
+      contextStr: "9999999;.....",
+      value: undefined,
+    },
+    {
+      name: "v1 trace_id + parent_id, missing context",
+      contextStr: "1;trace_id=abcdef,parent_id=12345",
+      value: {
+        traceId: "abcdef",
+        spanId: "12345",
+      },
+    },
+    {
+      name: "v1, missing trace_id",
+      contextStr: "1;parent_id=12345",
+      value: undefined,
+    },
+    {
+      name: "v1, missing parent_id",
+      contextStr: "1;trace_id=12345",
+      value: undefined,
+    },
+    {
+      name: "v1, garbled context",
+      contextStr: "1;trace_id=abcdef,parent_id=12345,context=123~!@@&^@",
+      value: undefined,
+    },
+    {
+      name: "v1, unknown key (otherwise valid)",
+      contextStr: "1;trace_id=abcdef,parent_id=12345,something=unsupported",
+      value: {
+        traceId: "abcdef",
+        spanId: "12345",
+      },
+    },
+  ]
+);
+
+describe("roundtrip", () => {
+  test("works", () => {
+    let contextStr = propagation.marshalTraceContext(testContext);
+
+    expect(propagation.unmarshalTraceContext(contextStr)).toEqual({
+      traceId: "abcdef123456",
+      spanId: "0102030405",
+      customContext: {
+        userID: 1,
+        errorMsg: "failed to sign on",
+        toRetry: true,
+      },
+    });
+  });
+});