diff --git a/src/v1/driver.js b/src/v1/driver.js index b52daa797..75566a0dc 100644 --- a/src/v1/driver.js +++ b/src/v1/driver.js @@ -26,6 +26,7 @@ import {DirectConnectionProvider} from './internal/connection-providers'; import Bookmark from './internal/bookmark'; import ConnectivityVerifier from './internal/connectivity-verifier'; import PoolConfig, {DEFAULT_ACQUISITION_TIMEOUT, DEFAULT_MAX_SIZE} from './internal/pool-config'; +import Logger from './internal/logger'; const DEFAULT_MAX_CONNECTION_LIFETIME = 60 * 60 * 1000; // 1 hour @@ -43,6 +44,8 @@ const READ = 'READ'; */ const WRITE = 'WRITE'; +let idGenerator = 0; + /** * A driver maintains one or more {@link Session}s with a remote * Neo4j instance. Through the {@link Session}s you can send statements @@ -66,17 +69,19 @@ class Driver { constructor(hostPort, userAgent, token = {}, config = {}) { sanitizeConfig(config); + this._id = idGenerator++; this._hostPort = hostPort; this._userAgent = userAgent; - this._openSessions = {}; - this._sessionIdGenerator = 0; + this._openConnections = {}; this._token = token; this._config = config; + this._log = Logger.create(config); this._pool = new Pool( this._createConnection.bind(this), this._destroyConnection.bind(this), this._validateConnection.bind(this), - PoolConfig.fromDriverConfig(config) + PoolConfig.fromDriverConfig(config), + this._log ); /** @@ -87,6 +92,15 @@ class Driver { this._connectionProvider = null; this._onCompleted = null; + + this._afterConstruction(); + } + + /** + * @protected + */ + _afterConstruction() { + this._log.info(`Direct driver ${this._id} created for server address ${this._hostPort}`); } /** @@ -118,14 +132,12 @@ class Driver { * @access private */ _createConnection(hostPort, release) { - let sessionId = this._sessionIdGenerator++; - let conn = connect(hostPort, this._config, this._connectionErrorCode()); + let conn = connect(hostPort, this._config, this._connectionErrorCode(), this._log); let streamObserver = new _ConnectionStreamObserver(this, conn); conn.initialize(this._userAgent, this._token, streamObserver); - conn._id = sessionId; conn._release = () => release(hostPort, conn); - this._openSessions[sessionId] = conn; + this._openConnections[conn.id] = conn; return conn; } @@ -145,12 +157,12 @@ class Driver { } /** - * Dispose of a live session, closing any associated resources. - * @return {Session} new session. + * Dispose of a connection. + * @return {Connection} the connection to dispose. * @access private */ _destroyConnection(conn) { - delete this._openSessions[conn._id]; + delete this._openConnections[conn.id]; conn.close(); } @@ -224,11 +236,19 @@ class Driver { * @return undefined */ close() { - for (let sessionId in this._openSessions) { - if (this._openSessions.hasOwnProperty(sessionId)) { - this._openSessions[sessionId].close(); - } + this._log.info(`Driver ${this._id} closing`); + + try { + // purge all idle connections in the connection pool this._pool.purgeAll(); + } finally { + // then close all connections driver has ever created + // it is needed to close connections that are active right now and are acquired from the pool + for (let connectionId in this._openConnections) { + if (this._openConnections.hasOwnProperty(connectionId)) { + this._openConnections[connectionId].close(); + } + } } } } diff --git a/src/v1/index.js b/src/v1/index.js index 69248e2e0..f6a79564d 100644 --- a/src/v1/index.js +++ b/src/v1/index.js @@ -68,6 +68,20 @@ const auth = { }; const USER_AGENT = "neo4j-javascript/" + VERSION; +/** + * Object containing predefined logging configurations. These are expected to be used as values of the driver config's logging property. + * @property {function(level: ?string): object} console the function to create a logging config that prints all messages to console.log with + * timestamp, level and message. It takes an optional level parameter which represents the maximum log level to be logged. Default value is 'info'. + */ +const logging = { + console: level => { + return { + level: level, + logger: (level, message) => console.log(`${global.Date.now()} ${level.toUpperCase()} ${message}`) + }; + } +}; + /** * Construct a new Neo4j Driver. This is your main entry point for this * library. @@ -172,6 +186,22 @@ const USER_AGENT = "neo4j-javascript/" + VERSION; * // Default value for this option is false because native JavaScript numbers might result * // in loss of precision in the general case. * disableLosslessIntegers: false, + * + * // Specify the logging configuration for the driver. Object should have two properties level and logger. + * // + * // Property level represents the logging level which should be one of: 'error', 'warn', 'info' or 'debug'. This property is optional and + * // its default value is 'info'. Levels have priorities: 'error': 0, 'warn': 1, 'info': 2, 'debug': 3. Enabling a certain level also enables all + * // levels with lower priority. For example: 'error', 'warn' and 'info' will be logged when 'info' level is configured. + * // + * // Property logger represents the logging function which will be invoked for every log call with an acceptable level. The function should + * // take two string arguments level and message. The function should not execute any blocking or long-running operations + * // because it is often executed on a hot path. + * // + * // No logging is done by default. See neo4j.logging object that contains predefined logging implementations. + * logging: { + * level: 'info', + * logger: (level, message) => console.log(level + ' ' + message) + * }, * } * * @param {string} url The URL for the Neo4j database, for instance "bolt://localhost" @@ -280,6 +310,7 @@ const forExport = { integer, Neo4jError, auth, + logging, types, session, error, @@ -301,6 +332,7 @@ export { integer, Neo4jError, auth, + logging, types, session, error, diff --git a/src/v1/internal/ch-node.js b/src/v1/internal/ch-node.js index d84af1f23..aa403b5c9 100644 --- a/src/v1/internal/ch-node.js +++ b/src/v1/internal/ch-node.js @@ -372,7 +372,6 @@ class NodeChannel { if( this._pending !== null ) { this._pending.push( buffer ); } else if( buffer instanceof NodeBuffer ) { - // console.log( "[Conn#"+this.id+"] SEND: ", buffer.toString() ); this._conn.write( buffer._buffer ); } else { throw newError( "Don't know how to write: " + buffer ); diff --git a/src/v1/internal/connection-providers.js b/src/v1/internal/connection-providers.js index 8acbaee29..ca74b53c4 100644 --- a/src/v1/internal/connection-providers.js +++ b/src/v1/internal/connection-providers.js @@ -60,7 +60,7 @@ export class DirectConnectionProvider extends ConnectionProvider { export class LoadBalancer extends ConnectionProvider { - constructor(hostPort, routingContext, connectionPool, loadBalancingStrategy, driverOnErrorCallback) { + constructor(hostPort, routingContext, connectionPool, loadBalancingStrategy, driverOnErrorCallback, log) { super(); this._seedRouter = hostPort; this._routingTable = new RoutingTable([this._seedRouter]); @@ -69,6 +69,7 @@ export class LoadBalancer extends ConnectionProvider { this._driverOnErrorCallback = driverOnErrorCallback; this._hostNameResolver = LoadBalancer._createHostNameResolver(); this._loadBalancingStrategy = loadBalancingStrategy; + this._log = log; this._useSeedRouter = false; } @@ -111,6 +112,7 @@ export class LoadBalancer extends ConnectionProvider { if (!currentRoutingTable.isStaleFor(accessMode)) { return Promise.resolve(currentRoutingTable); } + this._log.info(`Routing table is stale for ${accessMode}: ${currentRoutingTable}`); return this._refreshRoutingTable(currentRoutingTable); } @@ -235,6 +237,7 @@ export class LoadBalancer extends ConnectionProvider { // make this driver instance aware of the new table this._routingTable = newRoutingTable; + this._log.info(`Updated routing table ${newRoutingTable}`); } static _forgetRouter(routingTable, routersArray, routerIndex) { diff --git a/src/v1/internal/connector.js b/src/v1/internal/connector.js index 79ee9b5d9..f81234573 100644 --- a/src/v1/internal/connector.js +++ b/src/v1/internal/connector.js @@ -27,6 +27,7 @@ import ChannelConfig from './ch-config'; import urlUtil from './url-util'; import StreamObserver from './stream-observer'; import {ServerVersion, VERSION_3_2_0} from './server-version'; +import Logger from './logger'; let Channel; if( NodeChannel.available ) { @@ -54,22 +55,7 @@ IGNORED = 0x7E, // 0111 1110 // IGNORED FAILURE = 0x7F, // 0111 1111 // FAILURE //sent before version negotiation -MAGIC_PREAMBLE = 0x6060B017, -DEBUG = false; - -/** - * Very rudimentary log handling, should probably be replaced by something proper at some point. - * @param actor the part that sent the message, 'S' for server and 'C' for client - * @param msg the bolt message - */ -function log(actor, msg) { - if (DEBUG) { - for(var i = 2; i < arguments.length; i++) { - msg += " " + JSON.stringify(arguments[i]); - } - console.log(actor + ":" + msg); - } -} +MAGIC_PREAMBLE = 0x6060B017; function NO_OP(){} @@ -79,6 +65,8 @@ let NO_OP_OBSERVER = { onError : NO_OP }; +let idGenerator = 0; + /** * A connection manages sending and receiving messages over a channel. A * connector is very closely tied to the Bolt protocol, it implements the @@ -98,14 +86,11 @@ class Connection { * @constructor * @param {NodeChannel|WebSocketChannel} channel - channel with a 'write' function and a 'onmessage' callback property. * @param {string} hostPort - the hostname and port to connect to. + * @param {Logger} log - the configured logger. * @param {boolean} disableLosslessIntegers if this connection should convert all received integers to native JS numbers. */ - constructor(channel, hostPort, disableLosslessIntegers = false) { - /** - * An ordered queue of observers, each exchange response (zero or more - * RECORD messages followed by a SUCCESS message) we receive will be routed - * to the next pending observer. - */ + constructor(channel, hostPort, log, disableLosslessIntegers = false) { + this.id = idGenerator++; this.hostPort = hostPort; this.server = {address: hostPort}; this.creationTimestamp = Date.now(); @@ -115,6 +100,7 @@ class Connection { this._ch = channel; this._dechunker = new Dechunker(); this._chunker = new Chunker( channel ); + this._log = log; // initially assume that database supports latest Bolt version, create latest packer and unpacker this._packer = packStreamUtil.createLatestPacker(this._chunker); @@ -159,6 +145,10 @@ class Connection { this._handleMessage(this._unpacker.unpack(buf)); }; + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} created towards ${hostPort}`); + } + let handshake = alloc( 5 * 4 ); //magic preamble handshake.writeInt32( MAGIC_PREAMBLE ); @@ -178,6 +168,10 @@ class Connection { * @private */ _initializeProtocol(version, buffer) { + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} negotiated protocol version ${version}`); + } + // re-create packer and unpacker because version might be lower than we initially assumed this._packer = packStreamUtil.createPackerForProtocolVersion(version, this._chunker); this._unpacker = packStreamUtil.createUnpackerForProtocolVersion(version, this._disableLosslessIntegers); @@ -201,6 +195,11 @@ class Connection { _handleFatalError( err ) { this._isBroken = true; this._error = err; + + if (this._log.isErrorEnabled()) { + this._log.error(`${this} experienced a fatal error ${JSON.stringify(err)}`); + } + if( this._currentObserver && this._currentObserver.onError ) { this._currentObserver.onError(err); } @@ -223,11 +222,15 @@ class Connection { switch( msg.signature ) { case RECORD: - log("S", "RECORD", msg); + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} S: RECORD ${JSON.stringify(msg)}`); + } this._currentObserver.onNext( payload ); break; case SUCCESS: - log("S", "SUCCESS", msg); + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} S: SUCCESS ${JSON.stringify(msg)}`); + } try { this._currentObserver.onCompleted( payload ); } finally { @@ -235,7 +238,9 @@ class Connection { } break; case FAILURE: - log("S", "FAILURE", msg); + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} S: FAILURE ${JSON.stringify(msg)}`); + } try { this._currentFailure = newError(payload.message, payload.code); this._currentObserver.onError( this._currentFailure ); @@ -246,7 +251,9 @@ class Connection { } break; case IGNORED: - log("S", "IGNORED", msg); + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} S: IGNORED ${JSON.stringify(msg)}`); + } try { if (this._currentFailure && this._currentObserver.onError) this._currentObserver.onError(this._currentFailure); @@ -263,7 +270,9 @@ class Connection { /** Queue an INIT-message to be sent to the database */ initialize( clientName, token, observer ) { - log("C", "INIT", clientName, token); + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} C: INIT ${clientName} ${JSON.stringify(token)}`); + } const initObserver = this._state.wrap(observer); const queued = this._queueObserver(initObserver); if (queued) { @@ -276,7 +285,9 @@ class Connection { /** Queue a RUN-message to be sent to the database */ run( statement, params, observer ) { - log("C", "RUN", statement, params); + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} C: RUN ${statement} ${JSON.stringify(params)}`); + } const queued = this._queueObserver(observer); if (queued) { this._packer.packStruct(RUN, [this._packable(statement), this._packable(params)], @@ -287,7 +298,9 @@ class Connection { /** Queue a PULL_ALL-message to be sent to the database */ pullAll( observer ) { - log("C", "PULL_ALL"); + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} C: PULL_ALL`); + } const queued = this._queueObserver(observer); if (queued) { this._packer.packStruct(PULL_ALL, [], (err) => this._handleFatalError(err)); @@ -297,7 +310,9 @@ class Connection { /** Queue a DISCARD_ALL-message to be sent to the database */ discardAll( observer ) { - log("C", "DISCARD_ALL"); + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} C: DISCARD_ALL`); + } const queued = this._queueObserver(observer); if (queued) { this._packer.packStruct(DISCARD_ALL, [], (err) => this._handleFatalError(err)); @@ -311,7 +326,9 @@ class Connection { * @return {Promise} promise resolved when SUCCESS-message response arrives, or failed when other response messages arrives. */ resetAndFlush() { - log('C', 'RESET'); + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} C: RESET`); + } this._ackFailureMuted = true; return new Promise((resolve, reject) => { @@ -348,7 +365,9 @@ class Connection { return; } - log('C', 'ACK_FAILURE'); + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} C: ACK_FAILURE`); + } const observer = { onNext: record => { @@ -429,9 +448,16 @@ class Connection { * @param {function} cb - Function to call on close. */ close(cb) { + if (this._log.isDebugEnabled()) { + this._log.debug(`${this} closing`); + } this._ch.close(cb); } + toString() { + return `Connection ${this.id}`; + } + _packable(value) { return this._packer.packable(value, (err) => this._handleFatalError(err)); } @@ -553,13 +579,14 @@ class ConnectionState { * @param {string} hostPort - the Bolt endpoint to connect to * @param {object} config - this driver configuration * @param {string=null} connectionErrorCode - error code for errors raised on connection errors + * @param {Logger} log - configured logger * @return {Connection} - New connection */ -function connect(hostPort, config = {}, connectionErrorCode = null) { +function connect(hostPort, config = {}, connectionErrorCode = null, log = Logger.noOp()) { const Ch = config.channel || Channel; const parsedAddress = urlUtil.parseDatabaseUrl(hostPort); const channelConfig = new ChannelConfig(parsedAddress, config, connectionErrorCode); - return new Connection(new Ch(channelConfig), parsedAddress.hostAndPort, config.disableLosslessIntegers); + return new Connection(new Ch(channelConfig), parsedAddress.hostAndPort, log, config.disableLosslessIntegers); } export { diff --git a/src/v1/internal/logger.js b/src/v1/internal/logger.js new file mode 100644 index 000000000..b1c48a6e5 --- /dev/null +++ b/src/v1/internal/logger.js @@ -0,0 +1,225 @@ +/** + * Copyright (c) 2002-2018 "Neo4j," + * Neo4j Sweden AB [http://neo4j.com] + * + * This file is part of Neo4j. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +import {newError} from '../error'; + +const ERROR = 'error'; +const WARN = 'warn'; +const INFO = 'info'; +const DEBUG = 'debug'; + +const DEFAULT_LEVEL = INFO; + +const levels = { + [ERROR]: 0, + [WARN]: 1, + [INFO]: 2, + [DEBUG]: 3 +}; + +/** + * Logger used by the driver to notify about various internal events. Single logger should be used per driver. + */ +class Logger { + + /** + * @constructor + * @param {string} level the enabled logging level. + * @param {function(level: string, message: string)} loggerFunction the function to write the log level and message. + */ + constructor(level, loggerFunction) { + this._level = level; + this._loggerFunction = loggerFunction; + } + + /** + * Create a new logger based on the given driver configuration. + * @param {object} driverConfig the driver configuration as supplied by the user. + * @return {Logger} a new logger instance or a no-op logger when not configured. + */ + static create(driverConfig) { + if (driverConfig && driverConfig.logging) { + const loggingConfig = driverConfig.logging; + const level = extractConfiguredLevel(loggingConfig); + const loggerFunction = extractConfiguredLogger(loggingConfig); + return new Logger(level, loggerFunction); + } + return this.noOp(); + } + + /** + * Create a no-op logger implementation. + * @return {Logger} the no-op logger implementation. + */ + static noOp() { + return noOpLogger; + } + + /** + * Check if error logging is enabled, i.e. it is not a no-op implementation. + * @return {boolean} true when enabled, false otherwise. + */ + isErrorEnabled() { + return isLevelEnabled(this._level, ERROR); + } + + /** + * Log an error message. + * @param {string} message the message to log. + */ + error(message) { + if (this.isErrorEnabled()) { + this._loggerFunction(ERROR, message); + } + } + + /** + * Check if warn logging is enabled, i.e. it is not a no-op implementation. + * @return {boolean} true when enabled, false otherwise. + */ + isWarnEnabled() { + return isLevelEnabled(this._level, WARN); + } + + /** + * Log an warning message. + * @param {string} message the message to log. + */ + warn(message) { + if (this.isWarnEnabled()) { + this._loggerFunction(WARN, message); + } + } + + /** + * Check if info logging is enabled, i.e. it is not a no-op implementation. + * @return {boolean} true when enabled, false otherwise. + */ + isInfoEnabled() { + return isLevelEnabled(this._level, INFO); + } + + /** + * Log an info message. + * @param {string} message the message to log. + */ + info(message) { + if (this.isInfoEnabled()) { + this._loggerFunction(INFO, message); + } + } + + /** + * Check if debug logging is enabled, i.e. it is not a no-op implementation. + * @return {boolean} true when enabled, false otherwise. + */ + isDebugEnabled() { + return isLevelEnabled(this._level, DEBUG); + } + + /** + * Log a debug message. + * @param {string} message the message to log. + */ + debug(message) { + if (this.isDebugEnabled()) { + this._loggerFunction(DEBUG, message); + } + } +} + +class NoOpLogger extends Logger { + + constructor() { + super(null, null); + } + + isErrorEnabled() { + return false; + } + + error(message) { + } + + isWarnEnabled() { + return false; + } + + warn(message) { + } + + isInfoEnabled() { + return false; + } + + info(message) { + } + + isDebugEnabled() { + return false; + } + + debug(message) { + } +} + +const noOpLogger = new NoOpLogger(); + +/** + * Check if the given logging level is enabled. + * @param {string} configuredLevel the configured level. + * @param {string} targetLevel the level to check. + * @return {boolean} value of true when enabled, false otherwise. + */ +function isLevelEnabled(configuredLevel, targetLevel) { + return levels[configuredLevel] >= levels[targetLevel]; +} + +/** + * Extract the configured logging level from the driver's logging configuration. + * @param {object} loggingConfig the logging configuration. + * @return {string} the configured log level or default when none configured. + */ +function extractConfiguredLevel(loggingConfig) { + if (loggingConfig && loggingConfig.level) { + const configuredLevel = loggingConfig.level; + const value = levels[configuredLevel]; + if (!value && value !== 0) { + throw newError(`Illegal logging level: ${configuredLevel}. Supported levels are: ${Object.keys(levels)}`); + } + return configuredLevel; + } + return DEFAULT_LEVEL; +} + +/** + * Extract the configured logger function from the driver's logging configuration. + * @param {object} loggingConfig the logging configuration. + * @return {function(level: string, message: string)} the configured logging function. + */ +function extractConfiguredLogger(loggingConfig) { + if (loggingConfig && loggingConfig.logger) { + const configuredLogger = loggingConfig.logger; + if (configuredLogger && typeof configuredLogger === 'function') { + return configuredLogger; + } + } + throw newError(`Illegal logger function: ${loggingConfig.logger}`); +} + +export default Logger; diff --git a/src/v1/internal/pool.js b/src/v1/internal/pool.js index 7155569da..aece79eec 100644 --- a/src/v1/internal/pool.js +++ b/src/v1/internal/pool.js @@ -19,6 +19,7 @@ import PoolConfig from './pool-config'; import {newError} from '../error'; +import Logger from './logger'; class Pool { /** @@ -31,8 +32,10 @@ class Pool { * when it is returned). If this returns false, the resource will * be evicted * @param {PoolConfig} config configuration for the new driver. + * @param {Logger} log the driver logger. */ - constructor(create, destroy = (() => true), validate = (() => true), config = PoolConfig.defaultConfig()) { + constructor(create, destroy = (() => true), validate = (() => true), config = PoolConfig.defaultConfig(), + log = Logger.noOp()) { this._create = create; this._destroy = destroy; this._validate = validate; @@ -42,6 +45,7 @@ class Pool { this._acquireRequests = {}; this._activeResourceCounts = {}; this._release = this._release.bind(this); + this._log = log; } /** @@ -54,7 +58,9 @@ class Pool { if (resource) { resourceAcquired(key, this._activeResourceCounts); - + if (this._log.isDebugEnabled()) { + this._log.debug(`${resource} acquired from the pool`); + } return Promise.resolve(resource); } @@ -73,7 +79,7 @@ class Pool { reject(newError(`Connection acquisition timed out in ${this._acquisitionTimeout} ms.`)); }, this._acquisitionTimeout); - request = new PendingRequest(resolve, timeoutId); + request = new PendingRequest(resolve, timeoutId, this._log); allRequests[key].push(request); }); } @@ -147,12 +153,21 @@ class Pool { if (pool) { // there exist idle connections for the given key if (!this._validate(resource)) { + if (this._log.isDebugEnabled()) { + this._log.debug(`${resource} destroyed and can't be released to the pool ${key} because it is not functional`); + } this._destroy(resource); } else { + if (this._log.isDebugEnabled()) { + this._log.debug(`${resource} released to the pool ${key}`); + } pool.push(resource); } } else { // key has been purged, don't put it back, just destroy the resource + if (this._log.isDebugEnabled()) { + this._log.debug(`${resource} destroyed and can't be released to the pool ${key} because pool has been purged`); + } this._destroy(resource); } resourceReleased(key, this._activeResourceCounts); @@ -205,13 +220,17 @@ function resourceReleased(key, activeResourceCounts) { class PendingRequest { - constructor(resolve, timeoutId) { + constructor(resolve, timeoutId, log) { this._resolve = resolve; this._timeoutId = timeoutId; + this._log = log; } resolve(resource) { clearTimeout(this._timeoutId); + if (this._log.isDebugEnabled()) { + this._log.debug(`${resource} acquired from the pool`); + } this._resolve(resource); } diff --git a/src/v1/internal/routing-table.js b/src/v1/internal/routing-table.js index 85cf56260..f39468ca5 100644 --- a/src/v1/internal/routing-table.js +++ b/src/v1/internal/routing-table.js @@ -74,6 +74,7 @@ export default class RoutingTable { toString() { return `RoutingTable[` + `expirationTime=${this.expirationTime}, ` + + `currentTime=${Date.now()}, ` + `routers=[${this.routers}], ` + `readers=[${this.readers}], ` + `writers=[${this.writers}]]`; diff --git a/src/v1/routing-driver.js b/src/v1/routing-driver.js index 703e2c7e4..159f05f4d 100644 --- a/src/v1/routing-driver.js +++ b/src/v1/routing-driver.js @@ -35,9 +35,13 @@ class RoutingDriver extends Driver { this._routingContext = routingContext; } + _afterConstruction() { + this._log.info(`Routing driver ${this._id} created for server address ${this._hostPort}`); + } + _createConnectionProvider(hostPort, connectionPool, driverOnErrorCallback) { const loadBalancingStrategy = RoutingDriver._createLoadBalancingStrategy(this._config, connectionPool); - return new LoadBalancer(hostPort, this._routingContext, connectionPool, loadBalancingStrategy, driverOnErrorCallback); + return new LoadBalancer(hostPort, this._routingContext, connectionPool, loadBalancingStrategy, driverOnErrorCallback, this._log); } _createSession(mode, connectionProvider, bookmark, config) { @@ -50,9 +54,11 @@ class RoutingDriver extends Driver { const hostPort = conn.hostPort; if (error.code === SESSION_EXPIRED || isDatabaseUnavailable(error)) { + this._log.warn(`Routing driver ${this._id} will forget ${hostPort} because of an error ${error.code} '${error.message}'`); this._connectionProvider.forget(hostPort); return error; } else if (isFailureToWrite(error)) { + this._log.warn(`Routing driver ${this._id} will forget writer ${hostPort} because of an error ${error.code} '${error.message}'`); this._connectionProvider.forgetWriter(hostPort); return newError('No longer possible to write to server at ' + hostPort, SESSION_EXPIRED); } else { diff --git a/test/internal/connection-providers.test.js b/test/internal/connection-providers.test.js index a39f75f19..32d42eb67 100644 --- a/test/internal/connection-providers.test.js +++ b/test/internal/connection-providers.test.js @@ -24,6 +24,7 @@ import RoutingTable from '../../src/v1/internal/routing-table'; import {DirectConnectionProvider, LoadBalancer} from '../../src/v1/internal/connection-providers'; import Pool from '../../src/v1/internal/pool'; import LeastConnectedLoadBalancingStrategy from '../../src/v1/internal/least-connected-load-balancing-strategy'; +import Logger from '../../src/v1/internal/logger'; const NO_OP_DRIVER_CALLBACK = () => { }; @@ -137,7 +138,7 @@ describe('LoadBalancer', () => { it('initializes routing table with the given router', () => { const connectionPool = newPool(); const loadBalancingStrategy = new LeastConnectedLoadBalancingStrategy(connectionPool); - const loadBalancer = new LoadBalancer('server-ABC', {}, connectionPool, loadBalancingStrategy, NO_OP_DRIVER_CALLBACK); + const loadBalancer = new LoadBalancer('server-ABC', {}, connectionPool, loadBalancingStrategy, NO_OP_DRIVER_CALLBACK, Logger.noOp()); expectRoutingTable(loadBalancer, ['server-ABC'], @@ -1073,7 +1074,7 @@ function newLoadBalancerWithSeedRouter(seedRouter, seedRouterResolved, connectionPool = null) { const pool = connectionPool || newPool(); const loadBalancingStrategy = new LeastConnectedLoadBalancingStrategy(pool); - const loadBalancer = new LoadBalancer(seedRouter, {}, pool, loadBalancingStrategy, NO_OP_DRIVER_CALLBACK); + const loadBalancer = new LoadBalancer(seedRouter, {}, pool, loadBalancingStrategy, NO_OP_DRIVER_CALLBACK, Logger.noOp()); loadBalancer._routingTable = new RoutingTable(routers, readers, writers, expirationTime); loadBalancer._rediscovery = new FakeRediscovery(routerToRoutingTable); loadBalancer._hostNameResolver = new FakeDnsResolver(seedRouterResolved); diff --git a/test/internal/connector.test.js b/test/internal/connector.test.js index c738f981b..075961b90 100644 --- a/test/internal/connector.test.js +++ b/test/internal/connector.test.js @@ -26,6 +26,7 @@ import {Neo4jError, newError} from '../../src/v1/error'; import sharedNeo4j from '../internal/shared-neo4j'; import {ServerVersion} from '../../src/v1/internal/server-version'; import lolex from 'lolex'; +import Logger from '../../src/v1/internal/logger'; const ILLEGAL_MESSAGE = {signature: 42, fields: []}; const SUCCESS_MESSAGE = {signature: 0x70, fields: [{}]}; @@ -140,7 +141,7 @@ describe('connector', () => { it('should convert failure messages to errors', done => { const channel = new DummyChannel.channel; - connection = new Connection(channel, 'bolt://localhost'); + connection = new Connection(channel, 'bolt://localhost', Logger.noOp()); const errorCode = 'Neo.ClientError.Schema.ConstraintValidationFailed'; const errorMessage = 'Node 0 already exists with label User and property "email"=[john@doe.com]'; diff --git a/test/internal/logger.test.js b/test/internal/logger.test.js new file mode 100644 index 000000000..01b032e17 --- /dev/null +++ b/test/internal/logger.test.js @@ -0,0 +1,184 @@ +/** + * Copyright (c) 2002-2018 "Neo4j," + * Neo4j Sweden AB [http://neo4j.com] + * + * This file is part of Neo4j. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import neo4j from '../../src/v1'; +import sharedNeo4j from '../../test/internal/shared-neo4j'; +import Logger from '../../src/v1/internal/logger'; + +describe('Logger', () => { + + let originalConsoleLog; + + beforeEach(() => { + originalConsoleLog = console.log; + }); + + afterEach(() => { + console.log = originalConsoleLog; + }); + + it('should create no-op logger when not configured', () => { + const log = Logger.create({logging: null}); + + log.error('Error! This should be a no-op'); + log.warn('Warn! This should be a no-op'); + log.info('Info! This should be a no-op'); + log.debug('Debug! This should be a no-op'); + + expect(log.isErrorEnabled()).toBeFalsy(); + expect(log.isWarnEnabled()).toBeFalsy(); + expect(log.isInfoEnabled()).toBeFalsy(); + expect(log.isDebugEnabled()).toBeFalsy(); + }); + + it('should create Logger when configured', () => { + const logged = []; + const log = memorizingLogger(logged); + + log.error('Error! One'); + log.warn('Warn! Two'); + log.info('Info! Three'); + log.debug('Debug! Four'); + + expect(log.isErrorEnabled()).toBeTruthy(); + expect(log.isWarnEnabled()).toBeTruthy(); + expect(log.isInfoEnabled()).toBeTruthy(); + expect(log.isDebugEnabled()).toBeTruthy(); + + expect(logged).toEqual([ + {level: 'error', message: 'Error! One'}, + {level: 'warn', message: 'Warn! Two'}, + {level: 'info', message: 'Info! Three'}, + {level: 'debug', message: 'Debug! Four'} + ]); + }); + + it('should log according to the configured log level', () => { + const logged = []; + const log = memorizingLogger(logged, 'warn'); + + log.error('Error! One'); + log.warn('Warn! Two'); + log.info('Info! Three'); + log.debug('Debug! Four'); + + expect(logged).toEqual([ + {level: 'error', message: 'Error! One'}, + {level: 'warn', message: 'Warn! Two'} + ]); + }); + + it('should log when logger configured in the driver', done => { + const logged = []; + const config = memorizingLoggerConfig(logged); + const driver = neo4j.driver('bolt://localhost', sharedNeo4j.authToken, config); + + const session = driver.session(); + session.run('RETURN 42') + .then(() => { + expect(logged.length).toBeGreaterThan(0); + + const seenLevels = logged.map(log => log.level); + const seenMessages = logged.map(log => log.message); + + // at least info and debug should've been used + expect(seenLevels).toContain('info'); + expect(seenLevels).toContain('debug'); + + // the executed statement should've been logged + const statementLogged = seenMessages.find(message => message.indexOf('RETURN 42') !== -1); + expect(statementLogged).toBeTruthy(); + }) + .catch(error => { + done.fail(error); + }) + .then(() => { + driver.close(); + done(); + }); + }); + + it('should log debug to console when configured in the driver', done => { + const logged = []; + console.log = message => logged.push(message); + const driver = neo4j.driver('bolt://localhost', sharedNeo4j.authToken, {logging: neo4j.logging.console('debug')}); + + const session = driver.session(); + session.run('RETURN 123456789') + .then(() => { + expect(logged.length).toBeGreaterThan(0); + + // the executed statement should've been logged + const statementLogged = logged.find(log => log.indexOf('DEBUG') !== -1 && log.indexOf('RETURN 123456789') !== -1); + expect(statementLogged).toBeTruthy(); + + // driver creation should've been logged because it is on info level + const driverCreationLogged = logged.find(log => log.indexOf('driver') !== -1 && log.indexOf('created') !== -1); + expect(driverCreationLogged).toBeTruthy(); + }) + .catch(error => { + done.fail(error); + }) + .then(() => { + driver.close(); + done(); + }); + }); + + it('should log info to console when configured in the driver', done => { + const logged = []; + console.log = message => logged.push(message); + const driver = neo4j.driver('bolt://localhost', sharedNeo4j.authToken, {logging: neo4j.logging.console()}); // info is the default level + + const session = driver.session(); + session.run('RETURN 123456789') + .then(() => { + expect(logged.length).toBeGreaterThan(0); + + // the executed statement should not be logged because it is in debug level + const statementLogged = logged.find(log => log.indexOf('RETURN 123456789') !== -1); + expect(statementLogged).toBeFalsy(); + + // driver creation should've been logged because it is on info level + const driverCreationLogged = logged.find(log => log.indexOf('driver') !== -1 && log.indexOf('created') !== -1); + expect(driverCreationLogged).toBeTruthy(); + }) + .catch(error => { + done.fail(error); + }) + .then(() => { + driver.close(); + done(); + }); + }); + +}); + +function memorizingLogger(logged, level = 'debug') { + return Logger.create(memorizingLoggerConfig(logged, level)); +} + +function memorizingLoggerConfig(logged, level = 'debug') { + return { + logging: { + level: level, + logger: (level, message) => logged.push({level, message}) + } + }; +} diff --git a/test/internal/routing-table.test.js b/test/internal/routing-table.test.js index 4ee875485..67d79bab5 100644 --- a/test/internal/routing-table.test.js +++ b/test/internal/routing-table.test.js @@ -169,8 +169,14 @@ describe('routing-table', () => { }); it('should have correct toString', () => { - const table = createTable([1, 2], [3, 4], [5, 6], 42); - expect(table.toString()).toEqual('RoutingTable[expirationTime=42, routers=[1,2], readers=[3,4], writers=[5,6]]'); + const originalDateNow = Date.now; + try { + Date.now = () => 4242; + const table = createTable([1, 2], [3, 4], [5, 6], 42); + expect(table.toString()).toEqual('RoutingTable[expirationTime=42, currentTime=4242, routers=[1,2], readers=[3,4], writers=[5,6]]'); + } finally { + Date.now = originalDateNow; + } }); function expired() { diff --git a/test/v1/driver.test.js b/test/v1/driver.test.js index a8902059e..6554b3ded 100644 --- a/test/v1/driver.test.js +++ b/test/v1/driver.test.js @@ -461,7 +461,7 @@ describe('driver', () => { } function openConnectionFrom(driver) { - return Array.from(Object.values(driver._openSessions)); + return Array.from(Object.values(driver._openConnections)); } }); diff --git a/test/v1/routing.driver.boltkit.test.js b/test/v1/routing.driver.boltkit.test.js index 0a238d164..9f9262b8b 100644 --- a/test/v1/routing.driver.boltkit.test.js +++ b/test/v1/routing.driver.boltkit.test.js @@ -2143,7 +2143,7 @@ describe('routing driver with stub server', () => { } function numberOfOpenConnections(driver) { - return Object.keys(driver._openSessions).length; + return Object.keys(driver._openConnections).length; } class MemorizingRoutingTable extends RoutingTable { diff --git a/types/v1/driver.d.ts b/types/v1/driver.d.ts index 6970d0cb3..2fdcd541f 100644 --- a/types/v1/driver.d.ts +++ b/types/v1/driver.d.ts @@ -40,6 +40,13 @@ declare type TrustStrategy = declare type LoadBalancingStrategy = "least_connected" | "round_robin"; +declare type LogLevel = "error" | "warn" | "info" | "debug"; + +declare interface LoggingConfig { + level?: LogLevel; + logger: (level: LogLevel, message: string) => void; +} + declare interface Config { encrypted?: boolean | EncryptionLevel; trust?: TrustStrategy; @@ -55,6 +62,7 @@ declare interface Config { maxConnectionLifetime?: number; connectionTimeout?: number; disableLosslessIntegers?: boolean; + logging?: LoggingConfig; } declare type SessionMode = "READ" | "WRITE";