chore: added integration test for instana logger

packages/collector/test/tracing/logger/instana-logger/app-instana-creates-pino-logger.js

@@ -0,0 +1,61 @@
+/*
+ * (c) Copyright IBM Corp. 2024
+ */
+
+/* eslint-disable no-console */
+
+'use strict';
+
+// NOTE: c8 bug https://github.com/bcoe/c8/issues/166
+process.on('SIGTERM', () => {
+  process.disconnect();
+  process.exit(0);
+});
+
+const agentPort = process.env.AGENT_PORT;
+
+const instana = require('../../../..');
+instana({
+  agentPort,
+  level: 'warn',
+  tracing: {
+    enabled: process.env.TRACING_ENABLED !== 'false',
+    forceTransmissionStartingAt: 1
+  }
+});
+let instanaLogger;
+instanaLogger = require('../../../../src/logger').getLogger('test-module-name', newLogger => {
+  instanaLogger = newLogger;
+});
+
+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 = `Pino App [Instana creates Pino logger] (${process.pid}):\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('/trigger', (req, res) => {
+  instanaLogger.error('An error logged by Instana - this must not be traced');
+  res.sendStatus(200);
+});
+
+app.listen(port, () => {
+  log(`Listening on port: ${port}`);
+});
+
+function log() {
+  const args = Array.prototype.slice.call(arguments);
+  args[0] = logPrefix + args[0];
+  console.log.apply(console, args);
+}

packages/collector/test/tracing/logger/instana-logger/app-instana-receives-non-pino-logger.js

@@ -0,0 +1,72 @@
+/*
+ * (c) Copyright IBM Corp. 2024
+ */
+
+/* eslint-disable no-console */
+
+'use strict';
+
+// NOTE: c8 bug https://github.com/bcoe/c8/issues/166
+process.on('SIGTERM', () => {
+  process.disconnect();
+  process.exit(0);
+});
+
+const agentPort = process.env.AGENT_PORT;
+
+const dummyLogger = {
+  debug: function () {
+    // omit debug calls to not pollute test logs
+  },
+  info: console.log,
+  warn: console.warn,
+  error: console.error
+};
+
+const instana = require('../../../..')({
+  agentPort,
+  level: 'warn',
+  tracing: {
+    enabled: process.env.TRACING_ENABLED !== 'false',
+    forceTransmissionStartingAt: 1
+  }
+});
+
+instana.setLogger(dummyLogger);
+
+let instanaLogger;
+instanaLogger = require('../../../../src/logger').getLogger('test-module-name', newLogger => {
+  instanaLogger = newLogger;
+});
+
+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 = `Pino App [Instana receives non-Pino logger] (${process.pid}):\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('/trigger', (req, res) => {
+  instanaLogger.error('An error logged by Instana - this must not be traced');
+  res.sendStatus(200);
+});
+
+app.listen(port, () => {
+  log(`Listening on port: ${port}`);
+});
+
+function log() {
+  const args = Array.prototype.slice.call(arguments);
+  args[0] = logPrefix + args[0];
+  console.log.apply(console, args);
+}

packages/collector/test/tracing/logger/instana-logger/app-instana-receives-pino-logger.js

@@ -0,0 +1,62 @@
+/*
+ * (c) Copyright IBM Corp. 2024
+ */
+
+/* eslint-disable no-console */
+
+'use strict';
+
+// NOTE: c8 bug https://github.com/bcoe/c8/issues/166
+process.on('SIGTERM', () => {
+  process.disconnect();
+  process.exit(0);
+});
+
+const agentPort = process.env.AGENT_PORT;
+const pino = require('pino');
+const instana = require('../../../..')({
+  agentPort,
+  level: 'warn',
+  tracing: {
+    enabled: process.env.TRACING_ENABLED !== 'false',
+    forceTransmissionStartingAt: 1
+  }
+});
+instana.setLogger(pino({ name: 'app-logger' }));
+
+let instanaLogger;
+instanaLogger = require('../../../../src/logger').getLogger('test-module-name', newLogger => {
+  instanaLogger = newLogger;
+});
+
+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 = `Pino App [Instana receives Pino logger] (${process.pid}):\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('/trigger', (req, res) => {
+  instanaLogger.error('An error logged by Instana - this must not be traced');
+  res.sendStatus(200);
+});
+
+app.listen(port, () => {
+  log(`Listening on port: ${port}`);
+});
+
+function log() {
+  const args = Array.prototype.slice.call(arguments);
+  args[0] = logPrefix + args[0];
+  console.log.apply(console, args);
+}

packages/collector/test/tracing/logger/instana-logger/controls.js

@@ -0,0 +1,87 @@
+/*
+ * (c) Copyright IBM Corp. 2024
+ */
+
+'use strict';
+
+const spawn = require('child_process').spawn;
+const path = require('path');
+const portfinder = require('../../../test_util/portfinder');
+
+const testUtils = require('../../../../../core/test/test_util');
+const config = require('../../../../../core/test/config');
+
+const expressControls = require('../../../apps/expressControls');
+const agentControls = require('../../../globalAgent').instance;
+
+let appProcess;
+let appPort;
+
+exports.registerTestHooks = (opts = {}) => {
+  let appName = 'app.js';
+  if (opts.instanaLoggingMode) {
+    switch (opts.instanaLoggingMode) {
+      case 'instana-creates-pino-logger':
+        appName = 'app-instana-creates-pino-logger.js';
+        break;
+      case 'instana-receives-pino-logger':
+        appName = 'app-instana-receives-pino-logger.js';
+        break;
+      case 'instana-receives-non-pino-logger':
+        appName = 'app-instana-receives-non-pino-logger.js';
+        break;
+      default:
+        throw new Error(`Unknown instanaLoggingMode: ${opts.instanaLoggingMode}`);
+    }
+  }
+
+  beforeEach(async () => {
+    const env = Object.create(process.env);
+    env.AGENT_PORT = agentControls.getPort();
+    env.APP_PORT = portfinder();
+    appPort = env.APP_PORT;
+    env.UPSTREAM_PORT = expressControls.getPort();
+    env.STACK_TRACE_LENGTH = opts.stackTraceLength || 0;
+    env.TRACING_ENABLED = opts.enableTracing !== false;
+    env.INSTANA_RETRY_AGENT_CONNECTION_IN_MS = 100;
+    env.PINO_VERSION = opts.PINO_VERSION;
+
+    appProcess = spawn('node', [path.join(__dirname, appName)], {
+      stdio: config.getAppStdio(),
+      env
+    });
+
+    appProcess.on('message', msg => {
+      if (msg === 'instana.collector.initialized') {
+        appProcess.collectorInitialized = true;
+      }
+    });
+
+    await waitUntilServerIsUp();
+  });
+
+  afterEach(() => {
+    appProcess.kill();
+  });
+};
+
+function waitUntilServerIsUp() {
+  return testUtils.retry(async () => {
+    await fetch(`http://127.0.0.1:${appPort}`, {
+      method: 'GET',
+      headers: {
+        'X-INSTANA-L': '0'
+      }
+    });
+
+    if (!appProcess.collectorInitialized) throw new Error('Collector not fullly initialized.');
+  });
+}
+
+exports.getPid = () => appProcess.pid;
+
+exports.trigger = (level, headers = {}) => fetch(`http://127.0.0.1:${appPort}/${level}`, { headers });
+
+exports.stop = async () => {
+  await this.kill();
+};

packages/collector/test/tracing/logger/instana-logger/test.js

@@ -0,0 +1,67 @@
+/*
+ * (c) Copyright IBM Corp. 2024
+ */
+
+'use strict';
+
+const expect = require('chai').expect;
+
+const supportedVersion = require('@instana/core').tracing.supportedVersion;
+const config = require('../../../../../core/test/config');
+const testUtils = require('../../../../../core/test/test_util');
+const globalAgent = require('../../../globalAgent');
+
+const mochaSuiteFn = supportedVersion(process.versions.node) ? describe : describe.skip;
+
+mochaSuiteFn('tracing/instana-logger', function () {
+  this.timeout(config.getTestTimeout());
+
+  globalAgent.setUpCleanUpHooks();
+  const agentControls = globalAgent.instance;
+  const appControls = require('./controls');
+
+  // verify that Instana's own pino logging does not get traced
+  describe('do not trace Instana log calls', () => {
+    describe('Instana creates a new pino logger', () => {
+      appControls.registerTestHooks({
+        instanaLoggingMode: 'instana-creates-pino-logger'
+      });
+
+      it('log calls are not traced', () => verifyInstanaLoggingIsNotTraced());
+    });
+
+    describe('Instana receives a pino logger', () => {
+      appControls.registerTestHooks({
+        instanaLoggingMode: 'instana-receives-pino-logger'
+      });
+
+      it('log calls are not traced', () => verifyInstanaLoggingIsNotTraced());
+    });
+
+    describe('Instana receives a non-pino logger', () => {
+      appControls.registerTestHooks({
+        instanaLoggingMode: 'instana-receives-non-pino-logger'
+      });
+
+      it('log calls are not traced', () => verifyInstanaLoggingIsNotTraced());
+    });
+  });
+
+  function verifyInstanaLoggingIsNotTraced() {
+    return appControls.trigger('trigger').then(() =>
+      testUtils.retry(() =>
+        agentControls.getSpans().then(spans => {
+          testUtils.expectAtLeastOneMatching(spans, [
+            span => expect(span.n).to.equal('node.http.server'),
+            span => expect(span.f.e).to.equal(String(appControls.getPid())),
+            span => expect(span.f.h).to.equal('agent-stub-uuid')
+          ]);
+
+          // verify that nothing logged by Instana has been traced
+          const allpinoSpans = testUtils.getSpansByName(spans, 'log.pino');
+          expect(allpinoSpans).to.be.empty;
+        })
+      )
+    );
+  }
+});