useStdError=true can bring false positive test results

[dmytro-grablov]

The problem

I am not quite sure that this is fixable on the reporter side, but I feel I need to create the ticket just to bring an attention to the others. Teamcity has a known issue of output stream synchronizations Which means the order of messages across stdOut and stdErr is not guaranteed. It also appears that teamcity cares about the message order in regards to test reports (at least it cares in 2020.1)

With useStdError=true the reporter will throw 'testFailure' into stdErr, but 'testFinished' into stdOut. if you are unlucky, 'testFinished' will arrive earlier and the test will be marked as passed

Environment

• What mocha-teamcity-reporter version are you using: 4.0.0
• Version of NPM/yarn etc and Node.js: node 14.13.1, npm 6.14.10
• Version of teamcity (If Applicable): 2020.1 (on premises)

Details

An example test or code sample

To see the effect, you don't need to install mocha and teamcity reporter plugin. Just create a teamcity build configuration with one linux shell step:

echo "##teamcity[testSuiteStarted name='suite0' flowId='40792']"
echo "##teamcity[testStarted  name='test1' captureStandardOutput='true' flowId='40792']"
>&2 echo "##teamcity[testFailed   name='test1' message='horrible error' captureStandardOutput='true' flowId='40792']"
echo "##teamcity[testFinished name='test1' duration='1424' flowId='40792']"
echo "##teamcity[testStarted  name='test2' captureStandardOutput='true' flowId='40792']"
>&2 echo "##teamcity[testFailed   name='test2' message='horrible error' captureStandardOutput='true' flowId='40792']"
echo "##teamcity[testFinished name='test2' duration='1481' flowId='40792']"
echo "##teamcity[testStarted  name='test3' captureStandardOutput='true' flowId='40792']"
>&2 echo "##teamcity[testFailed   name='test3' message='horrible error' captureStandardOutput='true' flowId='40792']"
echo "##teamcity[testFinished name='test3' duration='1583' flowId='40792']"
echo "##teamcity[testStarted  name='test4' captureStandardOutput='true' flowId='40792']"
>&2 echo "##teamcity[testFailed   name='test4' message='horrible error' captureStandardOutput='true' flowId='40792']"
echo "##teamcity[testFinished name='test4' duration='1623' flowId='40792']"
echo "##teamcity[testStarted  name='test5' captureStandardOutput='true' flowId='40792']"
>&2 echo "##teamcity[testFailed   name='test5' message='horrible error' captureStandardOutput='true' flowId='40792']"
echo "##teamcity[testFinished name='test5' duration='1525' flowId='40792']"
echo "##teamcity[testStarted  name='test6' captureStandardOutput='true' flowId='40792']"
>&2 echo "##teamcity[testFailed   name='test6' message='horrible error' captureStandardOutput='true' flowId='40792']"
echo "##teamcity[testFinished name='test6' duration='1466' flowId='40792']"
echo "##teamcity[testSuiteFinished name='suite0' duration='12740' flowId='40792']"
echo "Executing global teardown"

Run the build several times and observe random results

[jamie-sherriff]

Thanks @dmitriy-grablyov seems like a gnarly one, any ideas on how to reduce the impact? If not I will probably just amend the readme with the information you provided for others and close this off?

[dmytro-grablov]

I might suspect that checking the test state in the 'test finished' hookand throwing the message into stdErr too if test was failed, might be a solution to this issue. On the other hand I doubt, that this is a good solution at all

[jamie-sherriff]

@dmitriy-grablyov The reporter already supports sending a failed test to stdErr on the test fail hook which is triggered before the test end event, does that not capture what you want it to?

[dmytro-grablov]

@jamie-sherriff , no because it sends testFailed into stdErr, but testFinished into stdOut. Plugin (or better let's say, mocha) guarantees to send testFailed before testFinished, but because these are 2 different pipes and due to JVM specifics teamcity cannot guarantee that these messages will appear in the same order on the log.

And if testFinished is printed before testFailed, then teamcity marks test as passed

[DJ-Glock]

@dmitriy-grablyov did you face this issue only with useStdError=true? It looks like I've faced the same with no useStdError flag. But I am not sure.

I can see in raw log the followiing:

e2e_1  | ##teamcity[testStarted name='FtsUI - 1.2 Security selected #full #intfull' captureStandardOutput='true' flowId='19']
e2e_1  | ##teamcity[testStarted name='"before each" hook: Clean search in "FtsUI - 1 Search Input "' captureStandardOutput='true' flowId='19']
e2e_1  | ##teamcity[testFinished name='"before each" hook: Clean search in "FtsUI - 1 Search Input "' flowId='19']
e2e_1  | ##teamcity[testFailed name='FtsUI - 1.2 Security selected #full #intfull' message='Test and Master SecuritySelected.png files should be equal: expected |'Screenshot /e2e/test-screenshots/FTS/SecuritySelected.png did not match with master screenshot /e2e/master-screenshots/FTS/SecuritySelected. DiffBounds: {"left":0,"top":0,"right":180,"bottom":31} Diff-image will be saved to /e2e/diff-screenshots/FTS/SecuritySelected.png.|' to equal true' details='AssertionError: Test and Master SecuritySelected.png files should be equal: expected |'Screenshot /e2e/test-screenshots/FTS/SecuritySelected.png did not match with master screenshot /e2e/master-screenshots/FTS/SecuritySelected. DiffBounds: {"left":0,"top":0,"right":180,"bottom":31} Diff-image will be saved to /e2e/diff-screenshots/FTS/SecuritySelected.png.|' to equal true|n    at Function.compareScreenshots (src/Tests/UIGeneric.ts:21:80)|n    at processTicksAndRejections (internal/process/task_queues.js:93:5)|n    at Context.<anonymous> (src/TestsPoMa/FTS/FTS.prl.ui.ts:45:7)' captureStandardOutput='true' flowId='19']
e2e_1  | ##teamcity[testFinished name='FtsUI - 1.2 Security selected #full #intfull' duration='6166' flowId='19']

But in TeamCity:

I am really confused because I did not set useStdError any value. I tried to set useStdError=false and get the same issue.

[dmytro-grablov]

No, this I haven't experienced

[DJ-Glock]

@dmitriy-grablyov thanks. It looks like a separate issue and I guess I know what is happening here. Will create another one.