flakes in node-test-commit-v8-linux/nodes=benchmark

[refack]

Refs: nodejs/node#16398
1005 failed
1006 passed
1007 passed
1008 failed
1009 failed
1010 pass
1011 pass (similar to 1005)
(there no apparent correlation with source changes)

The fail is when v8/deps/test/message/console.js compares actual vs expected output to stdout and stderr:

Actual output:

abcd: 0.055000
b: 0.000000
a: 0.001000
log more
warn 2
debug
info
/home/iojs/build/workspace/node-test-commit-v8-linux/nodes/benchmark/v8test/v8test/deps/v8/test/message/console.js:25: Error: exception
console.info({ toString: () => {throw new Error("exception");} })
                                ^
Error: exception
    at Object.toString (/home/iojs/build/workspace/node-test-commit-v8-linux/nodes/benchmark/v8test/v8test/deps/v8/test/message/console.js:25:39)
    at console.info (<anonymous>)
    at /home/iojs/build/workspace/node-test-commit-v8-linux/nodes/benchmark/v8test/v8test/deps/v8/test/message/console.js:25:9

Expected output:

abcd: {NUMBER}
b: 0.000000
a: {NUMBER}
log more
warn 2
debug
info
*%(basename)s:25: Error: exception
console.info({ toString: () => {throw new Error("exception");} })
                                ^
Error: exception
    at Object.toString (*%(basename)s:25:39)
    at console.info (<anonymous>)
    at *%(basename)s:25:9

[fhinkel]

Thanks for opening in the right repo.

[rvagg]

Can't explain this one, but since some of the weirdest infra problems have been solved with a reboot I've done that! Updated the machine while I was at it, I'm not sure it'd been updated since first installed (I hope I haven't messed up the benchmarks in the process!).

Re-ran last job and it looks OK for now, let's keep an eye on it and see if the problem returns.

https://ci.nodejs.org/job/node-test-commit-v8-linux/1026/nodes=benchmark,v8test=v8test/

[refack]

It's still there https://ci.nodejs.org/job/node-test-commit-v8-linux/nodes=benchmark,v8test=v8test/1027/console

[rvagg]

OK, I've got build 1027's state copied and compiled and I can repeat the failure. I don't have time to figure it out but I have it sitting in a directory on that server that won't be deleted (automatically), so who wants to take a look? @nodejs/v8

iojs@nodejsb1:~/v8test_temp_gh_build_936$ /home/iojs/v8test_temp_gh_build_936/deps/v8/out/x64.release/d8 --test --random-seed=1505382534 --no-stress-opt --nohard-abort /home/iojs/v8test_temp_gh_build_936/deps/v8/test/message/console.js
default: 0.001000
abcd: 0.027000
b: 0.000000
a: 0.001000
log more
warn 2
error
debug
info
/home/iojs/v8test_temp_gh_build_936/deps/v8/test/message/console.js:25: Error: exception
console.info({ toString: () => {throw new Error("exception");} })
                                ^
Error: exception
    at Object.toString (/home/iojs/v8test_temp_gh_build_936/deps/v8/test/message/console.js:25:39)
    at console.info (<anonymous>)
    at /home/iojs/v8test_temp_gh_build_936/deps/v8/test/message/console.js:25:9

[rvagg]

More:

iojs@nodejsb1:~/v8test_temp_gh_build_936$ echo $?
0

🤷 someone should take a look though and see if you can make sense why this is failing in CI

[fhinkel]

Thanks @rvagg . Do you get consistent failure with the copy of 1027? Or is it flaky?

[rvagg]

@fhinkel well, I get consistent output that I pasted above, but exit status for the test is 0 to maybe that's not actually a failure?

[rvagg]

@fhinkel I've put your github keys onto that machine, ssh iojs@50.23.85.254 and look in the v8test_temp_gh_build_936 directory for that clone of 1027. You can run /home/iojs/v8test_temp_gh_build_936/deps/v8/out/x64.release/d8 --test --random-seed=1505382534 --no-stress-opt --nohard-abort /home/iojs/v8test_temp_gh_build_936/deps/v8/test/message/console.js to replicate the failing bit.

[fhinkel]

Thanks! Investigating. Will let you know when you can delete my keys again.

[fhinkel]

That build doesn't reproduce the error for me. Message tests are somewhat confusing: The message tests are supposed to throw error messages. The test runner compares the output with the *.out files. So running just the test file with d8 looks like an error, but the test actually passes because the output matches the expected output.

iojs@nodejsb1:~/v8test_temp_gh_build_936$ ./deps/v8/tools/run-tests.py --arch=x64 --mode=release message/console
>>> Running tests for x64.release
No connection to distribution server; running tests locally.
[00:00|% 100|+   1|-   0]: Done   

Pinging @hashseed as he has touched the test case in the past if he has any idea why this might be flaky on the CI. When the test on the CI fails, the output looks to my eye exactly like the expected output 😕

[hashseed]

Doesn't ring a bell. I have never seen this test fail before, and the expectation file seems to match the output too.

[fhinkel]

@GeorgNeis figured it out 🎆 There's a regex checking that the time is a number - with 1 decimal in front of the period. So anything longer than 10 milliseconds fails the regex check. We'll fix this on the V8 side.

[fhinkel]

I guess we can close this? We can backport v8/753322 once it lands to avoid further flakes.

[rvagg]

phew! what a relief, thanks @fhinkel & @GeorgNeis. I'll remove those keys from the server now.