Integrate Structured Logging

[CMCDragonkai]

Specification

Structured logging is to use JSON on the STDERR logs. This exposes more of the data, and allows us to create a standard for the set of fields to be used.

There's no real official standard for structured logging. But journalctl and syslog defines some common fields. The fields can be similar to our formatting that we already use, but this time in a JSON format. Additional data fields can be encoded too.

We could put a json formatting in somewhere that provides the JSON serialisation.

This can be especially useful since we are also looking into adding error chaining, which we have done in a few places. But by creating our own @matrixai/error we can implement error chaining. MatrixAI/Polykey#304

Additional context

• Integrate Error Chaining in a js-errors or @matrixai/errors package Polykey#304
• https://www.structlog.org/en/stable/
• https://github.com/uber-go/zap
• Implementing BIP39 recovery, Unattended Bootstrap and Agent Start and Status Polykey#283 (comment) - where an error came up and no context was there, but all in the data which required manual serialisation

Tasks

1. Research different structured logging libraries
2. Compare with opentracing or tracing based data formats
3. Implement simple structured logging capabilities into js-logger

[CMCDragonkai]

Need to consider a couple of things:

• Common fields that should align with other structured logging mechanisms
• The --format field used for output formatting can double as for logger formatting too
• How does error chaining come into play here, and how should these be shown?
• How does stack traces come into play here? Stack traces don't have sensitive information, they are just traces of what functions called what functions.

[CMCDragonkai]

So basically the problem is this:

1. Does --format apply to just STDOUT or also to STDERR? I believe it should apply to both. Especially as STDERR will likely be relied on upon quite a bit by pk agent start. So doing something like pk agent start --format=json --verbose will then ensure that INFO messages get logged out to STDERR by with JSON structure rather than human readable messages. This will be important for any kind of long-term debugging of the PK agent.
2. If --format applies to STDERR as well, this then affects the PK CLI calls which would mean any exception plus INFO messages would also become JSON. This is OK as we can expect that once --format=json is used, we would actually want this to be worked by a computer.

Therefore any usage by a computer should always use --format=json. It would affect exception output on STDERR, logging messages to STDERR, and output to STDOUT.

[CMCDragonkai]

One additional issue is the "level of verbosity". This is basically controlled by --verbose. But when we output an exception to STDERR, we don't currently show the stack trace atm. The root exception handler by the PK agent and in PK CLI calls don't show the stack trace. The stack trace is useful for tracing where the error comes from.

Right now verbosity only controls INFO, WARNING... etc. We could do something where one chooses to use logger.debug to show the stacktrace as well if the logger level is appropriate. But this requires a conditional check on the logger's effective level.

Something like:

if (this.logger.getEffectiveLevel() > ...) {
  this.logger.debug(e, ...); // include stack trace
} else {
  this.logger.info(e, ...); // don't include stack trace
}

A similar situation would apply to errors being thrown over the GRPC boundary as discussed here MatrixAI/Polykey#249.

I reckon something can be automated if we integrate the design of js-logger with js-errors library here MatrixAI/Polykey#304, such that when an error is being logged out, we gain additional context depending on what the log level is. Of course what errors is passed over GRPC also depends, some errors we only want to write to the agent's STDERR, other errors we want to propagate to the GRPC client, and in other cases we would want to "map" agent-local errors to GRPC API errors.

This would mean something like catch a local agent error, write that out to STDERR on the agent on the RPC handler, then create a new error to be propagated to the GRPC client. We have to separate client errors from server errors like in HTTP where there is 4xx errors vs 5xx errors. 5xx errors would be caught by the exit handler, and put to STDERR. 4xx errors are not, they would be emitted by the RPC handler. We would only log them out to STDERR if the RPC handler handled the error, and also that this is a problem for the agent itself.

[CMCDragonkai]

Node v16 should be reporting the error chain nicely now.

[CMCDragonkai]

@emmacasolin FYI this issue addresses the idea of how the exceptions (including the error chaining) will eventually be displayed on the CLI or STDERR logging.

[CMCDragonkai]

Note that the cause property is actually an ES2022 feature, but nodev16 does support it, but because we haven't fully updated our standards to it, we will forget that it actually exists on the standard errors.

[CMCDragonkai]

Any kind of structured logging will be intended for machine consumption and filtering. That's because any logging of server errors may contain a long stack string, and that information is likely to be quite noisy on basic log readers.

[CMCDragonkai]

@emmacasolin this would still be needed to ensure that --format json affects STDERR logging.