Flaky failure on multiple platforms in CITGM

[MylesBorins]

Hey All,

We are periodically seeing failures with winston on various platforms in the Node.js Smoke Testing suite

https://ci.nodejs.org/view/Node.js-citgm/job/citgm-smoker/1655/nodes=ubuntu1804-docker/testReport/(root)/citgm/winston_v3_1_0/

https://ci.nodejs.org/view/Node.js-citgm/job/citgm-smoker/1655/nodes=osx1010/testReport/(root)/citgm/winston_v3_1_0/

   1) Logger, ExceptionHandler
        Custom exitOnError function does not exit:
      Uncaught [1m[31mUnknown assertation failure occured, assumed `[]` to deeply equal `[ 'Ignore this error' ]`
   [90m/home/iojs/build/workspace/citgm-smoker/nodes/ubuntu1804-docker/citgm_tmp/89c15413-6f86-4a39-97d1-0d7e8b66d8be/winston/test/log-exception.test.js[0m
       [31m                              v
       [90m66.       assume(child.killed).false();
       [0m67.       assume(stdout).deep.equals(['Ignore this error']);
       [90m68.       child.kill();
       [31m                              ^[0m
           at Assume.equal (node_modules/assume/index.js:676:15)
           at Timeout._onTimeout (test/log-exception.test.js:67:27)
   [0m

[indexzero]

Exception logging is quite tricky to test. We spawn a child process that throws an error and assert the process exit code / stderr output. There could be a race condition in how we consume child_process.

How long has this been ongoing? Since those tests have not changed in quite some time it also could be subtle change to an aspect of child_process timing in Node itself. If this is recent flakiness that would be more likely.

[MylesBorins]

We've been seeing this flakynes on and off since 3.0.0 afaik across release lines. Sorry for taking so long to report it. I can kick off a that across release lines to find out more

…

On Thu, Nov 29, 2018, 11:40 AM Charlie Robbins ***@***.*** wrote: Exception logging is quite tricky to test. We spawn a child process that throws an error and assert the process exit code stderr output. There could be a race condition in how we consume child_process. How long has this been ongoing? Since those tests have not changed in quite some time it also could be subtle change to an aspect of child_process timing in Node itself. If this is recent flakiness that would be more likely. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#1541 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAecV22kRlbUvbBV504DhThYyhHqKxDAks5u0A3xgaJpZM4Y6CeR> .

[indexzero]

There is a larger discussion about exitOnError and some subtle bugs in it that @DABH knows more about than I do. Will make sure to bring this up when we have our monthly meeting next week.

[indexzero]

Thanks again for the bug report – hopefully the flakiness isn't holding up releases on Node. If it is please let me know and we can make this a higher priority.

[MylesBorins]

It isn't blocking anything on our end. It does mean that we may miss future breakages until we can unmark Winston as flaky

…

On Fri, Nov 30, 2018, 9:01 AM Charlie Robbins ***@***.*** wrote: Thanks again for the bug report – hopefully the flakiness isn't holding up releases on Node. If it is please let me know and we can make this a higher priority. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#1541 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAecV7X3UqkDXu8beQMjIhbpUIhMV6aVks5u0ToegaJpZM4Y6CeR> .

[indexzero]

Just caught this flakyness on 3.2.0 latest, but only on node@6 and only on Windows (see: Appveyor build.

Are you still seeing this on latest versions of node @MylesBorins or on other platforms?

  1) Logger, ExceptionHandler
       Custom exitOnError function does not exit:
     Uncaught Unknown assertation failure occured, assumed `[]` to deeply equal `[ 'Ignore this error' ]`
  C:\projects\winston\test\log-exception.test.js
                                    v
      66.       assume(child.killed).false();
      67.       assume(stdout).deep.equals(['Ignore this error']);
      68.       child.kill();
                                    ^
          at Assume.equal (node_modules\assume\index.js:676:15)
          at Timeout._onTimeout (test\log-exception.test.js:67:27)

[BridgeAR]

We still encounter the very same failure. The failure is platform independent.

See e.g., https://ci.nodejs.org/view/Node.js-citgm/job/citgm-smoker/2142/nodes=debian9-64/testReport/junit/(root)/citgm/winston_v3_2_1/ (available ~7 days)

[BridgeAR]

I just had a look at the test and it seems likely that something could be written to stderr instead of stdout. This should probably be tested as well.