JSON output of several commands includes unexpected log entries

chatton commented 1 year ago

Summary of Bug

When using the --json flag to get json output, additional log lines being displayed to stdout in addition to the expected result.

hermes --json create client --host-chain cosmoshub-0 --reference-chain cosmoshub-1
{"timestamp":"2023-02-16T14:24:21.514413Z","level":"INFO","fields":{"message":"using default configuration from '/home/hermes/.hermes/config.toml'"},"threadId":"ThreadId(1)"}
{"timestamp":"2023-02-16T14:24:21.530391Z","level":"INFO","fields":{"message":"running Hermes v1.2.0+061f14f"},"threadId":"ThreadId(1)"}
{"result":{"CreateClient":{"client_id":"07-tendermint-0","client_type":"Tendermint","consensus_height":{"revision_height":9,"revision_number":1}}},"status":"success"}

When working on integrating hermes in to interchaintest, I used the json output to be more easily able to programatically interact with the hermes cli. However the json output does not produce a single json object, it outputs multiple distinct json objects which are not directly parsable without some additional pre-processing of the stdout. E.g.

func extractJsonResult(stdout []byte) []byte {
    stdoutLines := strings.Split(string(stdout), "\n")
    var jsonOutput string
    for _, line := range stdoutLines {
        if strings.Contains(line, "result") {
            jsonOutput = line
            break
        }
    }
    return []byte(jsonOutput)
}

which is a bit of a hack.

My expectation would be that just the final line is displayed to stdout

{"result":{"CreateClient":{"client_id":"07-tendermint-0","client_type":"Tendermint","consensus_height":{"revision_height":9,"revision_number":1}}},"status":"success"}

and the other ones would get appended to a log file.

This parsing needing to be done with outputs for several commands including querying channels, creating connections and creating clients.

Note: I did not encounter this issue in hermes v1.0.0

Version

v1.2.0+061f14f ( using docker container: docker.io/informalsystems/hermes:v1.2.0 )

Steps to Reproduce

Attempt to create a client, e.g. hermes --json create client --host-chain cosmoshub-0 --reference-chain cosmoshub-1

Acceptance Criteria

raw stdout when using --json command is directly unmarshallable into an equivalent data structure.

For Admin Use

[ ] Not duplicate issue
[ ] Appropriate labels applied
[ ] Appropriate milestone (priority) applied
[ ] Appropriate contributors tagged
[ ] Contributor assigned/self-assigned

romac commented 1 year ago

Hermes used to output log messages to stderr and the final result line to stdout (and still does for the human-readable textual output) but we decided to change this for the JSON output in order to make it easier to ingest the full output of start command into other systems.

I agree that for commands other than start, it would make more sense to only output the result line to stdout. Unfortunately, that would also make start and other commands inconsistent with each other, which is not great either.

In the meantime, you can either do exactly as you've shown above (which is a totally fine solution imho) or you can just process the last line of the output.

I will think more on this.

chatton commented 1 year ago

Hi @romac, I understand your concerns about commands being inconsistent, maybe I can provide two other suggestions that you might prefer.

display a json list [{log1Object}, {log2Object}, {resultObject}] this would make the stdout directly marshal-able into a json list. The caller can simply discard all that they don't care of and use myStruct.Results[len(myStruct.Results)-1] in my opinion this is not ideal but preferable to parsing stdout manually to find the json.
display a single json object where logs is an entry

{
    "logs": [{}, {}, {}],
    "result": {}
}

Similar to option one we can discard logs if they are not desired and we would have easy access to the result. Of these options I prefer the second and I think would result in a consistent API let me know what you think!

romac commented 1 year ago

Unfortunately, we cannot really implement either solution with how our logging infrastructure is setup, as we do not emit all the output at once but rather each log line may be emitted at a different time during the execution of the command and the last result line is emitted when the command completes.

I will think about reverting to outputting log lines on stderr and the result line of stdout, but I can't promise we will end up doing that given that Hermes is not the only software which outputs JSON line-by-line, and it is straightforward to only process the very last line emitted.

informalsystems / hermes