From 9a0d8fc0420e7462c3f17e247127b44a320eeace Mon Sep 17 00:00:00 2001 From: gurke Date: Mon, 22 Jul 2024 10:07:59 +0200 Subject: [PATCH] fix(core): avoided creating standalone exit spans when using the sdk (#1234) refs https://jsw.ibm.com/browse/INSTA-10132 --- .../test/test_util/ProcessControls.js | 3 +- .../tracing/protocols/http/client/sdkApp1.js | 46 ++++++++++++++ .../tracing/protocols/http/client/sdkApp2.js | 60 +++++++++++++++++++ .../tracing/protocols/http/client/test.js | 55 ++++++++++++++++- packages/core/src/tracing/clsHooked/unset.js | 8 ++- 5 files changed, 168 insertions(+), 4 deletions(-) create mode 100644 packages/collector/test/tracing/protocols/http/client/sdkApp1.js create mode 100644 packages/collector/test/tracing/protocols/http/client/sdkApp2.js diff --git a/packages/collector/test/test_util/ProcessControls.js b/packages/collector/test/test_util/ProcessControls.js index 5592caf181..c9ce984ca8 100644 --- a/packages/collector/test/test_util/ProcessControls.js +++ b/packages/collector/test/test_util/ProcessControls.js @@ -140,7 +140,7 @@ class ProcessControls { return this.port; } - async start(retryTime, until) { + async start(retryTime, until, skipWaitUntilServerIsUp = false) { const that = this; this.receivedIpcMessages = []; @@ -166,6 +166,7 @@ class ProcessControls { } }); + if (skipWaitUntilServerIsUp) return; await this.waitUntilServerIsUp(retryTime, until); } diff --git a/packages/collector/test/tracing/protocols/http/client/sdkApp1.js b/packages/collector/test/tracing/protocols/http/client/sdkApp1.js new file mode 100644 index 0000000000..feeb63d231 --- /dev/null +++ b/packages/collector/test/tracing/protocols/http/client/sdkApp1.js @@ -0,0 +1,46 @@ +/* + * (c) Copyright IBM Corp. 2024 + */ + +'use strict'; + +// NOTE: c8 bug https://github.com/bcoe/c8/issues/166 +process.on('SIGTERM', () => { + process.disconnect(); + process.exit(0); +}); + +const instana = require('../../../../..')(); +const { delay } = require('../../../../../../core/test/test_util'); +const nodeFetch = require('node-fetch-v2'); + +const main = async () => { + let err1; + + try { + const req = new nodeFetch.Request('https://example.com'); + await nodeFetch(req); + + await instana.sdk.async.startEntrySpan('my-translation-service'); + await nodeFetch('https://www.ibm.com/products/instana'); + } catch (err) { + err1 = err; + } + + instana.sdk.async.completeEntrySpan(err1); +}; + +const app = async () => { + let count = 0; + + while (count < 2) { + // eslint-disable-next-line no-await-in-loop + await main(); + count += 1; + + // eslint-disable-next-line no-await-in-loop + await delay(500); + } +}; + +app(); diff --git a/packages/collector/test/tracing/protocols/http/client/sdkApp2.js b/packages/collector/test/tracing/protocols/http/client/sdkApp2.js new file mode 100644 index 0000000000..84711eca74 --- /dev/null +++ b/packages/collector/test/tracing/protocols/http/client/sdkApp2.js @@ -0,0 +1,60 @@ +/* + * (c) Copyright IBM Corp. 2024 + */ + +'use strict'; + +// NOTE: c8 bug https://github.com/bcoe/c8/issues/166 +process.on('SIGTERM', () => { + process.disconnect(); + process.exit(0); +}); + +const instana = require('../../../../..')(); +const bodyParser = require('body-parser'); +const express = require('express'); +const morgan = require('morgan'); +const port = require('../../../../test_util/app-port')(); + +const app = express(); +const logPrefix = 'SDK App 2\t'; + +if (process.env.WITH_STDOUT) { + app.use(morgan(`${logPrefix}:method :url :status`)); +} + +app.use(bodyParser.json()); + +app.get('/', (req, res) => res.sendStatus(200)); + +app.get('/deferred-exit', (req, res) => { + /* + We do not support this case, because calling "startExitSpan" calls "skipExitTracing" + and this function does not respect reduced spans. + + setTimeout(async () => { + await instana.sdk.async.startExitSpan('deferred-exit'); + instana.sdk.async.completeExitSpan(); + }, 1000); + */ + + setTimeout(async () => { + await instana.sdk.async.startEntrySpan('deferred-entry'); + await instana.sdk.async.startExitSpan('deferred-exit'); + instana.sdk.async.completeExitSpan(); + instana.sdk.async.completeEntrySpan(); + }, 1000); + + res.sendStatus(200); +}); + +app.listen(port, () => { + log(`Listening on port: ${port}`); +}); + +function log() { + /* eslint-disable no-console */ + const args = Array.prototype.slice.call(arguments); + args[0] = logPrefix + args[0]; + console.log.apply(console, args); +} diff --git a/packages/collector/test/tracing/protocols/http/client/test.js b/packages/collector/test/tracing/protocols/http/client/test.js index 69a747d115..42d93f5e50 100644 --- a/packages/collector/test/tracing/protocols/http/client/test.js +++ b/packages/collector/test/tracing/protocols/http/client/test.js @@ -12,7 +12,7 @@ const semver = require('semver'); const constants = require('@instana/core').tracing.constants; const supportedVersion = require('@instana/core').tracing.supportedVersion; const config = require('../../../../../../core/test/config'); -const { expectExactlyOneMatching, retry } = require('../../../../../../core/test/test_util'); +const { expectExactlyOneMatching, retry, delay } = require('../../../../../../core/test/test_util'); const ProcessControls = require('../../../../test_util/ProcessControls'); const globalAgent = require('../../../../globalAgent'); @@ -39,6 +39,59 @@ mochaSuiteFn('tracing/http client', function () { describe('superagent', function () { registerSuperagentTest.call(this); }); + + describe('SDK CASE 1', function () { + let sdkControls; + + before(async () => { + sdkControls = new ProcessControls({ + appPath: path.join(__dirname, 'sdkApp1'), + useGlobalAgent: true, + env: {} + }); + + await sdkControls.start(null, null, true); + }); + + it('should not trace example.com exit span without entry span', async () => { + await delay(2500); + + await retry(async () => { + const spans = await globalAgent.instance.getSpans(); + expect(spans.length).to.equal(4); + }); + }); + }); + + describe('SDK CASE 2', function () { + let sdkControls; + + before(async () => { + sdkControls = new ProcessControls({ + appPath: path.join(__dirname, 'sdkApp2'), + useGlobalAgent: true, + env: {} + }); + + await sdkControls.startAndWaitForAgentConnection(); + }); + + after(async () => { + await sdkControls.stop(); + }); + + it('should trace deferred exit calls', async () => { + await sdkControls.sendRequest({ + method: 'GET', + path: '/deferred-exit' + }); + + await retry(async () => { + const spans = await globalAgent.instance.getSpans(); + expect(spans.length).to.equal(3); + }); + }); + }); }); function registerTests(useHttps) { diff --git a/packages/core/src/tracing/clsHooked/unset.js b/packages/core/src/tracing/clsHooked/unset.js index c26eba0e42..a2a9dfebe2 100644 --- a/packages/core/src/tracing/clsHooked/unset.js +++ b/packages/core/src/tracing/clsHooked/unset.js @@ -55,8 +55,12 @@ function storeReducedSpan(context, key, span) { // which an init call has been received, the memory used by clsHooked will grow, because context objects will be kept // around forever. By keeping the reduced span we can at least see (in a heap dump) for which type of spans the // destroy call is missing, aiding in troubleshooting the Node.js runtime bug. - - if (key === currentSpanKey && span != null) { + // + // Exception: + // SDK spans are different. Customers use "startEntrySpan" or "startExitSpan" manually inside their code base. + // We cannot remember the reduced spans because it can mislead to a wrong functionality such as + // tracing exit spans without entry spans - see sdkApp1.js. + if (key === currentSpanKey && span != null && span.n !== 'sdk') { context[reducedSpanKey] = { n: span.n, t: span.t,