Improved logging

[aleclarson]

This provides improved logging, as requested by #325, #351, and #334 (comment).

Overview

• options.logLevel is a string used to silence unwanted logs
• options.log can be an object with {debug, verbose, info, warn, error} methods
• When options.log is a function, its arguments are (level, message)
• When options.log is undefined, the console methods are used by default
• When options.log is falsy (or options.silent is truthy), log messages are silenced
• Some log messages have been tweaked, and log levels attached
• The pool master now emits an 'error' event with the associated Error object

Log levels

The valid values for options.logLevel are based off winston, minus the silly level and custom levels.

• error: Logs for unrecoverable failures
• warn: Logs for recoverable failures (eg: configuration issues, performance, deprecated API calls)
• info: Logs for information that should be known, but not a warning or error
• verbose: Logs for information that can be useful, but is usually overkill
• debug: Logs useful for debugging

Log levels are assigned an integer representing their importance. This integer is used to silence logs whose log level has an integer of higher value. As an example, if options.logLevel equals verbose, only debug logs are silenced. Likewise, if options.logLevel equals error, only error logs are not silenced.

The default value of options.logLevel is info, but you could argue that debug is more appropriate so the end user can provide more context when something goes wrong.

I made my best guesses on which log level should be used for each log-worthy event. Let me know if the classification of any events should be changed.

• warn: Entering slow growth mode
• info: Exiting slow growth mode
• info: Creating a pool
• verbose: Draining a pool
• verbose: Removing a pool
• verbose: Removed server has no associated pool
• debug: Failed to drain a pool
• debug: Failed to drain all pools
• debug: Failed to close a connection properly
• debug: Error emitted by a connection
• debug: The server_status changefeed returned an error
• debug: Failed to fetch another copy of server_status

The debug events are always followed by an error event, which emits the stack trace.

'error' event

I added an error event to the PoolMaster. This allows the end user to do whatever they like with the Error object (as requested in #325). My use case for this is overriding Error.prepareStackTrace to preserve the callsite objects, listening to the error event, and logging the error as JSON for easier consumption by logging dashboards.

If you would like, I can separate this change into its own PR, but I think it's useful and harmless to anyone who doesn't need it.

[marshall007]

I don't see a strong need for options.logLevel. Virtually all logging implementations have mechanisms for controlling log level behavior upstream. Having any default value whatsoever for options.logLevel complicates things when you are providing a logging instance/function that you would expect to control that behavior.

Aside from that I think this is pretty fantastic.

[aleclarson]

@marshall007 Thanks for the feedback! I would argue that options.logLevel is useful when options.log is undefined or a function, providing easy filtering with only 13 lines of code. I think the best compromise is to make debug the default. Then anyone using a logging library won't be disturbed with setting options.logLevel for the rethinkdb constructor.

[aleclarson]

Small change: When options.log is a function, its arguments are now (level, message) instead of (message, level), but any log event listeners are still passed (message, level)

[neumino]

A few thoughts

• What would be the point of someone using logLevel = 'warn? They would know when a pool is entering slow growth mode, but never if it exists slow growth mode. These two messages should be at the same level no?
• Creating a pool and removing a pool should be at the same level. Adding a server to your cluster should be the same as removing one from your cluster. Or you won't be able to get understand what's the state of your cluster looking at logs
• The changeed returning an error or a missing server_status is a huge warn IMO

[neumino]

Overall the first 2 points are the main reason why I think it's a bit wonky to have warn/info for rethinkdbdash.

I think it's fine to move the draining messages to debug, but the other messages should all be at the same level.

[aleclarson]

Good points, @neumino!

Here's an updated list of log levels per message:

• warn: Entering slow growth mode
• warn: Exiting slow growth mode
• warn: The server_status changefeed returned an error
• warn: Failed to fetch another copy of server_status
• info: Creating a pool
• info: Removing a pool
• info: Removed server has no associated pool
• info: Failed to close a connection properly
• info: Error emitted by a connection
• debug: Draining a pool
• debug: Failed to drain a pool
• debug: Failed to drain all pools

The verbose log level has been removed.

[aleclarson]

@neumino Are there any blockers on getting this merged? Should I update the docs too?