Bristol 1.0

[TomFrost]

Bristol 1.0

The 1.0 release of Bristol is in the works, and will be a major breaking release with a focus on performance, flexibility, and configurability.

Shortcomings of 0.x

• One of the most important features of Bristol is the separation of formatter and target. This is wildly useful but not found in any other major logging library. However, some targets require control of their own formatting, and it's a common practice right now to use the JSON formatter and then call JSON.parse in the custom target to get access to the pure object data again. This is bad. See Pass the unformatted message(s) to the target #56.
• The configuration method written for Bristol was created at a time that chained methods were extremely popular. In modern times of 12-factor code and env var-based configuration, this is annoying and requires users to write significant code to translate traditional config by json or env vars into chained method calls. See Allow targets to be automatically added to default Bristol instance, configured by env vars #31, Allow Bristol to be configured entirely through an options object passed to the constructor #32, Allows targets to be configured by passing an options object, rather than using chained methods #33.
• Items that should be configurable, such as whether file/line number data is included, are not. See Can't omit the file path altogether #53.
• Very little consideration was put into the performance of the console logger, as logging to file was the gold standard when Bristol was written. In modern applications, logging to stdout is the standard, and console.log is a blocking operation.
• Bristol has a number of features such as global static and dynamic variables, field transforms, etc., that are useful, but underutilized and inconsistent.
• Bristol has incredibly fine-grained target content restrictions that, while nice, haven't been used by almost anyone I've talked to. Bristol should default to being lean and minimal, and these features can be added back only if users present a good consistent use case for them
• It's a growing trend to have some "global" variables follow threads of operation, such as the logs generated by a single user's request, but shouldn't be global to the target. The ways users handle this -- creating a new Bristol instance per-request, exposing a "facade" log method, or maintaining a set of data that has to be manually passed to every log call -- are cumbersome and sometimes perform poorly. See Child logger support #46.

Solutions in 1.0

• Like Cryptex, Bristol will be able to be fully configured through a set of environment variables when it's instantiated without any other configuration. A config object can be passed to the constructor as well if environment variables aren't ideal. The chained configuration will be going away for Bristol in general as well as for new targets post-instantiation.
• Bristol 1.0 will keep the concept of formatters and targets, but targets will be supplied both the formatted string as well as the original raw data object. Target plugins have an ethical responsibility to respect the formatted string if it's present, and if possible to do so.
• 1.0 will eliminate static and dynamic global variables, as well as transforms. All manipulations to be performed on log events between the time of the log call and the time they're written to the target will be handled by middleware, similar to express.js. Middleware will be functions with the signature fn({Object} logData, {Object} options = {}), where logData will contain the timestamp, severity, and any other data that Bristol attaches to log messages internally. Options can be specified when the middleware is attached. Middleware must operate synchronously (so that messages write to the target in order) and make their changes directly to the logData object.
• Middleware can be attached directly to the Bristol instance (affecting all targets) or to specific targets.
• Bristol instances can be "forked", producing an instance that one can attach middleware to without affecting the parent instance. Use case: For each new request to your API, fork your logger and run this line: logFork.use(logData => { logData.user = req.tokenData.user }). Pass your fork along to your request handler and now everything you log for that specific request gets tagged with the user that generated it. The fork will be garbage collected when the request is handled.
• Formatters are just middleware that return a string and run after all the other middleware.
• The excluding and onlyIncluding target configs will be removed, barring rampant complaints. No one restricts by anything but severities in real-world use cases.
• Assuming console.log is not ideal for prod loads as I suspect, I'd keep a console.log logger for dev where blocking is useful, but add a stdout logger for non-development environments.

Limiting scope

1.0 will be a breaking update, and I'd like to define its scope by changing only the things, like the above, that are either breaking changes or features that users absolutely must learn about (such as using a stdout target instead of console target). While we could all list gobs of additional features we want on top of 1.0, I'd prefer to keep the 1.0 project small and iterate through the non-breaking changes later.

I also intend for 1.0 to draw a firm line in what Bristol ships with by default. Targets that are generalized or universal to most users will be included in Bristol -- file, console, stdout for sure in 1.0, syslog makes sense, I could even see an argument for a generic HTTP target that POSTs JSON logs to a configured URL with configured headers. Targets that are specific to aggregator products or narrow platforms will be excluded from Bristol core (Loggly has already been removed from master, for example), but the readme will encourage folks to publish middleware and targets to npm with the prefix bristol-.

RFC?

Paging @MarkHerhold @Fluidbyte @jeffijoe @dandv for your thoughts, as each of you have communicated challenging use cases that I'm hoping to largely solve with the above. I already know it solves my own ;-).

[jeffijoe]

This is spot on. People understand middleware and is a generic way to solve a lot of use cases such as excluding and only including certain fields.

I have written 2 targets, one for Sentry and one for Stackdriver, and in both cases I had to provide my own formatter, so glad this is being changed.

Love the log forking, been doing it for a while by hacking internal state in Bristol.

I think we should remove the custom log level names, and instead add more builtin ones to cover a wider spectrum. For example, the custom levels makes it hard to translate between Bristol and whatever target system you are outputting to that uses something else. Also makes TS typings harder (but not impossible).

Looking forward to it! Icing on the cake would be official typings for TypeScript 😄

[TomFrost]

Thanks Jeff!

People understand middleware and is a generic way to solve a lot of use cases such as excluding and only including certain fields.

To be clear, exclude/onlyInclude were mechanisms of restricting which messages would be passed to a certain target, and my thoughts around middleware didn't include a mechanism to prevent a message from being logged entirely. Though it might be cool to have a symbol flag for that right on the log data... then you could do this from middleware: logData[Bristol.WRITE_TO_LOG] = false. The message would go the whole way through all the middleware, and each could flip that flag as they see fit. If it's false when it's time to call the target, the target doesn't get called.

I think we should remove the custom log level names, and instead add more builtin ones to cover a wider spectrum.

Hahaha this is exactly why the custom log level names exist :). When I first wrote Bristol, there was no agreement on what the log levels should be. Some argued that it should support all 7 syslog levels, others said that all those levels give logging too much friction on a team (because it blurs the line of which level to use for certain cases, and different engineers would choose different levels for the same type of message). Both are 100% valid use cases, so the levels became configurable similarly to how Winston works. This is used so heavily that I don't think we can get rid of it.

[ksafranski]

Just another vote for removing custom log levels and embracing the 7 Syslog Levels (of Hell). Custom log levels are an unnecessary source of bike shedding, they don't clear up dev confusion, they just make it worse at the level where Bristol operates. Levels like error, warning, etc are more than sufficient when working with log data, if there's a requirement or need to clarify what constitutes those types of logs it feels more like an application concern that can/should be abstracted.

[jeffijoe]

@TomFrost ah, didn't think about that, I didnt use those options so I assume they meant filtering the log data which is exactly what middleware would let you do. All good. :)

And about log levels, I echo @Fluidbyte in that it just opens up for further bikeshedding. "warning" and above are the ones that are used the most I think, and people tend to know when to use them. I think the Syslog levels, given it's more or less a standard, makes sense.

[TomFrost]

I could be swayed to make syslog levels the default, but removing customizability of the levels isn't an option. That would be a dealbreaker for many current users of Bristol. I'm ok with breaking changes when there's a simple migration path (meaning that most/all changes happen in bootstrapping and not in every log call throughout one's app), and I can build an argument about removing functionality that I've never seen any evidence anyone's ever used (excluding/onlyIncluding), but I know for certain that levels customization is heavily used and I can't leave those users hanging. It's also a feature of Winston and has enabled many users to cut over to Bristol without unbearable changes to their codebases.

Regarding bikeshedding though -- while I see the possibility for bikeshedding the levels, I've heard of and been a part of numerous bike shedding discussions about what's a warn and what's a notice, and what's a notice and what's an info. Which pales in comparison to the rampant bikeshedding around emergency/alert/critical/error. Bunyan skirts this entirely by using fatal/error/warn/info/debug/trace. I dropped fatal in Bristol because in some applications, whether or not an error is fatal can be dynamic. Ex: DB fails to connect, error. DB fails 3 times in a row, we force a crash.

The point is: You probably have a really strong opinion one way or the other. I can choose one and alienate a portion of Bristol's current userbase, or keep a heavily-used current feature and let everyone choose what's already working for them. I have to prioritize the userbase.

[jeffijoe]

That's totally fair, making syslog the default is reasonable I'd say.

[dandv]

Thanks @TomFrost for taking into account #53 and #56. Agree with keeping log levels configurable, even though in order to avoid the paradox of choice, I was happy to see there are standards such as syslog.

Please keep the README readable - I found it much easier to parse than Winston's (1, 2).

Other issues that drove me away from choosing Winston despite its popularity, and may fall into the 1.0 scope:

• hard to log Error objects
• complexity of configuring the timestamp format

[dandv]

Just wanted to bring one issue to your attention, @TomFrost, in case addressing it may lead to breaking changes: flushing logs before process.exit() (#55).

From winstonjs/winston#228:

Loosing logs, especially at end of process - where errors are most likely to occur - seems hazardous at the least.

[jeffijoe]

That is a good point @dandv - i think adding a dispose function that returns a promise when all loggers have been disposed (up to the target implementation to resolve a promise when it is done flushing)

I use this pattern often for graceful shutdown, like waiting for writes to complete.

[dandv]

Hey @TomFrost, how's it going towards 1.0? :)