diff --git a/packages/collector/test/tracing/logging/pino/app.js b/packages/collector/test/tracing/logging/pino/app.js index d22c6227a4..f5646f182f 100644 --- a/packages/collector/test/tracing/logging/pino/app.js +++ b/packages/collector/test/tracing/logging/pino/app.js @@ -14,7 +14,10 @@ process.on('SIGTERM', () => { }); require('./mockVersion'); -require('../../../..')(); + +if (!process.env.NODE_OPTIONS || !process.env.NODE_OPTIONS.includes('src/immediate')) { + require('../../../..')(); +} const fetch = require('node-fetch-v2'); const bodyParser = require('body-parser'); @@ -212,6 +215,22 @@ app.get('/express-pino-error-random-object-and-string', (req, res) => { finish(res); }); +app.get('/thread-stream-test', (req, res) => { + try { + const mode = process.env.PINO_WORKER_MODE || 'transport'; + + const logger = + mode === 'transport' + ? pino({ transport: { target: 'pino-pretty', options: { destination: 1 } } }) + : pino({ destination: 1 }); + logger.error('Pino worker test error log'); + + res.sendStatus(200); + } catch (e) { + res.status(500).send(`Failed: ${e.message}`); + } +}); + function finish(res) { fetch(`http://127.0.0.1:${agentPort}`).then(() => { res.sendStatus(200); diff --git a/packages/collector/test/tracing/logging/pino/test.js b/packages/collector/test/tracing/logging/pino/test.js index a78b9e3c9a..49d44540d0 100644 --- a/packages/collector/test/tracing/logging/pino/test.js +++ b/packages/collector/test/tracing/logging/pino/test.js @@ -102,6 +102,51 @@ describe('tracing/logging/pino', function () { }); }); }); + describe('pino thread-stream worker', function () { + let controls; + + before(async () => { + controls = new ProcessControls({ + dirname: __dirname, + useGlobalAgent: true, + env: { + PINO_WORKER_MODE: 'transport', + PINO_EXPRESS: 'false', + NODE_OPTIONS: `--require ${path.join(__dirname, '../../../..', 'src', 'immediate.js')}` + } + }); + + await controls.startAndWaitForAgentConnection(); + }); + + beforeEach(async () => { + await agentControls.clearReceivedTraceData(); + }); + + after(async () => { + await controls.stop(); + }); + + it('must trace without errors', async () => { + await controls.sendRequest({ + method: 'GET', + path: '/thread-stream-test' + }); + await testUtils.delay(1000); + const spans = await agentControls.getSpans(); + + const logSpan = spans.find(s => s.n === 'log.pino'); + expect(logSpan).to.exist; + expect(logSpan.data.log.message).to.equal('Pino worker test error log'); + + const httpSpan = spans.find(s => s.n === 'node.http.server'); + expect(httpSpan).to.exist; + expect(httpSpan.data.http.path_tpl).to.equal('/thread-stream-test'); + expect(httpSpan.data.http.status).to.equal(200); + + expect(spans).to.have.lengthOf(2); + }); + }); function runTests(pinoVersion, useExpressPino) { const suffix = useExpressPino ? ' (express-pino)' : ''; diff --git a/packages/core/src/util/excludedFromInstrumentation.js b/packages/core/src/util/excludedFromInstrumentation.js index 1d139185da..b29740a1a9 100644 --- a/packages/core/src/util/excludedFromInstrumentation.js +++ b/packages/core/src/util/excludedFromInstrumentation.js @@ -13,22 +13,61 @@ // no value and also creates confusing log output, so we exclude them here explicitly. const excludePattern = /^.*\/(?:npm(?:\.js)?|npm-cli(?:\.js)?|yarn(?:\.js)?|yarn\/lib\/cli(?:\.js)?)$/i; +/** + * Determines if the current process is a Pino thread-stream worker. + * Pino uses background worker threads for "thread-stream" logging, which should not be instrumented. + * @returns {boolean} + */ +function isPinoThreadStreamWorker() { + try { + const { isMainThread, workerData } = require('worker_threads'); + if (isMainThread) return false; + + if (workerData && typeof workerData === 'object') { + const nested = workerData.workerData; + const isPinoWorker = + typeof workerData.filename === 'string' && + nested && + nested.$context && + typeof nested.$context.threadStreamVersion === 'string'; + + if (isPinoWorker) { + return true; + } + } + return false; + } catch { + return false; + } +} + /** * @type {Function} * @returns {boolean} */ module.exports = exports = function isExcludedFromInstrumentation() { const mainModule = process.argv[1]; - const excludedFromInstrumentation = typeof mainModule === 'string' && excludePattern.test(mainModule); + let excludedFromInstrumentation = typeof mainModule === 'string' && excludePattern.test(mainModule); + let reason = 'npm-yarn'; + + if (!excludedFromInstrumentation && isPinoThreadStreamWorker()) { + excludedFromInstrumentation = true; + reason = 'pino-thread-stream'; + } - if (excludedFromInstrumentation) { - const logLevelIsDebugOrInfo = - process.env.INSTANA_DEBUG || - (process.env.INSTANA_LOG_LEVEL && - (process.env.INSTANA_LOG_LEVEL.toLowerCase() === 'info' || - process.env.INSTANA_LOG_LEVEL.toLowerCase() === 'debug')); + const logEnabled = + process.env.INSTANA_DEBUG || + (process.env.INSTANA_LOG_LEVEL && ['info', 'debug'].includes(process.env.INSTANA_LOG_LEVEL.toLowerCase())); - if (logLevelIsDebugOrInfo) { + if (excludedFromInstrumentation && logEnabled) { + if (reason === 'pino-thread-stream') { + // eslint-disable-next-line no-console + console.log( + // eslint-disable-next-line max-len + `[Instana] INFO: Skipping instrumentation for process ${process.pid} - detected as a Pino thread-stream worker. ` + + 'Logging threads do not require instrumentation.' + ); + } else { // eslint-disable-next-line no-console console.log( `[Instana] INFO: Not instrumenting process ${process.pid}: ${process.argv[0]} ${mainModule}` + diff --git a/packages/core/test/util/excludedFromInstrumentation_test.js b/packages/core/test/util/excludedFromInstrumentation_test.js index b6a3fbddbf..e371247804 100644 --- a/packages/core/test/util/excludedFromInstrumentation_test.js +++ b/packages/core/test/util/excludedFromInstrumentation_test.js @@ -66,6 +66,165 @@ describe('util.excludedFromInstrumentation', () => { expect(isExcluded('/usr/local/npmx.js')).to.be.false; }); + describe('pino thread-stream worker detection', () => { + let originalRequire; + + beforeEach(() => { + originalRequire = require.cache[require.resolve('worker_threads')]; + }); + + afterEach(() => { + if (originalRequire) { + require.cache[require.resolve('worker_threads')] = originalRequire; + } else { + delete require.cache[require.resolve('worker_threads')]; + } + delete require.cache[require.resolve('../../src/util/excludedFromInstrumentation')]; + }); + + it('should exclude Pino thread-stream worker with valid structure', () => { + mockWorkerThreads({ + isMainThread: false, + workerData: { + filename: '/path/to/worker.js', + workerData: { + $context: { + threadStreamVersion: '2.0.0' + }, + target: 'pino-pretty' + } + } + }); + + const checkExclusion = require('../../src/util/excludedFromInstrumentation'); + expect(checkExclusion()).to.be.true; + }); + + it('should exclude Pino thread-stream worker with targets property', () => { + mockWorkerThreads({ + isMainThread: false, + workerData: { + filename: '/path/to/worker.js', + workerData: { + $context: { + threadStreamVersion: '2.1.0' + }, + targets: [{ target: 'pino-pretty' }] + } + } + }); + + const checkExclusion = require('../../src/util/excludedFromInstrumentation'); + expect(checkExclusion()).to.be.true; + }); + + it('should not exclude main thread', () => { + mockWorkerThreads({ + isMainThread: true, + workerData: { + filename: '/path/to/worker.js', + workerData: { + $context: { + threadStreamVersion: '2.0.0' + } + } + } + }); + + const checkExclusion = require('../../src/util/excludedFromInstrumentation'); + expect(checkExclusion()).to.be.false; + }); + + it('should not exclude worker without workerData', () => { + mockWorkerThreads({ + isMainThread: false, + workerData: null + }); + + const checkExclusion = require('../../src/util/excludedFromInstrumentation'); + expect(checkExclusion()).to.be.false; + }); + + it('should not exclude worker without filename', () => { + mockWorkerThreads({ + isMainThread: false, + workerData: { + workerData: { + $context: { + threadStreamVersion: '2.0.0' + } + } + } + }); + + const checkExclusion = require('../../src/util/excludedFromInstrumentation'); + expect(checkExclusion()).to.be.false; + }); + + it('should not exclude worker without nested workerData', () => { + mockWorkerThreads({ + isMainThread: false, + workerData: { + filename: '/path/to/worker.js' + } + }); + + const checkExclusion = require('../../src/util/excludedFromInstrumentation'); + expect(checkExclusion()).to.be.false; + }); + + it('should not exclude worker without $context', () => { + mockWorkerThreads({ + isMainThread: false, + workerData: { + filename: '/path/to/worker.js', + workerData: { + someOtherProperty: 'value' + } + } + }); + + const checkExclusion = require('../../src/util/excludedFromInstrumentation'); + expect(checkExclusion()).to.be.false; + }); + + it('should not exclude worker without threadStreamVersion', () => { + mockWorkerThreads({ + isMainThread: false, + workerData: { + filename: '/path/to/worker.js', + workerData: { + $context: { + someOtherProperty: 'value' + } + } + } + }); + + const checkExclusion = require('../../src/util/excludedFromInstrumentation'); + expect(checkExclusion()).to.be.false; + }); + + it('should not exclude non-Pino worker thread', () => { + mockWorkerThreads({ + isMainThread: false, + workerData: { + customData: 'some other worker' + } + }); + + const checkExclusion = require('../../src/util/excludedFromInstrumentation'); + expect(checkExclusion()).to.be.false; + }); + + function mockWorkerThreads(mockData) { + const mockModule = { + exports: mockData + }; + require.cache[require.resolve('worker_threads')] = mockModule; + } + }); + function isExcluded(argv1) { process.argv[1] = argv1; return isExcludedFromInstrumentation();