diff --git a/package-lock.json b/package-lock.json index cf0c25e17b..5372e9c695 100644 --- a/package-lock.json +++ b/package-lock.json @@ -48,6 +48,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", @@ -11939,6 +11940,18 @@ "integrity": "sha512-H0E+qZaDEfx/FY4t7iLRv1W2fFI6+pyCeTw1uN20AQPiwqwM6ojPxHxdLv4z8hi2DtnW9BOckSspLucW7pIE5g==", "dev": true }, + "node_modules/async-hook-jl": { + "version": "1.7.6", + "resolved": "https://registry.npmjs.org/async-hook-jl/-/async-hook-jl-1.7.6.tgz", + "integrity": "sha512-gFaHkFfSxTjvoxDMYqDuGHlcRyUuamF8s+ZTtJdDzqjws4mCt7v0vuV79/E2Wr2/riMQgtG4/yUtXWs1gZ7JMg==", + "dev": true, + "dependencies": { + "stack-chain": "^1.3.7" + }, + "engines": { + "node": "^4.7 || >=6.9 || >=7.3" + } + }, "node_modules/async-limiter": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/async-limiter/-/async-limiter-1.0.1.tgz", @@ -13371,6 +13384,20 @@ "mimic-response": "^1.0.0" } }, + "node_modules/cls-hooked": { + "version": "4.2.2", + "resolved": "https://registry.npmjs.org/cls-hooked/-/cls-hooked-4.2.2.tgz", + "integrity": "sha512-J4Xj5f5wq/4jAvcdgoGsL3G103BtWpZrMo8NEinRltN+xpTZdI+M38pyQqhuFU/P792xkMFvnKSf+Lm81U1bxw==", + "dev": true, + "dependencies": { + "async-hook-jl": "^1.7.6", + "emitter-listener": "^1.0.1", + "semver": "^5.4.1" + }, + "engines": { + "node": "^4.7 || >=6.9 || >=7.3 || >=8.2.1" + } + }, "node_modules/cluster-key-slot": { "version": "1.1.0", "resolved": "https://registry.npmjs.org/cluster-key-slot/-/cluster-key-slot-1.1.0.tgz", @@ -15342,6 +15369,15 @@ "integrity": "sha512-Mi2m55JrX2BFbNZGKYR+2ItcGnR4O5HhrvgoRRyZQlaMGQULqDhoGkLWHzJoshSzi7k1PUofxcDbNhlFrDZNhg==", "dev": true }, + "node_modules/emitter-listener": { + "version": "1.1.2", + "resolved": "https://registry.npmjs.org/emitter-listener/-/emitter-listener-1.1.2.tgz", + "integrity": "sha512-Bt1sBAGFHY9DKY+4/2cV6izcKJUf5T7/gkdmkxzX/qv9CcGH8xSwVRW5mtX03SWJtRTWSOpzCuWN9rBFYZepZQ==", + "dev": true, + "dependencies": { + "shimmer": "^1.2.0" + } + }, "node_modules/emoji-regex": { "version": "8.0.0", "resolved": "https://registry.npmjs.org/emoji-regex/-/emoji-regex-8.0.0.tgz", @@ -28759,6 +28795,12 @@ "node": ">=0.10.0" } }, + "node_modules/shimmer": { + "version": "1.2.1", + "resolved": "https://registry.npmjs.org/shimmer/-/shimmer-1.2.1.tgz", + "integrity": "sha512-sQTKC1Re/rM6XyFM6fIAGHRPVGvyXfgzIDvzoq608vM+jeyVD0Tu1E6Np0Kc2zAIFWIj963V2800iF/9LPieQw==", + "dev": true + }, "node_modules/side-channel": { "version": "1.0.4", "resolved": "https://registry.npmjs.org/side-channel/-/side-channel-1.0.4.tgz", @@ -29419,6 +29461,12 @@ "node": ">= 8" } }, + "node_modules/stack-chain": { + "version": "1.3.7", + "resolved": "https://registry.npmjs.org/stack-chain/-/stack-chain-1.3.7.tgz", + "integrity": "sha1-0ZLJ/06moiyUxN1FkXHj8AzqEoU=", + "dev": true + }, "node_modules/stack-trace": { "version": "0.0.10", "resolved": "https://registry.npmjs.org/stack-trace/-/stack-trace-0.0.10.tgz", @@ -42488,6 +42536,15 @@ "integrity": "sha512-H0E+qZaDEfx/FY4t7iLRv1W2fFI6+pyCeTw1uN20AQPiwqwM6ojPxHxdLv4z8hi2DtnW9BOckSspLucW7pIE5g==", "dev": true }, + "async-hook-jl": { + "version": "1.7.6", + "resolved": "https://registry.npmjs.org/async-hook-jl/-/async-hook-jl-1.7.6.tgz", + "integrity": "sha512-gFaHkFfSxTjvoxDMYqDuGHlcRyUuamF8s+ZTtJdDzqjws4mCt7v0vuV79/E2Wr2/riMQgtG4/yUtXWs1gZ7JMg==", + "dev": true, + "requires": { + "stack-chain": "^1.3.7" + } + }, "async-limiter": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/async-limiter/-/async-limiter-1.0.1.tgz", @@ -43644,6 +43701,17 @@ "mimic-response": "^1.0.0" } }, + "cls-hooked": { + "version": "4.2.2", + "resolved": "https://registry.npmjs.org/cls-hooked/-/cls-hooked-4.2.2.tgz", + "integrity": "sha512-J4Xj5f5wq/4jAvcdgoGsL3G103BtWpZrMo8NEinRltN+xpTZdI+M38pyQqhuFU/P792xkMFvnKSf+Lm81U1bxw==", + "dev": true, + "requires": { + "async-hook-jl": "^1.7.6", + "emitter-listener": "^1.0.1", + "semver": "^5.4.1" + } + }, "cluster-key-slot": { "version": "1.1.0", "resolved": "https://registry.npmjs.org/cluster-key-slot/-/cluster-key-slot-1.1.0.tgz", @@ -45246,6 +45314,15 @@ "integrity": "sha512-Mi2m55JrX2BFbNZGKYR+2ItcGnR4O5HhrvgoRRyZQlaMGQULqDhoGkLWHzJoshSzi7k1PUofxcDbNhlFrDZNhg==", "dev": true }, + "emitter-listener": { + "version": "1.1.2", + "resolved": "https://registry.npmjs.org/emitter-listener/-/emitter-listener-1.1.2.tgz", + "integrity": "sha512-Bt1sBAGFHY9DKY+4/2cV6izcKJUf5T7/gkdmkxzX/qv9CcGH8xSwVRW5mtX03SWJtRTWSOpzCuWN9rBFYZepZQ==", + "dev": true, + "requires": { + "shimmer": "^1.2.0" + } + }, "emoji-regex": { "version": "8.0.0", "resolved": "https://registry.npmjs.org/emoji-regex/-/emoji-regex-8.0.0.tgz", @@ -55887,6 +55964,12 @@ "integrity": "sha1-2kL0l0DAtC2yypcoVxyxkMmO/qM=", "dev": true }, + "shimmer": { + "version": "1.2.1", + "resolved": "https://registry.npmjs.org/shimmer/-/shimmer-1.2.1.tgz", + "integrity": "sha512-sQTKC1Re/rM6XyFM6fIAGHRPVGvyXfgzIDvzoq608vM+jeyVD0Tu1E6Np0Kc2zAIFWIj963V2800iF/9LPieQw==", + "dev": true + }, "side-channel": { "version": "1.0.4", "resolved": "https://registry.npmjs.org/side-channel/-/side-channel-1.0.4.tgz", @@ -56422,6 +56505,12 @@ "minipass": "^3.1.1" } }, + "stack-chain": { + "version": "1.3.7", + "resolved": "https://registry.npmjs.org/stack-chain/-/stack-chain-1.3.7.tgz", + "integrity": "sha1-0ZLJ/06moiyUxN1FkXHj8AzqEoU=", + "dev": true + }, "stack-trace": { "version": "0.0.10", "resolved": "https://registry.npmjs.org/stack-trace/-/stack-trace-0.0.10.tgz", diff --git a/package.json b/package.json index 64ec523609..8f6779b4f5 100644 --- a/package.json +++ b/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", diff --git a/packages/collector/test/tracing/misc/cls-hooked-conflict/app.js b/packages/collector/test/tracing/misc/cls-hooked-conflict/app.js new file mode 100644 index 0000000000..7a10a81fb2 --- /dev/null +++ b/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}`); +}); diff --git a/packages/collector/test/tracing/misc/cls-hooked-conflict/test.js b/packages/collector/test/tracing/misc/cls-hooked-conflict/test.js new file mode 100644 index 0000000000..2ce96e90eb --- /dev/null +++ b/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.') + ]); + }); + } +}); diff --git a/packages/collector/test/tracing/misc/too_late/test.js b/packages/collector/test/tracing/misc/too_late/test.js index 6389652287..4e9ad0563d 100644 --- a/packages/collector/test/tracing/misc/too_late/test.js +++ b/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', diff --git a/packages/core/src/tracing/index.js b/packages/core/src/tracing/index.js index e7ffac49d9..21a9d6928f 100644 --- a/packages/core/src/tracing/index.js +++ b/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', diff --git a/packages/core/src/tracing/instrumentation/control_flow/clsHooked.js b/packages/core/src/tracing/instrumentation/control_flow/clsHooked.js new file mode 100644 index 0000000000..53ff751c9a --- /dev/null +++ b/packages/core/src/tracing/instrumentation/control_flow/clsHooked.js @@ -0,0 +1,91 @@ +/* + * (c) Copyright IBM Corp. 2021 + * (c) Copyright Instana Inc. and contributors 2021 + */ + +'use strict'; + +const shimmer = require('shimmer'); + +const requireHook = require('../../../util/requireHook'); + +let hasBeenPatched = false; + +exports.init = () => { + requireHook.onModuleLoad('cls-hooked', patchClsHooked); +}; + +// This module 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. + +// The way cls-hooked and emitter-listener work would cause Instana's cls context to be lost in this scenario. In +// particular, cls-hooked will bind all event listener functions of the event emitter via cls-hooked#Namespace#bind, +// which replaces these functions with a wrapper function. But the cls context (also, the Instana cls context) is +// attached to the function object as a property. By replacing that function with a wrapper function, the cls context +// that had been attached to the function object is lost. To fix this, we instrument the cls-hooked package. (The reason +// why this only occurs when the request has a payload is that in that scenario work is triggered by the `onData` event +// listener of the request event emitter.) +// +// See also: +// * https://github.com/instana/nodejs/issues/438 +// * https://github.com/jonathansamines/instana-context-loss +// +// Actually, this is a fix that should be incorporated into the cls-hooked package directly, but that package has +// apparently been abandoned by its maintainer. Note that on modern Node.js runtimes you might want to consider +// using [AsyncLocalStorage](https://nodejs.org/api/async_context.html#class-asynclocalstorage) instead of +// cls-hooked. + +function patchClsHooked(clsHooked) { + shimmer.wrap(clsHooked, 'getNamespace', shimGetOrCreateNamespace.bind(null, clsHooked)); + shimmer.wrap(clsHooked, 'createNamespace', shimGetOrCreateNamespace.bind(null, clsHooked)); +} + +function shimGetOrCreateNamespace(clsHooked, originalGetOrCreateNamespace) { + return function () { + if (hasBeenPatched) { + return originalGetOrCreateNamespace.apply(this, arguments); + } + + const potentialNamespace = originalGetOrCreateNamespace.apply(this, arguments); + if ( + potentialNamespace && + potentialNamespace.constructor.name && + potentialNamespace.constructor.name === 'Namespace' + ) { + const namespacePrototype = Object.getPrototypeOf(potentialNamespace); + shimmer.wrap(namespacePrototype, 'bind', shimBind); + hasBeenPatched = true; + } + return potentialNamespace; + }; +} + +function shimBind(originalBind) { + return function () { + // Namespace#bind returns a function which wraps the original function. To fix losing the Instana CLS context when + // the application under monitoring uses [cls-hooked](https://github.com/Jeff-Lewis/cls-hooked/) on its own and + // binds the IncomingMessage/HTTP request object event emitter, we need to copy over all properties from the + // original function to the wrapper function. + // + const clsBind = originalBind.apply(this, arguments); + const originalFunction = arguments[0]; + if (typeof originalFunction === 'function') { + Object.keys(originalFunction).forEach(k => { + clsBind[k] = originalFunction[k]; + }); + } + return clsBind; + }; +} + +exports.activate = () => { + // nothing to do +}; + +exports.deactivate = () => { + // nothing to do +}; diff --git a/packages/core/src/util/initializedTooLateHeuristic.js b/packages/core/src/util/initializedTooLateHeuristic.js index 68cef9be0e..2cef7b2794 100644 --- a/packages/core/src/util/initializedTooLateHeuristic.js +++ b/packages/core/src/util/initializedTooLateHeuristic.js @@ -23,6 +23,8 @@ let patterns = [ /\/amqplib\/lib\//, /\/aws-sdk\/lib\/aws.js/, // deliberately not including bunyan because we depend on bunyan ourselves + /\/cls-hooked\/context.js/, + /\/cls-hooked\/context-legacy.js/, /\/elasticsearch\/src\/elasticsearch.js/, /\/express\/index.js/, /\/fastify\/lib\//,