diff --git a/packages/collector/test/tracing/sdk/entry_span_context_app.js b/packages/collector/test/tracing/sdk/entry_span_context_app.js new file mode 100644 index 0000000000..d144aa96f8 --- /dev/null +++ b/packages/collector/test/tracing/sdk/entry_span_context_app.js @@ -0,0 +1,245 @@ +#!/usr/bin/env node +/* + * (c) Copyright IBM Corp. 2022 + */ + +'use strict'; + +const instana = require('../../..')(); + +const express = require('express'); +const morgan = require('morgan'); +const { delay, getLogger } = require('@instana/core/test/test_util'); + +const app = express(); +const logPrefix = `SDK entry span context (${process.pid}):\t`; +const log = getLogger(logPrefix); + +const spanName = 'span-name'; +const parentContextAnnotation = 'sdk.custom.tags.parent-context'; +const defaultDelayBetweenIterations = 10; +const defaultDurationOfSpans = 5; + +let delayBetweenIterations = defaultDelayBetweenIterations; +if (process.env.DELAY) { + delayBetweenIterations = parseInt(process.env.DELAY, 10); + if (Number.isNaN(delayBetweenIterations)) { + delayBetweenIterations = defaultDelayBetweenIterations; + } +} + +let durationOfSpans = defaultDurationOfSpans; +if (process.env.SPAN_DURATION) { + durationOfSpans = parseInt(process.env.DELAY, 10); + if (Number.isNaN(durationOfSpans)) { + durationOfSpans = defaultDelayBetweenIterations; + } +} + +if (process.env.WITH_STDOUT) { + app.use(morgan(`${logPrefix}:method :url :status`)); +} + +app.get('/', (req, res) => { + res.sendStatus(200); +}); + +async function createSdkSpanRecursiveAsync(iterationsDone, maxIterations) { + await instana.sdk.async.startEntrySpan(spanName); + annotateWithParentContext(); + await delay(durationOfSpans); + instana.sdk.async.completeEntrySpan(); + + iterationsDone++; + if (iterationsDone < maxIterations) { + await new Promise(resolve => { + setTimeout(() => { + return createSdkSpanRecursivePromise(iterationsDone, maxIterations).then(resolve); + }, delayBetweenIterations); + }); + } +} + +async function createSdkSpanNonRecursiveAsync() { + await instana.sdk.async.startEntrySpan(spanName); + annotateWithParentContext(); + await delay(durationOfSpans); + instana.sdk.async.completeEntrySpan(); +} + +function createSdkSpanRecursivePromise(iterationsDone, maxIterations) { + return instana.sdk.promise + .startEntrySpan(spanName) + .then(annotateWithParentContext) + .then(() => delay(durationOfSpans)) + .then(instana.sdk.promise.completeEntrySpan) + .then(() => { + iterationsDone++; + if (iterationsDone < maxIterations) { + return new Promise(resolve => { + setTimeout(() => { + return createSdkSpanRecursivePromise(iterationsDone, maxIterations).then(resolve); + }, delayBetweenIterations); + }); + } else { + return Promise.resolve(); + } + }); +} + +function createSdkSpanNonRecursivePromise() { + return instana.sdk.promise + .startEntrySpan(spanName) + .then(annotateWithParentContext) + .then(() => delay(durationOfSpans)) + .then(instana.sdk.promise.completeEntrySpan); +} + +function createSdkSpanRecursiveCallback(iterationsDone, maxIterations, cb) { + instana.sdk.callback.startEntrySpan('span-name', () => { + annotateWithParentContext(); + + setTimeout(() => { + instana.sdk.callback.completeEntrySpan(); + + iterationsDone++; + if (iterationsDone < maxIterations) { + setTimeout(() => { + createSdkSpanRecursiveCallback(iterationsDone, maxIterations, () => { + cb(); + }); + }, delayBetweenIterations); + } else { + cb(); + } + }, durationOfSpans); + }); +} + +function createSdkSpanNonRecursiveCallback(cb) { + instana.sdk.callback.startEntrySpan(spanName, () => { + annotateWithParentContext(); + setTimeout(() => { + instana.sdk.callback.completeEntrySpan(); + cb(); + }, durationOfSpans); + }); +} + +process.on('message', async message => { + if (typeof message !== 'object' || Array.isArray(message)) { + return process.send(`error: malformed message, only non-array objects are allowed: ${JSON.stringify(message)}`); + } + if (!message.callPattern) { + return process.send(`error: message has no callPattern attribute: ${JSON.stringify(message)}`); + } + if (!message.apiType) { + return process.send(`error: message has no apiType attribute: ${JSON.stringify(message)}`); + } + let maxIterations = 5; + if (message.iterations) { + maxIterations = message.iterations; + } + + switch (message.callPattern) { + case 'recursive': + recursive(message.apiType, maxIterations); + break; + case 'non-recursive': + nonRecursive(message.apiType, maxIterations); + break; + default: + process.send(`error: unknown callPattern: ${message.callPattern}`); + } +}); + +async function recursive(apiType, maxIterations) { + switch (apiType) { + case 'async': + await createSdkSpanRecursiveAsync(0, maxIterations); + return process.send('done'); + + case 'promise': + createSdkSpanRecursivePromise(0, maxIterations).then(() => { + return process.send('done'); + }); + break; + + case 'callback': + createSdkSpanRecursiveCallback(0, maxIterations, () => { + return process.send('done'); + }); + break; + + default: + process.send(`error: unknown apiType: ${apiType}`); + } +} + +async function nonRecursive(apiType, maxIterations) { + let iterationsDone = 0; + let handle; + + switch (apiType) { + case 'async': + new Promise(resolve => { + handle = setInterval(async () => { + await createSdkSpanNonRecursiveAsync(); + iterationsDone++; + if (iterationsDone >= maxIterations) { + resolve(); + } + }, delayBetweenIterations + durationOfSpans); + }).then(() => { + clearInterval(handle); + process.send('done'); + }); + break; + + case 'promise': + new Promise(resolve => { + handle = setInterval(async () => { + createSdkSpanNonRecursivePromise().then(() => { + iterationsDone++; + if (iterationsDone >= maxIterations) { + resolve(); + } + }); + }, delayBetweenIterations + durationOfSpans); + }).then(() => { + clearInterval(handle); + process.send('done'); + }); + break; + + case 'callback': + // eslint-disable-next-line no-case-declarations, no-inner-declarations + function stop() { + clearInterval(handle); + process.send('done'); + } + + handle = setInterval(async () => { + createSdkSpanNonRecursiveCallback(() => { + iterationsDone++; + if (iterationsDone >= maxIterations) { + stop(); + } + }); + }, delayBetweenIterations + durationOfSpans); + break; + + default: + process.send(`error: unknown apiType: ${apiType}`); + } +} + +function annotateWithParentContext() { + const cls = instana.core.tracing.getCls(); + const prototypeOfActiveContext = cls && cls.ns.active ? Object.getPrototypeOf(cls.ns.active) : null; + instana.currentSpan().annotate(parentContextAnnotation, prototypeOfActiveContext); +} + +app.listen(process.env.APP_PORT, () => { + log(`Listening on port: ${process.env.APP_PORT}`); +}); diff --git a/packages/collector/test/tracing/sdk/entry_span_context_test.js b/packages/collector/test/tracing/sdk/entry_span_context_test.js new file mode 100644 index 0000000000..8e37d326b7 --- /dev/null +++ b/packages/collector/test/tracing/sdk/entry_span_context_test.js @@ -0,0 +1,94 @@ +/* + * (c) Copyright IBM Corp. 2022 + */ + +'use strict'; + +const expect = require('chai').expect; +const fail = require('chai').assert.fail; +const path = require('path'); +const semver = require('semver'); + +const supportedVersion = require('@instana/core').tracing.supportedVersion; +const config = require('../../../../core/test/config'); +const { retry } = require('../../../../core/test/test_util'); +const ProcessControls = require('../../test_util/ProcessControls'); +const globalAgent = require('../../globalAgent'); + +const mochaSuiteFn = supportedVersion(process.versions.node) ? describe : describe.skip; + +mochaSuiteFn('tracing/sdk - force separate context for startEntrySpan', function () { + this.timeout(config.getTestTimeout()); + + globalAgent.setUpCleanUpHooks(); + const agentControls = globalAgent.instance; + + ['AsyncLocalStorage', 'legacy cls-hooked'].forEach(function (contextImplementation) { + // Only execute tests for the AsyncLocalStorage implementation on Node.js versions which support it. We use the same + // semver expression here that packages/core/src/tracing/clsHooked/index.js uses. + let mochaSuiteFn2 = describe; + if ( + contextImplementation === 'AsyncLocalStorage' && + !semver.satisfies(process.versions.node, '12.17 - 16.6 || ^16.14 || >=17.2') + ) { + // eslint-disable-next-line no-console + console.log( + // eslint-disable-next-line max-len + `Skipping test suite "tracing/sdk - force separate context for startEntrySpan" for context implementation AsyncLocalStorage for Node.js version ${process.version}` + ); + mochaSuiteFn2 = describe.skip; + } + + mochaSuiteFn2(contextImplementation, function () { + const env = {}; + if (contextImplementation === 'legacy cls-hooked') { + env.INSTANA_FORCE_LEGACY_CLS = true; + } + const controls = new ProcessControls({ + appPath: path.join(__dirname, 'entry_span_context_app'), + useGlobalAgent: true, + env + }); + + ProcessControls.setUpHooks(controls); + + ['non-recursive', 'recursive'].forEach(callPattern => { + ['async', 'promise', 'callback'].forEach(apiType => { + it( + `${callPattern} calls to instana.sdk.${apiType}.startEntrySpan should create a new root context for ` + + 'each entry span', + async () => { + const iterations = 5; + controls.sendViaIpc({ + callPattern, + apiType, + iterations + }); + let spans; + await retry(async () => { + const ipcMessages = controls.getIpcMessages(); + checkForErrors(ipcMessages); + expect(ipcMessages.length).to.equal(1); + expect(ipcMessages[0]).to.equal('done'); + spans = await agentControls.getSpans(); + expect(spans).to.have.length(iterations); + }); + spans.forEach(span => { + expect(span.data.sdk.custom.tags['parent-context']).to.deep.equal({}); + }); + } + ); + }); + }); + }); + }); + + function checkForErrors(ipcMessages) { + for (let i = 0; i < ipcMessages.length; i++) { + const msg = ipcMessages[i]; + if (msg.indexOf('error: ') === 0) { + fail(`IPC error: ${msg}`); + } + } + } +}); diff --git a/packages/core/src/tracing/clsHooked/context.js b/packages/core/src/tracing/clsHooked/context.js index e9458671c9..7a131c35ab 100644 --- a/packages/core/src/tracing/clsHooked/context.js +++ b/packages/core/src/tracing/clsHooked/context.js @@ -10,6 +10,11 @@ // Jeff-Lewis, fix(destroy): destroy based on asyncId only (3cf7539 on Jul 25, 2017) // https://github.com/Jeff-Lewis/cls-hooked/blob/066c6c4027a7924b06997cc6b175b1841342abdc/context.js +// Changes: +// - rename the symbols to avoid name clashes +// - have Namespace.prototype.set return a function which can be used to unset the value from the context +// on which it was originally set. + 'use strict'; const util = require('util'); diff --git a/packages/core/src/tracing/clsHooked/index.js b/packages/core/src/tracing/clsHooked/index.js index 424fc85616..2940ff8fa1 100644 --- a/packages/core/src/tracing/clsHooked/index.js +++ b/packages/core/src/tracing/clsHooked/index.js @@ -3,30 +3,7 @@ * (c) Copyright Instana Inc. and contributors 2018 */ -/* eslint-env es6 */ -/* eslint-disable */ - -// This is a copy of cls-hooked - -// We are using a variation of cls-hooked, because we need to add additional cleanup logic. -// cls-hooked in its published version does not permit removal of values added to contexts. -// This is problematic for us in cases where sockets are long lived, e.g. http agents with -// maxSockets: Infinity. In such cases, the addition of the Node.js collector and the values it -// adds to async contexts (which are kept alive due to the living sockets), can tip a Node.js -// process over the edge. -// -// See also: -// https://github.com/Jeff-Lewis/cls-hooked/issues/21 -// https://github.com/Jeff-Lewis/cls-hooked/issues/11 - -// Changes: -// - rename the symbols to avoid name clashes -// - have Namespace.prototype.set return a function which can be used to unset the value from the context -// on which it was originally set. - -// Copy of -// Jeff-Lewis, feat(compat): v4.2 for node v4.7-v8 (0ebfb9b on Jul 21, 2017) -// https://github.com/Jeff-Lewis/cls-hooked/blob/066c6c4027a7924b06997cc6b175b1841342abdc/index.js +/* eslint-disable max-len */ 'use strict';