fix: replace bunyan logger #1447

abhilash-sivan · 2024-11-13T06:39:41Z

lock file change
check and verify concatenated strings using %s and correct it
pass logs to agent stream
fix tests for pino and logger_test
fix test for pino/test
fix instrumentation - We don't want to trace Instana's own loggers ( __in)
add additional test cases in pino
remove unwanted tests and enable only simple app test in bunyan

abhilash-sivan · 2024-12-16T12:10:38Z

packages/collector/src/agentConnection.js

@@ -267,9 +267,11 @@ exports.sendSpans = function sendSpans(spans, cb) {
    if (err && !maxContentErrorHasBeenLogged && err instanceof PayloadTooLargeError) {
      logLargeSpans(spans);
    } else if (err) {
-      logger.debug('Failed to send: %s', getSpanLengthInfo(spans));
+      const obj = getSpanLengthInfo(spans);


Pino does not support concatenated strings using %s if an object is passed instead of a string.

issue: Please use

logger.debug('Failed to send: %o', getSpanLengthInfo(spans));

There is more occurrences in the codebase.

logger.debug('Failed to send: %o', getSpanLengthInfo(spans));

Correction: This won't work for custom bunyan logger or winston.
Lets not use %s and no %o at all. Only normal strings.

If that works for all logger types, we can use this:

logger.debug('Failed to send spans", getSpanLengthInfo(spans))

If that does not work, you can use:

blabla = getSpanLengthInfo()
logger.debug(Failed to send spans ${blabla});

This is what you did already. Its probably better to raise a small PR to just remove this from our codebase. That would be good and makes the review easier.

abhilash-sivan · 2024-12-16T12:13:51Z

packages/collector/src/logger.js

+       * Custom write method to send logs to multiple destinations
+       * @param {string} chunk
+       */
+      write(chunk) {


custom write method which writes the log to stdout and agent stream function (pinoToAgentStream)

I tried implementing this use case using pino.transport, pino.destination and pino.multistream etc. And finally ended up with the current implementation which is working as expected like previous bunyan stream

abhilash-sivan · 2024-12-16T12:13:57Z

packages/collector/src/logger.js

@@ -31,40 +31,57 @@ const registry = {};
 * @param {boolean} [isReInit]
 */
 exports.init = function init(config, isReInit) {
+  const consoleStream = pino.destination(1);


If multistream is used, we need to specify the log streams where it is going. Here this is defined for logging into the process.stdout

I can't follow why we define this here.

While using multistream, our logger did not write to the console(stdout) by default.
We explicitly need to specify wherever this logs should go.
So added stdout and the agentStream as two attributes

abhilash-sivan · 2024-12-16T12:15:10Z

packages/collector/src/logger.js

+    parentLogger = pino(
+      {
+        ...parentLogger.levels,
+        base: parentLogger.bindings()


if we want to change something in pino logger after it is initialized, we need to create a new logger and assign initial logger bindings to it

abhilash-sivan · 2024-12-19T12:51:35Z

packages/collector/test/tracing/protocols/graphql/schema.js

@@ -8,18 +8,18 @@ const graphQL = require('graphql');
 const graphqlSubscriptions = require('graphql-subscriptions');
 const data = require('./data');
 // Pino log spans are used to verify that follow up calls are traced correctly in a GraphQL entry.
-const pinoLogger = require('pino')();
+const bunyanLogger = require('bunyan').createLogger({ name: 'test-logger' });


The reason for not using Winston here is that it is added to the list of packages allowed to load before the core module. In these situations, we might lose some spans that can cause the test to fail. We don't want to re-run the tests suppose this situation occurs

kirrg001 · 2024-12-20T09:18:21Z

packages/collector/test/tracing/misc/restore_context/app.js

@@ -16,7 +16,7 @@ const instana = require('../../../..')();
 const bodyParser = require('body-parser');
 const express = require('express');
 const morgan = require('morgan');
-const pino = require('pino')();
+const bunyan = require('bunyan').createLogger({ name: 'test-app' });


qs: Why can't we keep pino logger in all the apps? 🤔

kirrg001 · 2024-12-20T09:22:16Z

packages/collector/test/tracing/cloud/aws-sdk/v2/sqs/receiveMessage.js

@@ -32,7 +32,7 @@ const TeeLogger = require('../../../../../test_util/TeeLogger');
 const { sqs } = require('./sqsUtil');

 const instanaLogger = require('../../../../../../src/logger').getLogger('SQS receiver');
-instanaLogger.level('warn');
+instanaLogger.level = 'warn';


suggestion: Please use an interface method e.g. setInstanaLogLevel or simply setLevel. Otherwise we always need to update the whole codebase if we want to switch a logger.

kirrg001 · 2024-12-20T09:29:03Z

packages/collector/src/agentConnection.js

@@ -267,9 +267,11 @@ exports.sendSpans = function sendSpans(spans, cb) {
    if (err && !maxContentErrorHasBeenLogged && err instanceof PayloadTooLargeError) {
      logLargeSpans(spans);
    } else if (err) {
-      logger.debug('Failed to send: %s', getSpanLengthInfo(spans));
+      const obj = getSpanLengthInfo(spans);


issue: Please use

logger.debug('Failed to send: %o', getSpanLengthInfo(spans));

There is more occurrences in the codebase.

kirrg001 · 2024-12-20T09:34:57Z

packages/collector/src/logger.js

  if (config.logger && typeof config.logger.child === 'function') {
-    // A bunyan or pino logger has been provided via config. In either case we create a child logger directly under the
-    // given logger which serves as the parent for all loggers we create later on.
+    // A pino logger has been provided via config; create a child logger directly under it.


issue: Why did you change the comment when the condition was not changed? Is config.logger.child === function not valid for Bunyan? Was this wrong in the first place?

kirrg001 · 2024-12-20T09:51:01Z

packages/collector/src/logger.js

-      level: 'info'
-    });
+
+  if (isPino(parentLogger)) {


qs: It seems this condition is only for the internal logger, is that right? Because if yes, we can simplify the logic a lot.

yes, this is for the internal logger only.

kirrg001 · 2024-12-20T09:52:16Z

packages/collector/src/logger.js

@@ -31,40 +31,57 @@ const registry = {};
 * @param {boolean} [isReInit]
 */
 exports.init = function init(config, isReInit) {
+  const consoleStream = pino.destination(1);


I can't follow why we define this here.

kirrg001 · 2024-12-20T09:53:23Z

packages/collector/test/logger_test.js

+ * @param {*} _logger
+ * @returns {boolean}
+ */
+function isPinoLogger(_logger) {


qs: Can we expose this helper function from the logger interface?

kirrg001 · 2024-12-20T09:54:15Z

packages/collector/test/tracing/logger/bunyan/app.js

-    forceTransmissionStartingAt: 1
-  }
-});
+require('../../../..')();


qs: Can you please explain this removal?

kirrg001 · 2024-12-20T10:20:39Z

packages/collector/test/tracing/logger/pino/test.js

 const globalAgent = require('../../../globalAgent');
+const appControls = require('./controls');


issue: Please do not touch this test. Add a new internal logging integration test.

aryamohanan

Why can't we use the native console instead of Pino?

aryamohanan · 2024-12-23T05:22:37Z

packages/core/src/uninstrumentedLogger.js

+
+'use strict';
+
+// instana/no-unsafe-require


Suggested change

// instana/no-unsafe-require

aryamohanan · 2024-12-23T05:24:29Z

packages/core/src/uninstrumentedLogger.js

+const logger = require('pino');
+
+function createCustomLogger() {
+  const customPino = Object.assign(function (/** @type {any} */ ...args) {


Suggested change

const customPino = Object.assign(function (/** @type {any} */ ...args) {

const customLogger = Object.assign(function (/** @type {any} */ ...args) {

aryamohanan · 2024-12-23T05:41:18Z

packages/core/src/tracing/instrumentation/loggers/bunyan.js

@@ -29,13 +29,6 @@ function instrument(Logger) {
 function shimLog(markAsError) {
  return originalLog =>
    function () {
-      if (arguments.length === 0 || (this.fields && !!this.fields.__in)) {


qs: Why was the arguments.length === 0 check removed? This check prevents tracing unnecessary log calls like logger.warn() without arguments, which don’t produce useful data. How are we handling these cases now?

That was removed by mistake. Added it back

aryamohanan · 2024-12-23T05:50:14Z

packages/collector/src/agentConnection.js

@@ -267,9 +267,11 @@ exports.sendSpans = function sendSpans(spans, cb) {
    if (err && !maxContentErrorHasBeenLogged && err instanceof PayloadTooLargeError) {
      logLargeSpans(spans);
    } else if (err) {
-      logger.debug('Failed to send: %s', getSpanLengthInfo(spans));
+      const obj = getSpanLengthInfo(spans);


suggestion: Consider renaming obj to spanInfo or a similar name to improve clarity and provide better context.

aryamohanan · 2024-12-23T05:58:20Z

packages/collector/src/agentConnection.js

@@ -267,9 +267,11 @@ exports.sendSpans = function sendSpans(spans, cb) {
    if (err && !maxContentErrorHasBeenLogged && err instanceof PayloadTooLargeError) {
      logLargeSpans(spans);
    } else if (err) {
-      logger.debug('Failed to send: %s', getSpanLengthInfo(spans));
+      const obj = getSpanLengthInfo(spans);
+      logger.debug({ obj }, 'Failed to transmit.');


Suggested change

logger.debug({ obj }, 'Failed to transmit.');

logger.debug('Failed to send', { obj });

Is this format works?

No this does not work with pino

aryamohanan · 2024-12-23T06:15:12Z

packages/collector/src/logger.js

@@ -16,12 +16,14 @@ try {
  // thread (0).
 }

-const bunyan = require('bunyan');
-const { logger } = require('@instana/core');
+const { uninstrumentedLogger: pinoCopy } = require('@instana/core');


Suggested change

const { uninstrumentedLogger: pinoCopy } = require('@instana/core');

const { uninstrumentedLogger: pinoCopy } = require('@instana/core');

Suggested change

const { uninstrumentedLogger: pinoCopy } = require('@instana/core');

const { uninstrumentedLogger: pino } = require('@instana/core');

aryamohanan · 2024-12-23T06:35:21Z

packages/collector/src/logger.js

+        consoleStream.write(chunk);
+
+        const logRecord = JSON.parse(chunk);
+        pinoToAgentStream.write(logRecord);


Suggested change

pinoToAgentStream.write(logRecord);

pinoToAgentStream.write(JSON.parse(chunk));

aryamohanan · 2024-12-23T06:41:01Z

packages/collector/src/logger.js

 * @returns {boolean}
 */
-function isBunyan(_logger) {
-  return _logger instanceof bunyan;
+function isPino(_logger) {


concern: Relying on internal symbols (e.g., pino.symbols.streamSym)
may introduce risks if Pino's internal structure changes in future versions.

We can't check instanceof of pino. We need to rely on some internal functions to check this.
We don't need this check for the new logic. removing the function

aryamohanan · 2024-12-23T11:29:51Z

packages/collector/test/tracing/common/app.js

@@ -42,7 +42,7 @@ if (process.env.SCREW_AROUND_WITH_UP_ARRAY_FIND) {
 const instana = require('../../..')(config);

 const http = require('http');
-const pino = require('pino')();
+const bunyan = require('bunyan').createLogger({ name: 'test-common' });


In tests, consider using Winston or any other logger instead of Bunyan, as Bunyan is no longer actively maintained. If we need to drop support for Bunyan in the future, it could become difficult.

Planning to get it back to pino itself, that way we can be sure that our internal pino logs are not traced

…the unintsurmentedLogger module

abhilash-sivan added the WIP label Nov 13, 2024

abhilash-sivan changed the title ~~Fix replace bunyan~~ fix: replace bunyan logger Nov 18, 2024

abhilash-sivan force-pushed the fix-replace-bunyan branch from a34cab4 to 5e5f845 Compare November 19, 2024 05:29

abhilash-sivan force-pushed the fix-replace-bunyan branch from c756449 to accb4aa Compare November 26, 2024 08:05

abhilash-sivan commented Dec 16, 2024

View reviewed changes

abhilash-sivan force-pushed the fix-replace-bunyan branch from bd47728 to 6bcd53d Compare December 17, 2024 15:02

abhilash-sivan commented Dec 19, 2024

View reviewed changes

kirrg001 reviewed Dec 20, 2024

View reviewed changes

abhilash-sivan marked this pull request as ready for review December 20, 2024 10:21

abhilash-sivan requested a review from a team as a code owner December 20, 2024 10:21

abhilash-sivan removed the WIP label Dec 20, 2024

aryamohanan reviewed Dec 23, 2024

View reviewed changes

abhilash-sivan force-pushed the fix-replace-bunyan branch from 2b00699 to 5e80c7b Compare December 24, 2024 13:34

abhilash-sivan added 16 commits December 24, 2024 19:30

fix: replace bunyan and set pino as default loggger

39fc572

chore: updated type error

5e89de5

chore: update package lock

31d9183

chore: update pino child

6c22006

fix: updated logger with pino child

0b8b6d5

chore: removed unused function

3ee4089

chore: test case update

a2aeb22

chore: updated err msg

8e9c0f5

chore: test

dfd6a94

fix: added multistream for writing logs to agent

34cc23b

test: update test fn

a76eb67

test: fixed logger_test

a92d4b0

chore: lint fix

2c6b457

fix: fixed initialized too late warning

94a90a2

test: fix pino test

a975508

test: updated test for pino and removed unwanted tests in bunyan

e68b7b9

abhilash-sivan added 8 commits December 24, 2024 19:31

test: update test failed in ci

2d449b7

chore: test fix

387160d

test: fix bunyan test

c950d46

chore: cleanup

8e5d18f

chore: adapt pr comments

580de65

chore: adapt pr comments

bc7cbe8

chore: added integration test for instana logger

f743555

chore: added setLoggerLevel method

30a2a75

abhilash-sivan force-pushed the fix-replace-bunyan branch from 3bb0226 to 30a2a75 Compare December 24, 2024 14:03

chore: added pino to core modules as we use this package in creating …

9cc1abc

…the unintsurmentedLogger module

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: replace bunyan logger #1447

fix: replace bunyan logger #1447

abhilash-sivan commented Nov 13, 2024 •

edited

Loading

abhilash-sivan Dec 16, 2024

kirrg001 Dec 20, 2024

kirrg001 Dec 20, 2024

abhilash-sivan Dec 16, 2024

abhilash-sivan Dec 16, 2024

abhilash-sivan Dec 16, 2024

kirrg001 Dec 20, 2024

abhilash-sivan Dec 20, 2024

abhilash-sivan Dec 16, 2024

abhilash-sivan Dec 19, 2024

kirrg001 Dec 20, 2024

kirrg001 Dec 20, 2024

kirrg001 Dec 20, 2024

kirrg001 Dec 20, 2024

kirrg001 Dec 20, 2024

abhilash-sivan Dec 20, 2024

kirrg001 Dec 20, 2024

kirrg001 Dec 20, 2024

kirrg001 Dec 20, 2024

kirrg001 Dec 20, 2024

aryamohanan left a comment

aryamohanan Dec 23, 2024

aryamohanan Dec 23, 2024

aryamohanan Dec 23, 2024

abhilash-sivan Dec 24, 2024

aryamohanan Dec 23, 2024

aryamohanan Dec 23, 2024

abhilash-sivan Dec 24, 2024

aryamohanan Dec 23, 2024

aryamohanan Dec 23, 2024

aryamohanan Dec 23, 2024

abhilash-sivan Dec 24, 2024

aryamohanan Dec 23, 2024

abhilash-sivan Dec 24, 2024

		const globalAgent = require('../../../globalAgent');
		const appControls = require('./controls');

	const customPino = Object.assign(function (/** @type {any} */ ...args) {
	const customLogger = Object.assign(function (/** @type {any} */ ...args) {

	logger.debug({ obj }, 'Failed to transmit.');
	logger.debug('Failed to send', { obj });

	const { uninstrumentedLogger: pinoCopy } = require('@instana/core');
	const { uninstrumentedLogger: pinoCopy } = require('@instana/core');

	const { uninstrumentedLogger: pinoCopy } = require('@instana/core');
	const { uninstrumentedLogger: pino } = require('@instana/core');

	pinoToAgentStream.write(logRecord);
	pinoToAgentStream.write(JSON.parse(chunk));

fix: replace bunyan logger #1447

Are you sure you want to change the base?

fix: replace bunyan logger #1447

Conversation

abhilash-sivan commented Nov 13, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aryamohanan left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

abhilash-sivan commented Nov 13, 2024 •

edited

Loading