Tests marked as failed if success indicator isn't the beginning of output

[notnoop]

Noticed that some successful tests get marked as failures in our CI. I noticed that if the --- PASS: final line indicator is preceded by other log information, the test is marked as fail with -0.0 run_time.

The issue happens somewhat rarely - 10 builds out of 105 builds in my sample.

A sample case is TestScalingPolicies_GetPolicy in https://circleci.com/gh/hashicorp/nomad/69658 . The raw json events from go test is in https://69658-36653430-gh.circle-artifacts.com/0/tmp/test-reports/testjsonfile.json .

In the above case note that --- PASS: line isn't the beginning of the line:

{"Time":"2020-05-22T13:54:21.740428891Z","Action":"output","Package":"github.com/hashicorp/nomad/api","Test":"TestScalingPolicies_GetPolicy","Output":"    2020-05-22T13:54:21.737Z [DEBUG] worker: created evaluation: eval=\"\u003cEval \"1e656465-9c8c-7a35-a2fe-cda7fe77b049\" JobID: \"job1\" Namespace: \"default\"\u003e\"--- PASS: TestScalingPolicies_GetPolicy (1.60s)\n"}

The logs are output of a processes that is spawned from the test and directly writes to Stderr. My theory is that the process is killed before the new line is flushed and result into contaminating go test output. In all of my observations, the go test success indicator ended the line, I haven't noticed any case where the process final log output surrounded go test indicator. I've updated our project to ensure the process is terminated gracefully, but we are waiting results.

Here are some sample builds hitting this issue as well:

• https://circleci.com/gh/hashicorp/nomad/69429
• https://circleci.com/gh/hashicorp/nomad/69557
• https://circleci.com/gh/hashicorp/nomad/69570
• https://circleci.com/gh/hashicorp/nomad/69658
• https://circleci.com/gh/hashicorp/nomad/69688
• https://circleci.com/gh/hashicorp/nomad/69689
• https://circleci.com/gh/hashicorp/nomad/69703
• https://circleci.com/gh/hashicorp/nomad/69888

[dnephin]

I haven't looked into it in much detail, but I suspect this is an issue with test2json: golang/go#38063

Missing newlines cause problems. I'm happy to keep this issue open to track the problem, but I suspect this needs to be fixed in Go.

In general it seems like chatty tests which output a lot of stdout do not work well with test2json. I have been working on cleaning up some tests to buffer output, and only print them when the test fails (ex: hashicorp/consul#7948).

[notnoop]

Makes sense. I see that there are few other tickets related to this too already - so closing as duplicate. Thanks!