Support configurable logging #380

lutovich · 2018-05-30T18:27:36Z

This PR makes driver able to log internal events to the configured logging destination. Produced log messages should give an insight into what operations are happening inside the driver. Logging level and destination can be configured for the driver in the config object:

const config = {
  logging: {
    level: 'info',
    logger: (level, message) => console.log(level + ' ' + message)
  }
};

const driver = neo4j.driver(
 'bolt://localhost',
  neo4j.auth.basic('neo4j', 'password'),
  config
);

Property level should be a string. Currently supported levels are: 'error', 'warn', 'info' and 'debug'. Levels have the following priorities:

error: 0
warn: 1
info: 2
debug: 3

and enabling a certain level also enables all levels with lower priorities.

Property logger should be a function that takes two arguments level: string and message: string. Log level can now be 'error', 'warn', 'info' or 'debug'. Function should not execute any blocking or long-running operations because it is often invoked on a hot path.

There exists a predefined logger implementation which outputs timestamp, log level and message. Example:

1527703465096 INFO Direct driver 0 created for server address localhost:7687

It is defined in the neo4j.logging object and can be used like this:

const config = {
  logger: neo4j.logging.console('info') // optional level parameter
};

const driver = neo4j.driver(
 'bolt://localhost',
  neo4j.auth.basic('neo4j', 'password'),
  config
);

Users of the driver should be able to plug in an existing logging framework like https://github.com/winstonjs/winston.

Also fixed double closing of connections in Driver#close() and added current timestamp to the RoutingTable#toString().

oskarhane

I think this is a very welcome feature that'll help with the quality of reported issues and more.

Just a few comments.

oskarhane · 2018-05-31T08:28:56Z

src/v1/internal/connector.js

@@ -348,7 +365,9 @@ class Connection {
      return;
    }

-    log('C', 'ACK_FAILURE');
+    if (this._log.isEnabled()) {


Are these .isEnabled() calls really needed?
They create some noise and makes it harder to read when most of these functions only have a single row of logic.

Wouldn't a noop logger just do nothing with the level calls anyway?

These checks prevent code from generating a message string when logging is disabled. For example:

this._log.debug(`${this} S: RECORD ${JSON.stringify(msg)}`);

will stringify a record and create a message string with this and record content even if this._log is a no-op logger. The isEnabled() check makes code not even allocate all those strings.

This is an optimization that might be relevant in the connection code because it is very hot. I did not use it in other places that are not performance-critical.

Does this make sense?

This makes sense, great!

oskarhane · 2018-05-31T08:29:49Z

src/v1/internal/logger.js

+   * Check if logger is enabled, i.e. it is not a no-op implementation.
+   * @return {boolean} <code>true</code> when logger is not a no-op, <code>false</code> otherwise.
+   */
+  isEnabled() {


See prev comment about this. Is this needed?

oskarhane · 2018-05-31T08:32:59Z

src/v1/driver.js

      this._pool.purgeAll();
+    } finally {


Why are these changes part of this PR?

I noticed a double-close of connections because of logging and decided to fix it in-place :)
Will move it to a different PR.

Extracted two separate commits - one for RoutingTable#toString() change and one about this Driver#close()

oskarhane · 2018-05-31T08:34:49Z

test/internal/connection-providers.test.js

@@ -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());


What if the logger argument isn't defined, does it break?

Yes, LoadBalancer tests in connection-providers.test.js break. This is expected, right?

Maybe. Or maybe a noop function could be the default value.
Otoh, these are internal stuff that can have breaking changes, so I guess this is totally fine.

oskarhane · 2018-05-31T08:35:03Z

test/internal/connector.test.js

@@ -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());


What if the logger argument isn't defined, does it break?

Yes, this test breaks. This is expected, right?

This commit makes driver able to log internal events to the configured logging destination. Produced log messages should give an insight into what operations are happening inside the driver. Logging destination can be configured for the driver in the config object: ``` const config = { logger: (level, message) => console.log(level + ' ' + message) }; const driver = neo4j.driver( 'bolt://localhost', neo4j.auth.basic('neo4j', 'password'), config ); ``` Property `logger` should be a function that takes two arguments `level: string` and `message: string`. Log level can now be 'error', 'warn', 'info' or 'debug'. Function should not execute any blocking or long-running operations because it is often invoked on a hot path. There exists a predefined logger implementation which outputs timestamp, log level and message. Example: ``` 1527703465096 INFO Direct driver 0 created for server address localhost:7687 ``` It is defined in the `neo4j.logger` object and can be used like this: ``` const config = { logger: neo4j.logger.console }; const driver = neo4j.driver( 'bolt://localhost', neo4j.auth.basic('neo4j', 'password'), config ); ``` Users of the driver should be able to plug in an existing logging framework like https://github.com/winstonjs/winston.

To include current timestamp. Expiration timestamp (based on TTL) can then be compared with the current timestamp in logs.

When closed, driver purges all connections from the connection pool and then closes all connections stored in an internal array of all alive connections. First step is needed to close all connections that are idle in the connection pool. Second step is needed to close all connections that are active and checked out of the connection pool. Note that list of all connections contains both idle and active connections. Driver used to purge the pool at the same time as going over the list of all connections. This made it close some idle connections twice. It did not cause any issues but resulted in a bit weird logging where `Connection.close()` operation was logged twice. This commit fixes the problem by making driver first purge the pool and then go over the list of all connections to close them.

ali-ince

What do you think about bringing a feature that makes log level configurable and filters messages based on the configured level?

I believe it will better align with other logging frameworks and also will have less internal overhead for unwanted log calls (compared to having the user implemented his own filtering logic).

Previous solution where only the logger function is configured had a potential drawback - all log messages needed to be constructed even when user is only interested in a certain log level. E.g. debug messages that stringify returned values had to be created even if user is only interested in 'info' level. This commit addresses the problem by making the log level configurable. Driver configuration now looks like: ``` const config = { logging: { level: 'debug', logger: (level, message) => console.log(level + ' ' + message) } }; const driver = neo4j.driver( 'bolt://localhost', neo4j.auth.basic('neo4j', 'password'), config ); ``` to enable logging of all currently supported log levels. Levels have priorities like: ``` error: 0 warn: 1 info: 2 debug: 3 ``` Enabling a certain level also enables logging of all levels with lower priorities. When 'info' is enabled, logger will output 'error', 'warn', 'info' but not 'debug'. Level configuration is optional, 'info' is the default value.

lutovich · 2018-06-07T13:30:18Z

@ali-ince this is definitely a valuable thing to have. Updated the PR with it.

lutovich requested review from oskarhane, zhenlineo and ali-ince May 30, 2018 18:27

lutovich force-pushed the 1.7-logging branch 2 times, most recently from 31afd2a to cd49682 Compare May 30, 2018 21:21

oskarhane reviewed May 31, 2018

View reviewed changes

lutovich added 3 commits June 1, 2018 19:17

Improve RoutingTable#toString()

46c36ff

To include current timestamp. Expiration timestamp (based on TTL) can then be compared with the current timestamp in logs.

lutovich force-pushed the 1.7-logging branch from cd49682 to 04caeac Compare June 1, 2018 17:17

ali-ince reviewed Jun 5, 2018

View reviewed changes

lutovich force-pushed the 1.7-logging branch from 3946d21 to 0a86183 Compare June 7, 2018 13:27

ali-ince approved these changes Jun 8, 2018

View reviewed changes

ali-ince merged commit f95f3c3 into neo4j:1.7 Jun 8, 2018

lutovich deleted the 1.7-logging branch June 8, 2018 12:46

lutovich mentioned this pull request Jun 11, 2018

Driver 1.5 and up eventually stops working when put under load #373

Closed

lutovich mentioned this pull request Sep 14, 2018

Debug queries #411

Closed

danielnitsche mentioned this pull request Nov 4, 2022

How to solve Neo4jError: read ECONNRESET #385

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Support configurable logging #380

Support configurable logging #380

lutovich commented May 30, 2018 •

edited

Loading

oskarhane left a comment

oskarhane May 31, 2018

lutovich Jun 1, 2018

oskarhane Jun 4, 2018

oskarhane May 31, 2018

oskarhane May 31, 2018

lutovich Jun 1, 2018

lutovich Jun 1, 2018

oskarhane Jun 4, 2018

oskarhane May 31, 2018

lutovich Jun 1, 2018 •

edited

Loading

oskarhane Jun 4, 2018

oskarhane May 31, 2018

lutovich Jun 1, 2018

ali-ince left a comment

lutovich commented Jun 7, 2018

Support configurable logging #380

Support configurable logging #380

Conversation

lutovich commented May 30, 2018 • edited Loading

oskarhane 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

lutovich Jun 1, 2018 • 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

ali-ince left a comment

Choose a reason for hiding this comment

lutovich commented Jun 7, 2018

lutovich commented May 30, 2018 •

edited

Loading

lutovich Jun 1, 2018 •

edited

Loading