command "cargo test --release -- -Z unstable-options --format json" is genrating invalid json sometimes

[merlachandra]

Problem

I'm running tests using the command "cargo test --release -- -Z unstable-options --format json", but intermittently I'm seeing json generated is invalid.

I'm seeing output is being printed in json immediately following "event": "ok" as highlighted in below output:

{ "type": "test", "name": "cloud::tests::set_operation_status_to_successful_success", "event": "ok"[2021-04-03T17:24:48Z] command [1874045692]: 81,client_id_123,/device_id_654
}
{ "type": "test", "event": "started", "name": "cloud::tests::unexpected_40_record_no_86" }
[2021-04-03T17:24:48Z] response [1874045692]:

Sometimes the json output is coming finely as below. This is random, happening in different tests each time.

{ "type": "test", "name": "cloud::tests::set_operation_status_to_successful_success", "event": "ok" }
[2021-04-03T07:10:25Z] command [2703824267]: 83,client_id_123
[2021-04-03T07:10:25Z] response [2703824267]: 40,,/meta/connect,402::Unknown client
86,,,0,handshake

Basically I'm trying to get junit report out of this json as decribed at https://crates.io/crates/cargo2junit, where I'm getting error as below due to invalid json:

Error: Custom { kind: Other, error: "Error parsing '{ "type": "test", "name": "cloud::tests::set_operation_status_to_successful_success", "event": "ok"[2021-04-03T17:24:48Z] command [1874045692]: 81,client_id_123,/device_id_654': expected , or } at line 1 column 100" }

Steps

Possible Solution(s)

The json generated is broken sometimes due to incorrect json format, which needs to be fixed.

Notes

Output of cargo version:
cargo 1.49.0 (d00d64d 2020-12-05)
rustc 1.49.0 (e1884a8e3 2020-12-29)

sh-4.2# cat /etc/os-release
NAME="CentOS Linux"
VERSION="7 (Core)"
ID="centos"
ID_LIKE="rhel fedora"
VERSION_ID="7"
PRETTY_NAME="CentOS Linux 7 (Core)"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:centos:centos:7"
HOME_URL="https://www.centos.org/"
BUG_REPORT_URL="https://bugs.centos.org/"

CENTOS_MANTISBT_PROJECT="CentOS-7"
CENTOS_MANTISBT_PROJECT_VERSION="7"
REDHAT_SUPPORT_PRODUCT="centos"
REDHAT_SUPPORT_PRODUCT_VERSION="7"

[ehuss]

Do you maybe have logging or something writing directly to stdout or stderr? Where is [2021-04-03T17:24:48Z] command [1874045692]: 81,client_id_123,/device_id_654 coming from?

The test harness tries to capture stdout/stderr (like println! will get captured), but there are ways to circumvent that (like writing to std::io::stdout). If the tests are circumventing that capture, there's not much that can be done. The main alternative is to launch a separate process per test (which is partially implemented and tracked in rust-lang/rust#67650).

[ehuss]

Without further information, I'm going to close. I suspect the issue is that logging is writing directly to stderr which is uncoordinated with the test harness' output. Also, if you have further issues with the libtest output, the issue tracker for that is https://github.com/rust-lang/rust/issues, where the test crate lives.