Post-mortem on a recent hapi logging adventure

[cjihrig]

Support plan

• which support plan is this issue covered by? (e.g. Community, Core, Plus, or Enterprise): community
• is this issue currently blocking your project? (yes/no): no
• is this issue affecting a production system? (yes/no): no

Context

• node version: 12 and 13
• module version: 19.x
• environment (e.g. node, browser, native): node
• used with (e.g. hapi application, another framework, standalone, ...): hapi application
• any other relevant information: related to events and logging

What problem are you trying to solve?

I was recently working on a logging module (https://github.com/cjihrig/graylogi) and ended up diving into the events and logging deeper than I otherwise have recently. This issue is documenting some of the things that I found a bit confusing, as well as some logging features that would be useful to have from the framework:

• The 'request' event is not emitted when a new request is received. Due to its name, and the presence of the similar 'response' event, it took me a minute to realize that I needed the onRequest extension instead.
• The fact that server.log() triggers 'log' events, but request.log() triggers 'request' events.
• The fact that request errors also trigger 'request' events. It's nice that there are a small number of events to handle, but the flip side is that individual event handlers end up more complex than they'd otherwise need to be.

Do you have a new or modified API suggestion to solve the problem?

From a logging perspective, the following things would be great to have:

• It would be nice if hapi either provided some logging friendly objects/methods as first class citizens, or toJSON() methods on more objects that are otherwise problematic to deal with in JSON (circular structures, Maps, etc.). I know this might be tricky, as people will always want different things in their logs.

• Built in support for ignoring events based on path or tags would also be great. For example, ignoring everything related to /health.

• Support for log levels, including the ability to set a default log level and a minimum log level threshold.

• A documented log format. That would enable things like logging to stdout/stderr from hapi, and piping them to another process for more in depth handling (reformatting, shipping, etc.). This is similar to pino's concept of transports.

Sorry if it seems like I'm requesting a lot 😄

[devinivy]

Just chiming in here to offer some brief feedback and squeak out a few more details.

The fact that server.log() triggers 'log' events, but request.log() triggers 'request' events.

You see this solely as a naming issue, is that right?

The fact that request errors also trigger 'request' events. It's nice that there are a small number of events to handle, but the flip side is that individual event handlers end up more complex than they'd otherwise need to be.

Did you investigate the filter and channel options provided via podium? If so, where did those fall down for you?

It would be nice if hapi either provided some logging friendly objects/methods as first class citizens, or toJSON() methods on more objects that are otherwise problematic to deal with in JSON (circular structures, Maps, etc.). I know this might be tricky, as people will always want different things in their logs.

When you say "objects," are you referencing hapi-specific objects such as request and route objects, or arbitrary objects that users might log?

Built in support for ignoring events based on path or tags would also be great. For example, ignoring everything related to /health.

That would be neat: I can imagine adding route ids into request log tags, so it would be simple to filter by specific routes.

Support for log levels, including the ability to set a default log level and a minimum log level threshold.

Do you see this interplaying with event tag filters?

A documented log format. That would enable things like logging to stdout/stderr from hapi, and piping them to another process for more in depth handling (reformatting, shipping, etc.). This is similar to pino's concept of transports.

I think hapi-pino has solved this issue (and some of the issues mentioned above, e.g. utilizing tags for log levels) fairly well. Are you overall encouraging hapi to provide some of the functionality provided by external libraries (e.g. hapi-pino) rather than providing the very generic eventing/filtering system that it currently does? And would you advocate it be part of hapi core, or a separate module (i.e. replacing good, which is deprecated at the end of the year)?

[cjihrig]

The fact that server.log() triggers 'log' events, but request.log() triggers 'request' events.

You see this solely as a naming issue, is that right?

Yes and no. Yes, in that I would expect 'request' to be similar to 'response'. No, in that it's not an event, but an extension point.

Did you investigate the filter and channel options provided via podium? If so, where did those fall down for you?

I think my issue is more that the 'request' event does too many things - kind of an umbrella of things related to requests. It would be more straightforward if there were separate events (example names request-log and request-error) to make it much more explicit what data you're subscribing to (which you could further filter based on channel, etc.).

When you say "objects," are you referencing hapi-specific objects such as request and route objects, or arbitrary objects that users might log?

Using pino as an example, they have a collection of standard serializers for things like the request and response objects. This provides a known format for the rest of the pino ecosystem to build on.

Do you see this interplaying with event tag filters?

Sort of. Log levels are different from events though. Events can be filtered based on a string name. For log levels, the values need to map to values that can be compared in a way that makes sense. For example, doing a string compare between 'error' and 'info' doesn't make much sense for determining log level.

I think hapi-pino has solved this issue (and some of the issues mentioned above, e.g. utilizing tags for log levels) fairly well. Are you overall encouraging hapi to provide some of the functionality provided by external libraries (e.g. hapi-pino) rather than providing the very generic eventing/filtering system that it currently does? And would you advocate it be part of hapi core, or a separate module (i.e. replacing good, which is deprecated at the end of the year)?

hapi-pino is a great inspiration, but is ultimately tied to an external team, another http framework, and out of hapi's control. We were using hapi-pino until today, but because of $reasons I needed to either write a logging module that tied into hapi directly, or a pino transport. I think hapi should have an official logging solution (to replace good). I don't have an opinion about it being built into core or just under the hapijs org, but it should be The Way™ to do hapi logging.