Repository: honeycombio/beeline-nodejs
Pull request #347 (2021-05-07 20:51:51)

Fix api.addContext so it works on the current span (not the root)
The documented behavior for `api.addContext` is that it adds fields to
the current span. However, the code was accessing index 0 of the context
stack, which will always be the *root* span. Tests previously did not
catch this because `api.addContext` was only exercised in a single-span
trace. A similar issue exists for `api.removeContext`, although it's
deprecated. But the patch is simple, so I applied it to both functions.

This probably wasn't caught sooner because `span.addContext` gets used
way more, particularly with asynchronous spans. As evidence, the
auto-instrumentation does not use `api.addContext` at all!

Note that running npm automatically bumped the package-lock.json, since
v2.7.0 of the Beeline had been released without changing the lock file.

vreynolds: @honeycombio/integrations-team thoughts on whether this is a breaking change? It's been this way for a while, which makes me wonder if people have come to expect current (incorrect) behavior. The function itself is pretty front and center in the docs: https://docs.honeycomb.io/getting-data-in/javascript/beeline-nodejs/ but may not be used that much in the wild.
bdarfler: This requires a major version bump. For that reason, we are going to hold off merging until this or other major version bump work becomes pressing.
nicwise: WAY more confusingly: https://honeycombpollinators.slack.com/archives/CLMLJ7CDV/p1630626416019700

I have 2 projects. One is our main backend (apollo lambda). One is a small ses/sns notification lambda.

The main backend works fine. Nice traces + spans, info in the right places etc.

The new one doesn't. All the addContext attaches it to the root span. I can't put anything in a sub-span unless I add it in `startSpan` or use `span.addContext`

Both are on the same version of node, same env (lambda), same version of beeline. Only difference is that the small one isn't using `async` anywhere (even the event handler isn't) and the other one very much is, tho the startTrace isn't in a function which is marked as async - YET (I need to upgrade middy which would force me to make it async)

I'd very much like this to be more predictable. I think this would make it so.
nicwise: here's the not at all cut down version of the new, smaller handler from above. The main app is all middleware etc and needs a lot of code removing to make sense, so I can't post that.

https://gist.github.com/nicwise/35a38c6c17cab6d01bfae7e17ced37ac
vreynolds: @nicwise thanks for reporting! The difference you're seeing (sorta) makes sense at first glance, because `startAsyncSpan` creates a temporary new stack, so anything you add within that async context would treat that started span as the "root".

We'll chat about this again when the team's back after the holiday -- might be we just bite the bullet and do a major bump for this.

Patch:
diff --git a/lib/api/libhoney.js b/lib/api/libhoney.js
index 5083b08..675b671 100644
--- a/lib/api/libhoney.js
+++ b/lib/api/libhoney.js
@@ -290,7 +290,7 @@ module.exports = class LibhoneyEventAPI {
       // valid, since we can end up in our instrumentation outside of requests we're tracking
       return;
     }
-    Object.assign(context.stack[0].payload, map);
+    Object.assign(context.stack[context.stack.length - 1].payload, map);
   }
 
   /**
@@ -302,7 +302,7 @@ module.exports = class LibhoneyEventAPI {
       // valid, since we can end up in our instrumentation outside of requests we're tracking
       return;
     }
-    delete context.stack[0].payload[key];
+    delete context.stack[context.stack.length - 1].payload[key];
   }
 
   addTraceContext(map) {
diff --git a/lib/api/mock.js b/lib/api/mock.js
index 5a528ec..27424df 100644
--- a/lib/api/mock.js
+++ b/lib/api/mock.js
@@ -85,7 +85,7 @@ module.exports = class MockEventAPI {
     if (!context || context.stack.length === 0) {
       return;
     }
-    Object.assign(context.stack[0], map);
+    Object.assign(context.stack[context.stack.length - 1], map);
   }
 
   /**
@@ -93,7 +93,7 @@ module.exports = class MockEventAPI {
    */
   removeContext(key) {
     let context = tracker.getTracked();
-    delete context.stack[0].payload[key];
+    delete context.stack[context.stack.length - 1].payload[key];
   }
 
   addTraceContext(map) {


Test patch:
diff --git a/lib/api/index.test.js b/lib/api/index.test.js
index b7d4e0f..b4f4b2a 100644
--- a/lib/api/index.test.js
+++ b/lib/api/index.test.js
@@ -648,6 +648,76 @@ test("async spans share custom context", () => {
   expect(asyncData["app.custom"]).toBe("value");
 });
 
+test("addContext works on the current span", () => {
+  const honey = api._apiForTesting().honey;
+
+  let parentSpan = api.startTrace({ name: "parent" });
+  api.addContext({ field: "a" });
+
+  let childSpan = api.startSpan({ name: "child" });
+  api.addContext({ field: "b" });
+
+  let grandchildSpan = api.startSpan({ name: "grandchild" });
+  api.addContext({ field: "c" });
+
+  api.finishSpan(grandchildSpan);
+  api.finishSpan(childSpan);
+  api.finishTrace(parentSpan);
+
+  expect(honey.transmission.events.length).toBe(3);
+
+  let parentEvent = honey.transmission.events[2].postData;
+  let childEvent = honey.transmission.events[1].postData;
+  let grandchildEvent = honey.transmission.events[0].postData;
+
+  expect(parentEvent["name"]).toBe("parent");
+  expect(childEvent["name"]).toBe("child");
+  expect(grandchildEvent["name"]).toBe("grandchild");
+
+  expect(parentEvent["field"]).toBe("a");
+  expect(childEvent["field"]).toBe("b");
+  expect(grandchildEvent["field"]).toBe("c");
+});
+
+test("removeContext works on the current span", () => {
+  const honey = api._apiForTesting().honey;
+
+  let parentSpan = api.startTrace({ name: "parent" });
+  api.addContext({ a: 1, b: 2 });
+  api.removeContext("b");
+
+  let childSpan = api.startSpan({ name: "child" });
+  api.addContext({ b: 2, c: 3 });
+  api.removeContext("c");
+
+  let grandchildSpan = api.startSpan({ name: "grandchild" });
+  api.addContext({ c: 3, d: 4 });
+  api.removeContext("d");
+
+  api.finishSpan(grandchildSpan);
+  api.finishSpan(childSpan);
+  api.finishTrace(parentSpan);
+
+  expect(honey.transmission.events.length).toBe(3);
+
+  let parentEvent = honey.transmission.events[2].postData;
+  let childEvent = honey.transmission.events[1].postData;
+  let grandchildEvent = honey.transmission.events[0].postData;
+
+  expect(parentEvent["name"]).toBe("parent");
+  expect(childEvent["name"]).toBe("child");
+  expect(grandchildEvent["name"]).toBe("grandchild");
+
+  expect(parentEvent["a"]).toBe(1);
+  expect(parentEvent["b"]).toBeUndefined();
+
+  expect(childEvent["b"]).toBe(2);
+  expect(childEvent["c"]).toBeUndefined();
+
+  expect(grandchildEvent["c"]).toBe(3);
+  expect(grandchildEvent["d"]).toBeUndefined();
+});
+
 describe("presend hook", () => {
   it("calls the presend hook function if provided", () => {
     const mockPresendHook = jest.fn();