[#373] gRPC Logger

Author: feelform

lib/client/grpc-data-sender.js

@@ -25,6 +25,7 @@ const { logError } = require('./grpc-errors')
 const StreamDeadlineOptionsBuilder = require('./stream-deadline-options-builder')
 const GrpcReadableStreamBuilder = require('./grpc-readable-stream-builder')
 const UnaryDeadlineOptionsBuilder = require('./unary-deadline-options-builder')
+const { LogBuilder } = require('../utils/log/log-builder')
 
 // AgentInfoSender.java
 // refresh daily
@@ -38,6 +39,7 @@ class GrpcDataSender {
     this.collectorTcpPort = collectorTcpPort
     this.collectorStatPort = collectorStatPort
     this.collectorSpanPort = collectorSpanPort
+    this.logger = log.getLogger(LogBuilder.buildGrpcLog())
 
     this.unaryDeadlineOptionsBuilder = new UnaryDeadlineOptionsBuilder()
     this.initializeClients()
@@ -256,7 +258,7 @@ class GrpcDataSender {
       this.spanStream.push(pSpanChunk)
     } catch (e) {
       if (e && e.stack) {
-        log.error(`sendSpanChunk(spanChunk) Error: ${e.stack}`)
+        this.logger.error(`sendSpanChunk(spanChunk) Error: ${e.stack}`)
       }
     }
   }
@@ -271,7 +273,7 @@ class GrpcDataSender {
       this.statStream.push(pStatMessage)
     } catch (e) {
       if (e && e.stack) {
-        log.error('sendStat(stat) Error: ', e)
+        this.logger.error('sendStat(stat) Error: ', e)
       }
     }
   }
@@ -282,8 +284,8 @@ class GrpcDataSender {
     }
 
     const pCmdMessage = CommandType.supportedServicesCommandMessage()
-    if (log.isDebug()) {
-      log.debug(`sendControlHandshake pCmdMessage: `, pCmdMessage.toObject())
+    if (this.logger.isDebug()) {
+      this.logger.debug(`sendControlHandshake pCmdMessage: `, pCmdMessage.toObject())
     }
     this.commandStream.push(pCmdMessage)
   }
@@ -361,7 +363,7 @@ class GrpcDataSender {
     let options = this.unaryDeadlineOptionsBuilder.build()
     this.profilerClient.commandEcho(commandEchoResponse, options, (err, response) => {
       if (err) {
-        log.error(err)
+        this.logger.error(err)
       }
       if (callback) {
         callback(err, response)

lib/client/grpc-errors.js

@@ -8,20 +8,26 @@
 
 const grpc = require('@grpc/grpc-js')
 const log = require('../utils/log/logger')
+const { LogBuilder } = require('../utils/log/log-builder')
 
+let logger = null
 function logError(message, error) {
     if (!error) {
         return
     }
 
+    if (!logger) {
+        logger = log.getLogger(LogBuilder.buildGrpcLog())
+    }
+
     if (isCancelledError(error)) {
-        log.error(`Pinpoint Collector has been shut down : ${message}`)
+        logger.error(`Pinpoint Collector has been shut down : ${message}`)
     } else if (isUnavailableError(error)) {
-        log.error(`Pinpoint Collector is gRPC connection unavailable : ${message}`)
+        logger.error(`Pinpoint Collector is gRPC connection unavailable : ${message}`)
     } else if (isDeadlineExceededError(error)) {
-        log.error(`gRPC Stream deadline exceeded : ${message}`, error)
+        logger.error(`gRPC Stream deadline exceeded : ${message}`, error)
     } else {
-        log.error(message, error)
+        logger.error(message, error)
     }
 }
 

lib/client/grpc-readable-stream.js

@@ -9,6 +9,7 @@
 const { Transform } = require('node:stream')
 const log = require('../utils/log/logger')
 const { logError } = require('./grpc-errors')
+const { LogBuilder } = require('../utils/log/log-builder')
 
 const maxAttempts = 3
 const initialBackoff = 1000
@@ -20,6 +21,7 @@ class GrpcReadableStream {
         this.readableStream = this.makeReadableStream()
         this.name = options.name ?? ''
         this.pipeWritableStream()
+        this.logger = log.getLogger(LogBuilder.buildGrpcLog())
     }
 
     makeReadableStream() {
@@ -95,7 +97,7 @@ class GrpcReadableStream {
             this.writableStream = writableStream
         } catch (error) {
             if(error?.message !== 'Channel has been shut down') {
-                log.error('error in pipeWritableStream', error)
+                this.logger.error('error in pipeWritableStream', error)
             }
             this.lazyPipeWritableStream(retryCount + 1)
         }

lib/client/grpc-writable-stream-builder.js

@@ -9,6 +9,7 @@
 const { logError } = require('./grpc-errors')
 const ExponentialBackoffRetryBuilder = require('./exponential-backoff-retry-builder')
 const log = require('../utils/log/logger')
+const { LogBuilder } = require('../utils/log/log-builder')
 
 class GrpcWritableStream {
     constructor(makeWritableStream) {
@@ -21,6 +22,7 @@ class GrpcWritableStream {
         }).setRetryCallback(() => {
             this.connect()
         }).build()
+        this.logger = log.getLogger(LogBuilder.buildGrpcLog())
     }
 
     connect() {
@@ -43,7 +45,7 @@ class GrpcWritableStream {
 
                 if (error) {
                     if (error.code === 13) {
-                        log.warn('Warning: Collector returned 13 INTERNAL error. Too much Span data may be sent. Try increasing PINPOINT_SAMPLING_RATE to reduce traffic. https://github.com/pinpoint-apm/pinpoint-node-agent/issues/317')
+                        this.logger.warn('Warning: Collector returned 13 INTERNAL error. Too much Span data may be sent. Try increasing PINPOINT_SAMPLING_RATE to reduce traffic. https://github.com/pinpoint-apm/pinpoint-node-agent/issues/317')
                     }
                     logError('clientService callback in GrpcWritableStreamBuilder', error)
                     this.backoffRetry.retry()

lib/utils/log/log-builder.js

@@ -53,6 +53,10 @@ class Log {
 }
 
 class LogBuilder {
+    static buildGrpcLog() {
+        return new LogBuilder('grpcLogger').build()
+    }
+
     static createDefaultLogBuilder() {
         return new LogBuilder('default-logger')
     }
@@ -154,5 +158,6 @@ class LogBuilder {
 
 module.exports = {
     LogBuilder,
-    LogLevel
+    LogLevel,
+    Log
 }

lib/utils/log/logger.js

@@ -7,7 +7,7 @@
 'use strict'
 
 const loglevel = require('loglevel')
-const { LogBuilder, LogLevel: Level } = require('./log-builder')
+const { LogBuilder, LogLevel: Level, Log } = require('./log-builder')
 
 class Logging {
   constructor(loglevel, log) {
@@ -105,11 +105,15 @@ class Logger extends Logging {
   }
 
   getLogger(log) {
-    if (typeof log?.getName !== 'function') {
+    if (!(log instanceof Log) && typeof log !== 'string') {
       return this
     }
 
-    const logName = log.getName()
+    if (typeof log === 'string' && !this.loggers.has(log)) {
+      return this
+    }
+
+    const logName = log.getName?.() ?? (typeof log === 'string' ? log : LogBuilder.createDefaultLogBuilder().build().getName())
     if (!this.loggers.has(logName)) {
       this.loggers.set(logName, new ChildLogger(this.loglevel.getLogger(logName), log))
     }

test/utils/log/logger.test.js

@@ -474,4 +474,57 @@ test('PINPOINT_LOGGER_LEVELS environment variable log levels', (t) => {
     t.ok(noLevelAppenderMessages2[2].includes('NO-LEVEL-APPENDER2 INFO: info message'), 'NO-LEVEL appender 2 should receive info message from grpc logger')
     t.ok(noLevelAppenderMessages2[3].includes('NO-LEVEL-APPENDER2 WARN: warn message'), 'NO-LEVEL appender 2 should receive warn message from grpc logger')
     t.ok(noLevelAppenderMessages2[4].includes('NO-LEVEL-APPENDER2 ERROR: error message'), 'NO-LEVEL appender 2 should receive error message from grpc logger')
+})
+
+test('getLogger with string parameter should return existing logger', (t) => {
+    t.plan(4)
+
+    // Create a logger with LogBuilder first
+    const logName = 'test-string-logger'
+    const originalLogger = log.getLogger(new LogBuilder(logName).logLevelDebug().build())
+
+    // Get logger with string parameter - should return the existing logger
+    const stringLogger = log.getLogger(logName)
+
+    t.equal(stringLogger, originalLogger, 'getLogger with string should return the same instance')
+    t.equal(stringLogger.name, logName, 'Logger name should match')
+
+    // Test with another logger to ensure it works for multiple loggers
+    const logName2 = 'test-string-logger-2'
+    const originalLogger2 = log.getLogger(new LogBuilder(logName2).logLevelInfo().build())
+    const stringLogger2 = log.getLogger(logName2)
+
+    t.equal(stringLogger2, originalLogger2, 'getLogger with string should return the same instance for second logger')
+    t.equal(stringLogger2.name, logName2, 'Second logger name should match')
+})
+
+test('getLogger with string parameter for non-existing logger', (t) => {
+    t.plan(2)
+
+    // Try to get a logger that doesn't exist with string parameter
+    const nonExistentLogName = 'non-existent-logger'
+    const logger = log.getLogger(nonExistentLogName)
+
+    t.ok(logger, 'Logger should be created even if it did not exist before')
+    t.equal(logger.name, 'default-logger', 'Logger should have default name since it was created without LogBuilder')
+})
+
+test('getLogger caching behavior with string and LogBuilder', (t) => {
+    t.plan(3)
+
+    const logName = 'cache-test-logger'
+
+    // First, get logger with string (non-existing)
+    const firstLogger = log.getLogger(logName)
+
+    // Then, get logger with LogBuilder with same name
+    const secondLogger = log.getLogger(new LogBuilder(logName).logLevelWarn().build())
+
+    // Then, get logger with string again
+    const thirdLogger = log.getLogger(logName)
+
+    // All should be the same instance due to caching
+    t.notEqual(firstLogger, secondLogger, 'Logger is different instances when no created with LogBuilder first')
+    t.equal(secondLogger, thirdLogger, 'Logger obtained again with string should be the same instance')
+    t.equal(firstLogger.name, 'default-logger', 'Logger is not created with LogBuilder first has default name')
 })