Repository: honeycombio/beeline-nodejs
Pull request #158 (2019-08-08 20:38:01)

update express instrumentation to correctly track `request.route` and `request.base_url`
Currently it add `request.route` to the context before express matches the request to a route.
This PR moves `request.route` to the `boundFinisher` so that it will only be added after express has already matched the request to a route and set `request.route`.

tikotzky: The same issue was happening with `request.base_url`.
It was setting it to the context as soon as the request came in, but express updated `req.baseUrl` as the request passes through the middleware.
In order for `request.route` to be set to the correct `req.baseUrl` it would need to be set to context after the request has already been handled by a route.
tikotzky: Thanks.
Name added.

Patch:
diff --git a/CONTRIBUTORS b/CONTRIBUTORS
index 3e6f095..57b94c4 100644
--- a/CONTRIBUTORS
+++ b/CONTRIBUTORS
@@ -5,3 +5,4 @@ Christine Yen
 Erwin van der Koogh
 Ally Weir
 Ashish Bista
+Mordy Tikotzky
diff --git a/lib/instrumentation/express.js b/lib/instrumentation/express.js
index 0ee43d7..88d5582 100644
--- a/lib/instrumentation/express.js
+++ b/lib/instrumentation/express.js
@@ -87,12 +87,10 @@ const getMagicMiddleware = ({ userContext, traceIdSource, packageVersion }) => (
       [schema.TRACE_SPAN_NAME]: "request",
       [schema.TRACE_ID_SOURCE]: traceContext.source,
       "request.host": req.hostname,
-      "request.base_url": req.baseUrl,
       "request.original_url": req.originalUrl,
       "request.remote_addr": req.ip,
       "request.secure": req.secure,
       "request.method": req.method,
-      "request.route": req.route ? req.route.path : undefined,
       "request.scheme": req.protocol,
       "request.path": req.path,
       "request.query": req.query,
@@ -129,8 +127,14 @@ const getMagicMiddleware = ({ userContext, traceIdSource, packageVersion }) => (
     }
 
     api.addContext({
+      "request.base_url": req.baseUrl,
       "response.status_code": String(response.statusCode),
     });
+    if (req.route) {
+      api.addContext({
+        "request.route": req.route.path,
+      });
+    }
     if (req.params) {
       Object.keys(req.params).forEach(param =>
         api.addContext({
diff --git a/package-lock.json b/package-lock.json
index 33ee7cd..1a14b49 100644
--- a/package-lock.json
+++ b/package-lock.json
@@ -5138,9 +5138,9 @@
       }
     },
     "lodash": {
-      "version": "4.17.11",
-      "resolved": "https://registry.npmjs.org/lodash/-/lodash-4.17.11.tgz",
-      "integrity": "sha512-cQKh8igo5QUhZ7lg38DYWAxMvjSAKG0A8wGSVimP07SIUEK2UO+arSRKbRZWtelMtN5V0Hkwh5ryOto/SshYIg==",
+      "version": "4.17.15",
+      "resolved": "https://registry.npmjs.org/lodash/-/lodash-4.17.15.tgz",
+      "integrity": "sha512-8xOcRHvCjnocdS5cpwXQXVzmmh5e5+saE2QGoeQmbKmRS6J3VQppPOIt0MnmE+4xlZoumy0GPG0D0MVIQbNA1A==",
       "dev": true
     },
     "lodash.sortby": {


Test patch:
diff --git a/lib/instrumentation/express.test.js b/lib/instrumentation/express.test.js
index d75ee16..7cd9304 100644
--- a/lib/instrumentation/express.test.js
+++ b/lib/instrumentation/express.test.js
@@ -53,7 +53,7 @@ describe("userContext", () => {
             [schema.BEELINE_VERSION]: pkg.version,
             "request.host": "127.0.0.1",
             "request.base_url": "",
-            "request.route": undefined,
+            "request.route": "/",
             "request.original_url": "/",
             "request.remote_addr": "::ffff:127.0.0.1",
             "request.secure": false,
@@ -133,6 +133,62 @@ describe("userContext as function", () => {
   });
 });
 
+describe("req proprties should only be read after a request matches a route", () => {
+  const express = instrumentExpress(require("express"), {});
+
+  let server;
+  function initializeTestServer() {
+    let app = express();
+    let router = express.Router();
+    app.get("/:name", function(req, res) {
+      res.status(200).send("ok");
+    });
+
+    router.get("/router/:name", function(req, res) {
+      res.status(200).send("ok");
+    });
+
+    app.use("/base", router);
+
+    server = app.listen(3000);
+  }
+
+  beforeEach(() => {
+    api.configure({ impl: "mock" });
+    initializeTestServer();
+  });
+  afterEach(() => {
+    api._resetForTesting();
+    server.close();
+  });
+
+  test("it correctly sends the matched path", done => {
+    request(server)
+      .get("/mordy")
+      .expect(200, () => {
+        setTimeout(() => {
+          expect(api._apiForTesting().sentEvents.length).toBe(1);
+          let ev = api._apiForTesting().sentEvents[0];
+          expect(ev["request.route"]).toBe("/:name");
+          done();
+        }, 1000);
+      });
+  });
+
+  test("it correctly sends the matched base_url", done => {
+    request(server)
+      .get("/base/router/mordy")
+      .expect(200, () => {
+        setTimeout(() => {
+          expect(api._apiForTesting().sentEvents.length).toBe(1);
+          let ev = api._apiForTesting().sentEvents[0];
+          expect(ev["request.base_url"]).toBe("/base");
+          done();
+        }, 1000);
+      });
+  });
+});
+
 describe("request id from http headers", () => {
   const express = instrumentExpress(require("express"), {});