Fix log message doesn't appearing correctly in the Bolt log.

The write and receive message functions were moved from the connection to the `response-handler` and `bolt-protocol`, but logs on the functions still creating the message using the `this`, but in the nnew context the value of `this` is not serialized as the connection id.

Since the connection id data is dynamic and the depends on a response from the server, the issue was solved decorating the logger function to add connection context information.

Author: bigmontz

bolt-connection/src/bolt/bolt-protocol-v1.js

@@ -334,7 +334,7 @@ export default class BoltProtocol {
 
     if (queued) {
       if (this._log.isDebugEnabled()) {
-        this._log.debug(`${this} C: ${message}`)
+        this._log.debug(`C: ${message}`)
       }
 
       this.packer().packStruct(

bolt-connection/src/bolt/response-handler.js

@@ -92,13 +92,13 @@ export default class ResponseHandler {
     switch (msg.signature) {
       case RECORD:
         if (this._log.isDebugEnabled()) {
-          this._log.debug(`${this} S: RECORD ${json.stringify(msg)}`)
+          this._log.debug(`S: RECORD ${json.stringify(msg)}`)
         }
         this._currentObserver.onNext(payload)
         break
       case SUCCESS:
         if (this._log.isDebugEnabled()) {
-          this._log.debug(`${this} S: SUCCESS ${json.stringify(msg)}`)
+          this._log.debug(`S: SUCCESS ${json.stringify(msg)}`)
         }
         try {
           const metadata = this._transformMetadata(payload)
@@ -109,7 +109,7 @@ export default class ResponseHandler {
         break
       case FAILURE:
         if (this._log.isDebugEnabled()) {
-          this._log.debug(`${this} S: FAILURE ${json.stringify(msg)}`)
+          this._log.debug(`S: FAILURE ${json.stringify(msg)}`)
         }
         try {
           const error = newError(payload.message, payload.code)
@@ -125,7 +125,7 @@ export default class ResponseHandler {
         break
       case IGNORED:
         if (this._log.isDebugEnabled()) {
-          this._log.debug(`${this} S: IGNORED ${json.stringify(msg)}`)
+          this._log.debug(`S: IGNORED ${json.stringify(msg)}`)
         }
         try {
           if (this._currentFailure && this._currentObserver.onError) {

bolt-connection/src/connection/connection-channel.js

@@ -18,11 +18,14 @@
  */
 
 import { Chunker, Dechunker, ChannelConfig, Channel } from '../channel'
-import { newError, error, json } from 'neo4j-driver-core'
+import { newError, error, json, internal } from 'neo4j-driver-core'
 import Connection from './connection'
 import Bolt from '../bolt'
 
 const { PROTOCOL_ERROR } = error
+const {
+  logger: { Logger }
+} = internal
 
 let idGenerator = 0
 
@@ -57,15 +60,14 @@ export function createChannelConnection (
       const createProtocol = conn =>
         Bolt.create({
           version,
-          connection: conn,
           channel,
           chunker,
           dechunker,
           disableLosslessIntegers: config.disableLosslessIntegers,
           useBigInt: config.useBigInt,
           serversideRouting,
           server: conn.server,
-          log,
+          log: conn.logger,
           observer: {
             onError: conn._handleFatalError.bind(conn),
             onFailure: conn._resetOnFailure.bind(conn),
@@ -97,7 +99,6 @@ export function createChannelConnection (
       })
     )
 }
-
 export default class ChannelConnection extends Connection {
   /**
    * @constructor
@@ -128,7 +129,7 @@ export default class ChannelConnection extends Connection {
     this._disableLosslessIntegers = disableLosslessIntegers
     this._ch = channel
     this._chunker = chunker
-    this._log = log
+    this._log = createConnectionLogger(this, log)
     this._serversideRouting = serversideRouting
 
     // connection from the database, returned in response for HELLO message and might not be available
@@ -145,7 +146,7 @@ export default class ChannelConnection extends Connection {
     this._isBroken = false
 
     if (this._log.isDebugEnabled()) {
-      this._log.debug(`${this} created towards ${address}`)
+      this._log.debug(`created towards ${address}`)
     }
   }
 
@@ -234,6 +235,10 @@ export default class ChannelConnection extends Connection {
     return this._server
   }
 
+  get logger () {
+    return this._log
+  }
+
   /**
    * "Fatal" means the connection is dead. Only call this if something
    * happens that cannot be recovered from. This will lead to all subscribers
@@ -247,7 +252,7 @@ export default class ChannelConnection extends Connection {
 
     if (this._log.isErrorEnabled()) {
       this._log.error(
-        `${this} experienced a fatal error ${json.stringify(this._error)}`
+        `experienced a fatal error ${json.stringify(this._error)}`
       )
     }
 
@@ -322,7 +327,7 @@ export default class ChannelConnection extends Connection {
    */
   async close () {
     if (this._log.isDebugEnabled()) {
-      this._log.debug(`${this} closing`)
+      this._log.debug('closing')
     }
 
     if (this._protocol && this.isOpen()) {
@@ -334,7 +339,7 @@ export default class ChannelConnection extends Connection {
     await this._ch.close()
 
     if (this._log.isDebugEnabled()) {
-      this._log.debug(`${this} closed`)
+      this._log.debug('closed')
     }
   }
 
@@ -350,3 +355,15 @@ export default class ChannelConnection extends Connection {
     return error
   }
 }
+
+/**
+ * Creates a log with the connection info as prefix
+ * @param {Connection} connection The connection
+ * @param {Logger} logger The logger
+ * @returns {Logger} The new logger with enriched messages
+ */
+function createConnectionLogger (connection, logger) {
+  return new Logger(logger._level, (level, message) =>
+    logger._loggerFunction(level, `${connection} ${message}`)
+  )
+}

test/internal/connection-channel.test.js

@@ -543,13 +543,19 @@ describe('#integration ChannelConnection', () => {
   /**
    * @return {Promise<Connection>}
    */
-  function createConnection (url, config, errorCode = null) {
+  function createConnection (
+    url,
+    config,
+    errorCode = null,
+    logger = createVerifyConnectionIdLogger()
+  ) {
     const _config = config || {}
+    connection = undefined
     return createChannelConnection(
       ServerAddress.fromUrl(url),
       _config,
       new ConnectionErrorHandler(errorCode || SERVICE_UNAVAILABLE),
-      Logger.noOp()
+      logger
     ).then(c => {
       connection = c
       return connection
@@ -563,4 +569,22 @@ describe('#integration ChannelConnection', () => {
       originalWrite(message, observer, flush)
     }
   }
+
+  function createVerifyConnectionIdLogger () {
+    return new Logger('debug', (_, message) => {
+      if (!connection) {
+        // the connection is not the context, so we could
+        // only assert if it starts with Connection [
+        expect(
+          message.startsWith('Connection ['),
+          `Log message "${message}" should starts with "Connection ["`
+        ).toBe(true)
+        return
+      }
+      expect(
+        message.startsWith(`${connection}`),
+        `Log message "${message}" should starts with "${connection}"`
+      ).toBe(true)
+    })
+  }
 })