fix(tracing): fix context loss when cls-hooked#bindEmitter is used

Applies a patch to the cls-hooked module
(https://github.com/Jeff-Lewis/cls-hooked/). This patch fixes a breakage that
occurs in the following scenario:
* The application under monitoring uses the cls-hooked package (in addition
  to @instana/core),
* the application under monitoring binds the incoming http request object
  (`IncomingMessage`, which is an event emitter), via cls-hooked/bindEmitter,
  and
* the incoming request has a payload.

See also:
* #438
* https://github.com/jonathansamines/instana-context-loss

fixes #438

package.json

@@ -89,6 +89,7 @@
     "body-parser": "^1.19.0",
     "bull": "3.22.6",
     "chai": "4.3.4",
+    "cls-hooked": "^4.2.2",
     "commitizen": "^4.2.4",
     "cz-conventional-changelog": "^3.3.0",
     "dev-null": "0.1.1",

packages/collector/test/tracing/misc/cls-hooked-conflict/app.js

@@ -0,0 +1,89 @@
+/*
+ * (c) Copyright IBM Corp. 2021
+ * (c) Copyright Instana Inc. and contributors 2021
+ */
+
+'use strict';
+
+const instana = require('../../../../')();
+const clsHooked = require('cls-hooked');
+
+const express = require('express');
+const morgan = require('morgan');
+const pino = require('pino')();
+
+const logPrefix = `cls-hooked-no-conflict (${process.pid}):\t`;
+const log = require('@instana/core/test/test_util/log').getLogger(logPrefix);
+
+const app = express();
+const port = process.env.APP_PORT || 3215;
+
+if (process.env.WITH_STDOUT) {
+  app.use(morgan(`${logPrefix}:method :url :status`));
+}
+
+// Create a custom cls-hooked namespace for the application under monitoring.
+const namespaceID = 'application-under-monitoring';
+const namespace = clsHooked.createNamespace(namespaceID);
+
+// An express middleware to add bind custom property to the incoming HTTP request event emitter.
+function requestContextFactory() {
+  return function requestContext(req, res, next) {
+    namespace.run(() => {
+      // Binding the request/IncomingMessage object as an event emitter would break the cls based context tracking in
+      // @instana/core prior until version 1.137.2.
+      namespace.bindEmitter(req);
+
+      // Binding the response does not have an effect on the issue, but we do it here for completeness sake.
+      namespace.bindEmitter(res);
+
+      // Set an arbitrary property to be able to check that the cls-hooked binding of the application under monitoring
+      // also still works.
+      namespace.set('custom-cls-property', 'custom property value');
+
+      return next();
+    });
+  };
+}
+
+function handler(req, res) {
+  const customPropertyValue = namespace.active ? namespace.get('custom-cls-property') : 'unknown';
+
+  const activeSpan = instana.currentSpan();
+  let instanaTraceId = 'unknown';
+  let instanaSpanId = 'unknown';
+  if (activeSpan && activeSpan.span) {
+    instanaTraceId = activeSpan.span.t;
+    instanaSpanId = activeSpan.span.s;
+  }
+
+  // Trigger another arbitrary call that is supposed to be traced, to verify that tracing outgoing calls
+  // works as expected.
+  pino.warn('Should be traced.');
+
+  return res.json({
+    'incoming-request': {
+      body: req.body
+    },
+    'cls-contexts': {
+      'appliation-under-monitoring': customPropertyValue,
+      instana: {
+        traceId: instanaTraceId,
+        spanId: instanaSpanId
+      }
+    }
+  });
+}
+
+app.get('/', (req, res) => {
+  res.sendStatus(200);
+});
+
+app.use(requestContextFactory());
+app.use(express.json());
+app.use(express.urlencoded({ extended: true }));
+app.use(handler);
+
+app.listen(port, () => {
+  log(`Listening on port: ${port}`);
+});

packages/collector/test/tracing/misc/cls-hooked-conflict/test.js

@@ -0,0 +1,84 @@
+/*
+ * (c) Copyright IBM Corp. 2021
+ * (c) Copyright Instana Inc. and contributors 2021
+ */
+
+'use strict';
+
+const expect = require('chai').expect;
+
+const constants = require('@instana/core').tracing.constants;
+const config = require('../../../../../core/test/config');
+const { expectExactlyOneMatching, retry } = require('../../../../../core/test/test_util');
+const ProcessControls = require('../../../test_util/ProcessControls');
+const globalAgent = require('../../../globalAgent');
+
+const agentControls = globalAgent.instance;
+
+// This test reproduces a scenario where the application under monitoring uses the cls-hooked package in a specific way
+// that breaks @instana/core's cls context handling. See
+// packages/core/src/tracing/instrumentation/control_flow/clsHooked.js for details.
+
+describe('tracing/no-conflict-with-cls-hooked', function () {
+  this.timeout(config.getTestTimeout());
+
+  globalAgent.setUpCleanUpHooks();
+
+  const controls = new ProcessControls({
+    dirname: __dirname,
+    useGlobalAgent: true
+  });
+  ProcessControls.setUpHooks(controls);
+
+  it('must not lose context when the application binds the http request event emitter via cls-hooked', async () => {
+    const response = await controls.sendRequest({
+      method: 'POST',
+      path: '/api',
+
+      // Adding a body is required to trigger the specific breakage that this test focusses on. This is because the
+      // issue depends on work being triggered by the `onData` event listener of the IncomingMessage object, that both
+      // the/ application under monitoring and @instan/core bind as an event-emitter.
+      body: {
+        what: 'ever'
+      }
+    });
+    await verify(response);
+  });
+
+  async function verify(response) {
+    expect(response['incoming-request']).to.be.an('object');
+    expect(response['incoming-request'].body).to.be.an('object');
+    expect(response['cls-contexts']).to.be.an('object');
+    expect(response['cls-contexts']['appliation-under-monitoring']).to.equal('custom property value');
+
+    const instanaContext = response['cls-contexts'].instana;
+    expect(instanaContext).to.be.an('object');
+    const traceId = instanaContext.traceId;
+    const spanId = instanaContext.spanId;
+    expect(traceId).to.be.a('string');
+    expect(traceId).to.not.equal('unknown');
+    expect(spanId).to.be.a('string');
+    expect(spanId).to.not.equal('unknown');
+
+    await retry(async () => {
+      const spans = await agentControls.getSpans();
+      const httpEntry = expectExactlyOneMatching(spans, [
+        span => expect(span.n).to.equal('node.http.server'),
+        span => expect(span.k).to.equal(constants.ENTRY),
+        span => expect(span.p).to.not.exist,
+        span => expect(span.t).to.equal(traceId),
+        span => expect(span.s).to.equal(spanId),
+        span => expect(span.data.http.method).to.equal('POST'),
+        span => expect(span.data.http.url).to.equal('/api')
+      ]);
+
+      expectExactlyOneMatching(spans, [
+        span => expect(span.n).to.equal('log.pino'),
+        span => expect(span.k).to.equal(constants.EXIT),
+        span => expect(span.t).to.equal(traceId),
+        span => expect(span.p).to.equal(httpEntry.s),
+        span => expect(span.data.log.message).to.equal('Should be traced.')
+      ]);
+    });
+  }
+});

packages/collector/test/tracing/misc/too_late/test.js

@@ -36,6 +36,7 @@ mochaSuiteFn('tracing/too late', function () {
     'amqplib',
     'aws-sdk',
     'bluebird',
+    'cls-hooked',
     'elasticsearch',
     'express',
     'fastify',

packages/core/src/tracing/index.js

@@ -46,6 +46,7 @@ const instrumentations = [
   './instrumentation/cloud/gcp/pubsub',
   './instrumentation/cloud/gcp/storage',
   './instrumentation/control_flow/bluebird',
+  './instrumentation/control_flow/clsHooked',
   './instrumentation/control_flow/graphqlSubscriptions',
   './instrumentation/database/elasticsearchLegacy',
   './instrumentation/database/elasticsearchModern',