Format option should affect the output formatting of exceptions on STDERR for the CLI

[CMCDragonkai]

Specification

Now that we centralised all of our error functionality into https://github.com/MatrixAI/js-errors, we have a more structured way of creating and propagating way. Due to this, we need our output for these errors to become more formalised as well in order to display this information. We need to be able to communicate the information from our errors to both humans and machines, so we need to modify the --format option to apply to the STDERR as well as the STDOUT.

Readable details included in both styles of output would need to include:

• Structured error information coming from Integrate Structured Logging js-logger#3
• Chained error information coming from Integrate Error Chaining in a js-errors or @matrixai/errors package #304
• Extra data that is put into the data property
• Whether the exception came from local or from a remote PK node Integrate Error Chaining in a js-errors or @matrixai/errors package #304 (comment)
• Contextual information about parsing/validation errors

The json output is the most simple to achieve, since we now have toJSON and fromJSON methods for our errors that allow them to be serialised and deserialised easily. toJSON is called automatically whenever JSON.stringify() is called, so nothing needs to change about how we already handle the output of json data (except for handling non-polykey errors, which have no toJSON method).

A bit more thought needs to go into the human-readable output style, for example:

• Indentation: we want to indent every error in the cause chain, and we want to indent error properties underneath the name of the error
• Formatting: we want to use tabs between keys and values for readability, and keys should be displayed in camelCase
• Data: we want to include important information without crowding the output - we want to minimise repetition (e.g. don't print the exitCode for remote errors since these are inherited from the cause, and don't print the stack for any errors)

There is one point of ambiguity, which is that of logging for the PK agent. When starting the PK agent, we can use the --format option, but this would affect the output of the starting command and the output of logs going to STDERR for the agent process. Should this be 2 separate options? I believe this has been discussed here MatrixAI/js-logger#3 (comment) and the conclusion was that no, it should be 1 option, and it affects STDOUT, STDERR of the CLI command as well as the STDERR logging of the agent process if any.

This means that the format option needs to be propagated to the exit handlers, as well as the error loggers in polykey-agent.ts. This requires dynamic setting of the format property after it has been passed in as an option.

Additional context

• Integrate Structured Logging js-logger#3 - We need structured logging in order to completely address this issue
• Integrate Error Chaining in a js-errors or @matrixai/errors package #304 - Issue for error chaining including implementation details

Tasks

1. Modify the output formatter to display more detailed error information (including the error chain)
2. Propagate the --format option to CommandPolykey (and all subcommands), the exit handlers, and polykey-agent

[CMCDragonkai]

@emmacasolin when you come up with the format here, can you also update the issue description here later. Some of the notes above will be out of date.

[emmacasolin]

For the human readable errors I have a method that produces the following output:

Standard error

    TypeError: some error

PK error (not ErrorPolykeyRemote)

    ErrorPolykey: Polykey error - some pk error
    ExitCode    1
    Timestamp   Fri May 20 2022 16:45:53 GMT+1000 (Australian Eastern Standard Time)
    Data        {"string":"one","number":1}

ErrorPolykeyRemote wrapping a PK error

    ErrorPolykeyRemote: Remote error from RPC call - some remote error
    Command     some command
    NodeId      v71ijgc1ncgsjic9k61h32dhl74q32cj36opm4or669ij4chl68og
    Host        127.0.0.1
    Port        55555
    Timestamp   Fri May 20 2022 16:45:53 GMT+1000 (Australian Eastern Standard Time)
    Remote error: ErrorPolykey: Polykey error - some pk error
      ExitCode  1
      Timestamp Fri May 20 2022 16:45:53 GMT+1000 (Australian Eastern Standard Time)
      Data      {"string":"one","number":1}

Two ErrorPolykeyRemotes wrapping a PK error with a cause

    ErrorPolykeyRemote: Remote error from RPC call - remote error 2
    Command     command 2
    NodeId      v74o3ed3261gm4pj6ckp64phkcdh36e35ccq38or471i62phg6cp0
    Host        127.0.0.1
    Port        55555
    Timestamp   Fri May 20 2022 16:45:53 GMT+1000 (Australian Eastern Standard Time)
    Remote error: ErrorPolykeyRemote: Remote error from RPC call - remote error 1
      Command   command 1
      NodeId    v6hi36c1kcgs3ie9p6cq66chn6lhm2ohnc5i38dj56pijcphp6hh0
      Host      127.0.0.1
      Port      55555
      Timestamp Fri May 20 2022 16:45:53 GMT+1000 (Australian Eastern Standard Time)
      Remote error: ErrorPolykey: Polykey error - pk error
        ExitCode        1
        Timestamp       Fri May 20 2022 16:45:53 GMT+1000 (Australian Eastern Standard Time)
        Data    {}
        Cause: TypeError: some error

I don't like that a PK error with an empty data property shows up as {} but I can't seem to strip it out.

[emmacasolin]

In polykey.ts the exit handlers are constructed before the root command (because the exit handlers need to be passed into the root command during construction). This is a problem though, because the desired format for error logging is only decided at the time that the root command is run. There is some error logging that is done by the exit handlers, but I can't think of a way to propagate the format option to them.

[CMCDragonkai]

Yea, that is correct. You will have to dynamic formatting change.

The exit handlers are setup before the root command CommandPolykey because it is supposed to handle all possible exits and potentially non-terminating command exits.

They are used in both src/polykey.ts and src/polykey-agent.ts.

So you'll need to make the ExitHandler class capable of taking the format option dynamically. That is inside your CommandPolykey after the format option is set, you will need to do something like exitHandlers.setFormat(f).

Then inside the ExitHandlers class, you'll need to have some parameter that switches state, and that changes how it performs the call binUtils.outputFormatter.

In the case of src/bin/polykey-agent.ts, dynamic setting can also be done, but only after the options are read from messageIn.agentConfig.

[emmacasolin]

Examples of the new error logging style:

# Single error (no cause)
# --format=human (default)
ErrorStatusLocked: Status is locked by another process
  exitCode      75
  timestamp     Mon May 23 2022 15:25:08 GMT+1000 (Australian Eastern Standard Time)
# --format=json
{"type":"ErrorStatusLocked","data":{"message":"","timestamp":"2022-05-23T05:00:32.049Z","data":{},"stack":"ErrorStatusLocked\n    at constructor_.start (/home/emma/Projects/js-polykey/src/status/Status.ts:53:13)\n    at async /home/emma/Projects/js-polykey/node_modules/@matrixai/async-init/src/StartStop.ts:56:24\n    at async withF (/home/emma/Projects/js-polykey/node_modules/@matrixai/resources/src/utils.ts:24:12)\n    at async Object.bootstrapState (/home/emma/Projects/js-polykey/src/bootstrap/utils.ts:73:5)\n    at async /home/emma/Projects/js-polykey/src/bin/bootstrap/CommandBootstrap.ts:24:31\n    at async CommandBootstrap.<anonymous> (/home/emma/Projects/js-polykey/src/bin/CommandPolykey.ts:75:7)\n    at async CommandPolykey.parseAsync (/home/emma/Projects/js-polykey/node_modules/commander/lib/command.js:923:5)\n    at async main (/home/emma/Projects/js-polykey/src/bin/polykey.ts:54:5)\n    at async /home/emma/Projects/js-polykey/src/bin/polykey.ts:103:5","exitCode":75}}

# Remote error with cause
# --format=human (default)
ErrorPolykeyRemote: Remote error from RPC call
  command       nodesPing
  nodeId        vasrqbpb1u51khi7ibg5j63ai3odomhj6js348k1ra5jffjuvrhsg
  host  127.0.0.1
  port  37595
  timestamp     Mon May 23 2022 15:25:21 GMT+1000 (Australian Eastern Standard Time)
  remote error: ErrorNodeGraphEmptyDatabase: NodeGraph database was empty
    exitCode    64
    timestamp   Mon May 23 2022 15:25:21 GMT+1000 (Australian Eastern Standard Time)
# --format=json
{"type":"ErrorPolykeyRemote","data":{"message":"","timestamp":"2022-05-23T04:56:47.661Z","data":{},"cause":{"type":"ErrorNodeGraphEmptyDatabase","data":{"message":"","timestamp":"2022-05-23T04:56:47.648Z","data":{},"stack":"ErrorNodeGraphEmptyDatabase\n    at constructor_.getClosestGlobalNodes (/home/emma/Projects/js-polykey/src/nodes/NodeConnectionManager.ts:456:13)\n    at async constructor_.findNode (/home/emma/Projects/js-polykey/src/nodes/NodeConnectionManager.ts:373:17)\n    at async NodeManager.pingNode (/home/emma/Projects/js-polykey/src/nodes/NodeManager.ts:58:7)\n    at async Object.nodesPing (/home/emma/Projects/js-polykey/src/client/service/nodesPing.ts:48:22)","exitCode":64}},"stack":"ErrorPolykeyRemote\n    at toError (/home/emma/Projects/js-polykey/src/grpc/utils/utils.ts:202:29)\n    at Object.callback (/home/emma/Projects/js-polykey/src/grpc/utils/utils.ts:380:17)\n    at Object.onReceiveStatus (/home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/client.ts:351:26)\n    at /home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/call-stream.ts:206:27\n    at Object.onReceiveStatus (/home/emma/Projects/js-polykey/src/grpc/utils/FlowCountInterceptor.ts:57:13)\n    at InterceptingListenerImpl.onReceiveStatus (/home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/call-stream.ts:202:19)\n    at /home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/call-stream.ts:206:27\n    at Object.onReceiveStatus (/home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/client-interceptors.ts:163:5)\n    at InterceptingListenerImpl.onReceiveStatus (/home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/call-stream.ts:202:19)\n    at Object.onReceiveStatus (/home/emma/Projects/js-polykey/node_modules/@grpc/grpc-js/src/client-interceptors.ts:462:34)","exitCode":64,"metadata":{"nodeId":{"type":"IdInternal","data":[87,55,165,229,97,241,67,72,200,242,92,11,51,13,82,30,27,139,70,102,159,6,68,80,59,81,102,247,207,223,220,121]},"host":"127.0.0.1","port":37595,"command":"nodesPing"}}}

Normal logger messages remain the same (i.e. are not affected by the format option). This can be addressed later in MatrixAI/js-logger#3.

[CMCDragonkai]

We'll have another issue addressing the usability experience of the CLI errors. I imagine we would combine --format with --verbose. So increasing verbosity will end up showing more error information. The default verbosity might just print <Description> - <Message> without even the error name.

So for now, the remote error should be changed back to just cause like all other exceptions.

Not showing the stack is fine for now. We can figure that out in the usability part.

As for --format=json, I believe this would not be affected by verbosity, since the expectation is that this would be used by machines. So verbosity flags would affect only the --format=human.

[CMCDragonkai]

The error reporting verbosity control is here MatrixAI/Polykey-CLI#17. That can be addressed in the future.

[CMCDragonkai]

According to @emmacasolin I believe this is done. However right now structured logging (MatrixAI/js-logger#3) is not available yet, so the --format json doesn't affect STDERR logs yet. We still need to address that along with MatrixAI/Polykey-CLI#17. This is done in staging.