chore(logs): improve log messages

[martinm82]

While debugging the app I have been struggling a lot with figuring out from where the logs were coming from. We are using a central logging system (DataSet) where logs can be easily queried and filtered.

For that purpose I have started to use the child method of the pino logger used by the Probot app to add additional attributes in the log messages.

Let me know what you think about this.

[anderssonjohan]

@martinm82 I think it looks good, but what about duplicate keys for context in the output? https://github.com/pinojs/pino/blob/master/docs/child-loggers.md#duplicate-keys-caveat

Maybe a good thing could be to use different property names for the context? I interpret the context in your PR similarly to the logger name in Python's logger.getLogger("logger.name.here"). If you add plugin as another property and pass that logger to MergeDeep's constructor, then you will have both "plugin": "branches" and "context": "mergedeep" in the log output from mergedeep and similar utility modules. That would remove the duplicate key that may get lost when shipping the json logs somewhere.

It makes sense to have a logger context/name that matches the source code filename. Also adding plugin would make it easy to filter out everything caused by a specific plugin.

But most valueable to me when doing log diving is to have a trace id around. In the context of Safe Settings it would be really great to have the github delivery id on every log record:

Sometimes you have to debug timeouts in the webhook delivery log and you wonder what actually happened in the Safe Settings end. Did the request get processed and/or did the lambda start? Maybe the request took too long time to complete?
Having the delivery id around would help filter out the log output for a specific event/delivery.

The delivery ID could be populated in a "root logger" in the event handler / index.js. Each plugin could create a child logger from that (passed via the constructor) and further on utility modules like mergedeep can create their child loggers from the plugin loggers.

What do you think?

[martinm82]

@martinm82 I think it looks good, but what about duplicate keys for context in the output? https://github.com/pinojs/pino/blob/master/docs/child-loggers.md#duplicate-keys-caveat

Maybe a good thing could be to use different property names for the context? I interpret the context in your PR similarly to the logger name in Python's logger.getLogger("logger.name.here"). If you add plugin as another property and pass that logger to MergeDeep's constructor, then you will have both "plugin": "branches" and "context": "mergedeep" in the log output from mergedeep and similar utility modules. That would remove the duplicate key that may get lost when shipping the json logs somewhere.

Indeed, haven't thought about the duplicates. Will extend a bit the implementation and incorporate this.

It makes sense to have a logger context/name that matches the source code filename. Also adding plugin would make it easy to filter out everything caused by a specific plugin.

With central logging systems (e.g. DataSet) one can use queries like plugin = * and it is able to filter out all logs where the attribute plugin exists. But I will extend the PR and add a component/type attribute so that one can easily grep as well for example for plugins.

But most valueable to me when doing log diving is to have a trace id around. In the context of Safe Settings it would be really great to have the github delivery id on every log record:

I agree but maybe we could tackle this in a separate PR, WDYT?

[anderssonjohan]

This seems unused to me. Maybe I'm missing something here :)