From 077294af78a3e573ad712c12e2c3b7e0b04789d5 Mon Sep 17 00:00:00 2001 From: Antonio Barcelos Date: Fri, 11 Jun 2021 16:44:56 +0200 Subject: [PATCH] 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. --- bolt-connection/src/bolt/bolt-protocol-v1.js | 2 +- bolt-connection/src/bolt/response-handler.js | 8 ++--- .../src/connection/connection-channel.js | 35 ++++++++++++++----- test/internal/connection-channel.test.js | 28 +++++++++++++-- 4 files changed, 57 insertions(+), 16 deletions(-) diff --git a/bolt-connection/src/bolt/bolt-protocol-v1.js b/bolt-connection/src/bolt/bolt-protocol-v1.js index a5302ba63..53a03b1af 100644 --- a/bolt-connection/src/bolt/bolt-protocol-v1.js +++ b/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( diff --git a/bolt-connection/src/bolt/response-handler.js b/bolt-connection/src/bolt/response-handler.js index 6936c9fdb..15d65cfc3 100644 --- a/bolt-connection/src/bolt/response-handler.js +++ b/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) { diff --git a/bolt-connection/src/connection/connection-channel.js b/bolt-connection/src/connection/connection-channel.js index 2c026e535..95a08de5e 100644 --- a/bolt-connection/src/connection/connection-channel.js +++ b/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,7 +60,6 @@ export function createChannelConnection ( const createProtocol = conn => Bolt.create({ version, - connection: conn, channel, chunker, dechunker, @@ -65,7 +67,7 @@ export function createChannelConnection ( 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}`) + ) +} diff --git a/test/internal/connection-channel.test.js b/test/internal/connection-channel.test.js index a28d7d692..2327292a7 100644 --- a/test/internal/connection-channel.test.js +++ b/test/internal/connection-channel.test.js @@ -543,13 +543,19 @@ describe('#integration ChannelConnection', () => { /** * @return {Promise} */ - 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) + }) + } })