diff --git a/packages/collector/test/tracing/logger/instana-logger/app-instana-creates-pino-logger.js b/packages/collector/test/tracing/logger/instana-logger/app-instana-creates-pino-logger.js new file mode 100644 index 000000000..1cbb026c1 --- /dev/null +++ b/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); +} diff --git a/packages/collector/test/tracing/logger/instana-logger/app-instana-receives-non-pino-logger.js b/packages/collector/test/tracing/logger/instana-logger/app-instana-receives-non-pino-logger.js new file mode 100644 index 000000000..2d127ebd4 --- /dev/null +++ b/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); +} diff --git a/packages/collector/test/tracing/logger/instana-logger/app-instana-receives-pino-logger.js b/packages/collector/test/tracing/logger/instana-logger/app-instana-receives-pino-logger.js new file mode 100644 index 000000000..8f5dcbe27 --- /dev/null +++ b/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); +} diff --git a/packages/collector/test/tracing/logger/instana-logger/controls.js b/packages/collector/test/tracing/logger/instana-logger/controls.js new file mode 100644 index 000000000..3ad59b7c8 --- /dev/null +++ b/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(); +}; diff --git a/packages/collector/test/tracing/logger/instana-logger/test.js b/packages/collector/test/tracing/logger/instana-logger/test.js new file mode 100644 index 000000000..8a4a5c5eb --- /dev/null +++ b/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; + }) + ) + ); + } +});