test(sdk): add test for SDK entry span context

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}`);
+});

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}`);
+      }
+    }
+  }
+});

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');

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';