Flaky test-async-wrap-uncaughtexception #16210

joyeecheung · 2017-10-15T02:35:43Z

Version: master
Platform: Windows
Subsystem: test

I have seen multiple errors from this one on Windows this week. sample

not ok 35 parallel/test-async-wrap-uncaughtexception
  ---
  duration_ms: 0.337
  severity: fail
  stack: |-
    Mismatched <anonymous> function calls. Expected exactly 1, actual 2.
        at Object.exports.mustCall (c:\workspace\node-test-binary-windows\COMPILED_BY\vs2015\RUNNER\win2008r2-vs2017\RUN_SUBSET\0\test\common\index.js:486:10)
        at Object.<anonymous> (c:\workspace\node-test-binary-windows\COMPILED_BY\vs2015\RUNNER\win2008r2-vs2017\RUN_SUBSET\0\test\parallel\test-async-wrap-uncaughtexception.js:14:33)
        at Module._compile (module.js:599:30)
        at Object.Module._extensions..js (module.js:610:10)
        at Module.load (module.js:518:32)
        at tryModuleLoad (module.js:481:12)
        at Function.Module._load (module.js:473:3)
        at Function.Module.runMain (module.js:640:10)
        at startup (bootstrap_node.js:187:16)

The text was updated successfully, but these errors were encountered:

joyeecheung · 2017-10-15T02:36:21Z

cc @nodejs/async_hooks @nodejs/platform-windows

Trott · 2017-10-15T04:14:55Z

This is happening pretty much constantly as of about 12 hours ago. Yikes! I don't see anything obvious that has landed that would cause this.

@nodejs/testing @nodejs/build

AndreasMadsen · 2017-10-15T07:25:07Z

I've had this issue in #15538 for a long time (6 days). Where it also appears to be unrelated to my changes.

edit: fixed wrong link.

joaocgreis · 2017-10-15T15:26:33Z

This does not seem to be ties to a specific host or set of hosts
This might be tied to compiler. I've only seen this on runs compiled by VS2015 or VCBT2015
I cannot reproduce this locally
I cannot reproduce this with stess tests: https://ci.nodejs.org/view/All/job/node-stress-single-test/1447/, https://ci.nodejs.org/view/All/job/node-stress-single-test/1448/
Investigating one of the affected CI machines, this does never happen when running node directly (cmd or git bash) but always happens when using test.py

addaleax · 2017-10-15T17:18:10Z

Investigating one of the affected CI machines, this does never happen when running node directly (cmd or git bash) but always happens when using test.py

@joaocgreis Taking a guess based on that: This might be because test.py sets up stdio differently than a plain run of Node from the command line, so the stdio objects in Node use different implementations – do you think you could try to verify/disprove that?

joaocgreis · 2017-10-16T04:52:39Z

@addaleax verified. Redirecting both stdout and stderr to a file makes this happen in cmd. Thanks!

How to check stderr type for future reference

Release\node.exe -e "console.log(util.inspect(process.stderr))"
Release\node.exe -e "console.log(util.inspect(process.stderr))" 2>&1 | cat
Release\node.exe -e "console.log(util.inspect(process.stderr))" > file 2>&1 & type file

Some more notes:

The directory where the test is run makes a difference. In the CI machine where I'm running tests, running in c:\workspace\node-test-binary-windows\COMPILED_BY\vs2015\RUNNER\win2012r2\RUN_SUBSET\0 makes this happen every time, but in any parent or subdir it does never happen. Renaming the directories does not seem to matter, apparently only the number of directories does
I can't make this reproduce in a local VM with the same OS and the same binaries generated by CI that fail in the CI worker. Even in the same directory
Current working directory does not seem to influence, running with full path fails in any directory
Moving the whole test (or just the last group of lines) to a setImmediate makes the test pass

So, the error is that beforeExit is running twice in

node/test/parallel/test-async-wrap-uncaughtexception.js

Lines 14 to 19 in 006fdb2

    
           process.on('beforeExit', common.mustCall(() => { 
        
             process.removeAllListeners('uncaughtException'); 
        
             hooks.disable(); 
        
             assert.strictEqual(typeof call_id, 'number'); 
        
             assert.deepStrictEqual(call_log, [1, 1, 1, 1]); 
        
           }));

Can anything there be scheduling more async work?

joaocgreis · 2017-10-16T05:02:08Z

I've changed the workspace directory of node-test-binary-windows (simplified it to c:\workspace\node-test-binary-windows\) and haven't seen this happen since in CI, but this is still an issue.

refack · 2017-10-29T14:55:06Z

Just now: https://ci.nodejs.org/job/node-test-binary-windows/COMPILED_BY=vcbt2015,RUNNER=win10,RUN_SUBSET=3/12350/console

joyeecheung · 2017-10-30T00:45:51Z

I think this is not specific to Windows:

https://ci.nodejs.org/job/node-test-commit-linux/13653/nodes=centos7-64/console
https://ci.nodejs.org/job/node-test-commit-linux/13653/nodes=ubuntu1604-64/console

joyeecheung · 2017-10-30T00:47:03Z

Also I vaguely remember that I have seen this on my macbook, but it does not reproduce much.

Trott · 2017-10-30T02:13:34Z

Happened twice in a row on Windows 10 in CI:

https://ci.nodejs.org/job/node-test-binary-windows/12364/COMPILED_BY=vcbt2015,RUNNER=win10,RUN_SUBSET=3/console
https://ci.nodejs.org/job/node-test-binary-windows/12365/COMPILED_BY=vcbt2015,RUNNER=win10,RUN_SUBSET=3/console:

not ok 36 parallel/test-async-wrap-uncaughtexception
  ---
  duration_ms: 0.188
  severity: fail
  stack: |-
    Mismatched <anonymous> function calls. Expected exactly 1, actual 2.
        at Object.exports.mustCall (c:\workspace\node-test-binary-windows\test\common\index.js:501:10)
        at Object.<anonymous> (c:\workspace\node-test-binary-windows\test\parallel\test-async-wrap-uncaughtexception.js:14:33)
        at Module._compile (module.js:617:30)
        at Object.Module._extensions..js (module.js:628:10)
        at Module.load (module.js:536:32)
        at tryModuleLoad (module.js:479:12)
        at Function.Module._load (module.js:471:3)
        at Function.Module.runMain (module.js:658:10)
        at startup (bootstrap_node.js:191:16)

Trott · 2017-10-30T02:43:18Z

Can anything there be scheduling more async work?

process.removeAllListeners() emits removeListener events, so that may be scheduling more work, maybe?

If we're pretty sure the being-emitted-twice thing is not actually a bug but dependent on the state of the machine, easiest fix might be to use process.once() instead. I'll submit a PR now-ish...

It's possible for `beforeExit` to be emitted more than once if work is scheduled by its listeners. Accommodate this fact in the test. Fixes: nodejs#16210

Trott · 2017-10-30T02:51:07Z

Fix (maybe?) in #16598

refack · 2017-10-30T21:33:37Z

Seems like we now have a repro - https://ci.nodejs.org/job/node-stress-single-test/1475/
(Ubuntu1604x64).
All the above clues makes me thing this is a memory corruption bug...

Trott · 2017-11-02T00:15:22Z

git bisect is suggesting that e567402 is the source of this problem.

Here's three CI stress test failures in a row on that commit:

The immediately preceding commit is ab2c351. Here's three CI stress test successes in a row on that commit:

(ping @jasnell)

joyeecheung · 2017-11-02T01:36:57Z

@Trott that commit landed 6 days ago while this issue was opened 18 days ago...I think there could be more to it, might need to audit some crypto error PRs

Trott · 2017-11-02T02:10:20Z

@joyeecheung Urm...hmmm... Maybe that commit caused the failures to happen on ubuntu 1604 which only started failing more recently? Maybe the bug has deeper roots for Windows?

I did the stress testing on Ubuntu so it would go faster, but I guess I may need to take a deep breath, set aside several hours, and do it on Windows....

joyeecheung · 2017-11-02T03:55:50Z

@Trott I looked into e567402 again and AFAICT it does not seem to touch the code path tested in test-async-wrap-uncaughtexception. Maybe we could switch to another async hooks provider in the test to see if the root is in crypto?

Trott · 2017-11-02T13:12:01Z

Hmmm....after 12 hours of nothing but red (presumably due to this issue), Windows is coming back green/yellow/red now...

Trott · 2017-11-02T13:46:44Z

Argh, nope, still a thing, now showing up on fedora24:

https://ci.nodejs.org/job/node-test-commit-linux/13748/nodes=fedora24/console

  ...
not ok 136 parallel/test-async-wrap-uncaughtexception
  ---
  duration_ms: 0.138
  severity: fail
  stack: |-
    Mismatched <anonymous> function calls. Expected exactly 1, actual 2.
        at Object.exports.mustCall (/home/iojs/build/workspace/node-test-commit-linux/nodes/fedora24/test/common/index.js:490:10)
        at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/fedora24/test/parallel/test-async-wrap-uncaughtexception.js:14:33)
        at Module._compile (module.js:641:30)
        at Object.Module._extensions..js (module.js:652:10)
        at Module.load (module.js:560:32)
        at tryModuleLoad (module.js:503:12)
        at Function.Module._load (module.js:495:3)
        at Function.Module.runMain (module.js:682:10)
        at startup (bootstrap_node.js:191:16)

joyeecheung · 2017-11-02T15:06:02Z

BTW I have seen this a few times this week on my macbook, but have never been able to reproduce reliably. It only shows up when I run the tests in parallel.

Trott · 2017-11-02T17:02:03Z

I'm worried about this one at Code + Learn next week because I can totally imagine a third of the room having the test fail locally or something like that....

jasnell · 2017-11-02T17:05:22Z

FYI: #16692

refack · 2017-11-02T17:10:28Z

I'm worried about this one at Code + Learn next week because I can totally imagine a third of the room having the test fail locally or something like that....

Alternative: Marking as flaky #16694 PR

@jasnell RE: #16692 we see either a regression between 8.6.0 and 8.7.0 or some level of non-determinism, so IMHO we shouldn't force the test to pass and so hide the bug

`parallel/test-async-wrap-uncaughtexception.js` has become flaky. At this time investigating the cause is still on going, but this issue become has prevalent. In order to restore CI status to be relevant, this marks the test as explicitly FLAKY. PR-URL: nodejs#16694 Refs: nodejs#16210 Reviewed-By: Rich Trott <rtrott@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Myles Borins <myles.borins@gmail.com>

MylesBorins · 2017-11-03T03:54:13Z

I created a new project to track flakes on CI and put a variety of related issues to this test in a column. Please feel free to add more related issues / prs

Trott · 2017-11-04T00:12:16Z

FWIW, moving this test to sequential does not solve the problem (tried it in #16733) so having too much other stuff happening on the system is unlikely to be the problem.

Trott · 2017-11-04T02:37:19Z

I can replicate this if I use the inspector and step into or out of stuff.

Trott · 2017-11-04T06:30:25Z

I'm starting to suspect that the extra beforeExit call might be caused either by the changes starting in the block starting on line 4708 of src/node.cc in f27b5e4bdaa or (more likely, perhaps?) the V8 changes that commit is trying to accommodate. Haven't been able to pin it down yet, but if a C++ person wants to do some debugging, please do. :-D (And, of course, I could be totally wrong in my suspicion, just like I've been a multiple times already with this issue.)

addaleax · 2017-11-04T20:19:49Z

@Trott The only V8 functionality I know of that will require the change is asynchronous WASM compilation, which is currently behind a flag even in V8 master.

It might be related to f27b5e4, but I’d be surprised since all I can see V8 doing when the test is being executed is scheduling background tasks, no foreground or delayed foreground tasks…

Refs: nodejs#16210

`parallel/test-async-wrap-uncaughtexception.js` has become flaky. At this time investigating the cause is still on going, but this issue become has prevalent. In order to restore CI status to be relevant, this marks the test as explicitly FLAKY. PR-URL: nodejs#16694 Refs: nodejs#16210 Reviewed-By: Rich Trott <rtrott@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Myles Borins <myles.borins@gmail.com>

Do not let an internal handle keep the event loop alive. Fixes: nodejs#16210

joyeecheung · 2017-12-27T13:03:13Z

This has been fixed and can be closed now.

joyeecheung added flaky-test Issues and PRs related to the tests with unstable failures on the CI. test Issues and PRs related to the tests. labels Oct 15, 2017

AndreasMadsen added async_wrap async_hooks Issues and PRs related to the async hooks subsystem. labels Oct 15, 2017

AndreasMadsen mentioned this issue Oct 19, 2017

async-hooks: add trace events to AsyncWrap #15538

Closed

3 tasks

Trott added a commit to Trott/io.js that referenced this issue Oct 30, 2017

test: fix flaky test-async-wrap-uncaughtexception

a200dbb

It's possible for `beforeExit` to be emitted more than once if work is scheduled by its listeners. Accommodate this fact in the test. Fixes: nodejs#16210

Trott mentioned this issue Oct 30, 2017

test: fix flaky test-async-wrap-uncaughtexception #16598

Closed

2 tasks

AndreasMadsen mentioned this issue Oct 30, 2017

async_hooks: enable runtime checks by default #16318

Closed

4 tasks

misterdjules mentioned this issue Oct 30, 2017

deps: update V8 to 6.3 #16271

Closed

2 tasks

seishun mentioned this issue Oct 31, 2017

Last builds lack Windows installers and binaries nodejs/node-v8#19

Closed

yhwang mentioned this issue Nov 2, 2017

src: explicitly register built-in modules #16565

Closed

2 tasks

refack mentioned this issue Nov 3, 2017

test: mark as flaky #16694

Merged

3 tasks

Trott changed the title ~~Flaky test-async-wrap-uncaughtexception on Windows~~ Flaky test-async-wrap-uncaughtexception Nov 4, 2017

This was referenced Nov 4, 2017

test: disable hooks before removing listeners #16739

Closed

test: move hooks.disable() #16740

Closed

addaleax mentioned this issue Nov 4, 2017

test: add simple extra debugging to flaky test (async-wrap-uncaughtexception) #16757

Closed

3 tasks

addaleax added a commit to addaleax/node that referenced this issue Nov 4, 2017

test: add simple extra debugging to flaky test

5f01a9e

Refs: nodejs#16210

addaleax mentioned this issue Nov 4, 2017

src: use unrefed async for GC tracking #16758

Closed

2 tasks

addaleax added a commit to addaleax/node that referenced this issue Nov 11, 2017

src: use unrefed async for GC tracking

808887d

Do not let an internal handle keep the event loop alive. Fixes: nodejs#16210

joyeecheung closed this as completed Dec 27, 2017

joyeecheung mentioned this issue Jan 18, 2018

Investigate flaky sequential/test-async-wrap-getasyncid #18190

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Flaky test-async-wrap-uncaughtexception #16210

Flaky test-async-wrap-uncaughtexception #16210

joyeecheung commented Oct 15, 2017

joyeecheung commented Oct 15, 2017 •

edited

Loading

Trott commented Oct 15, 2017

AndreasMadsen commented Oct 15, 2017 •

edited

Loading

joaocgreis commented Oct 15, 2017

addaleax commented Oct 15, 2017

joaocgreis commented Oct 16, 2017 •

edited

Loading

joaocgreis commented Oct 16, 2017

refack commented Oct 29, 2017

joyeecheung commented Oct 30, 2017

joyeecheung commented Oct 30, 2017

Trott commented Oct 30, 2017

Trott commented Oct 30, 2017

Trott commented Oct 30, 2017

refack commented Oct 30, 2017

Trott commented Nov 2, 2017 •

edited

Loading

joyeecheung commented Nov 2, 2017

Trott commented Nov 2, 2017 •

edited

Loading

joyeecheung commented Nov 2, 2017

Trott commented Nov 2, 2017

Trott commented Nov 2, 2017

joyeecheung commented Nov 2, 2017 •

edited

Loading

Trott commented Nov 2, 2017

jasnell commented Nov 2, 2017

refack commented Nov 2, 2017

MylesBorins commented Nov 3, 2017

Trott commented Nov 4, 2017

Trott commented Nov 4, 2017 •

edited

Loading

Trott commented Nov 4, 2017 •

edited

Loading

addaleax commented Nov 4, 2017

joyeecheung commented Dec 27, 2017

Flaky test-async-wrap-uncaughtexception #16210

Flaky test-async-wrap-uncaughtexception #16210

Comments

joyeecheung commented Oct 15, 2017

joyeecheung commented Oct 15, 2017 • edited Loading

Trott commented Oct 15, 2017

AndreasMadsen commented Oct 15, 2017 • edited Loading

joaocgreis commented Oct 15, 2017

addaleax commented Oct 15, 2017

joaocgreis commented Oct 16, 2017 • edited Loading

joaocgreis commented Oct 16, 2017

refack commented Oct 29, 2017

joyeecheung commented Oct 30, 2017

joyeecheung commented Oct 30, 2017

Trott commented Oct 30, 2017

Trott commented Oct 30, 2017

Trott commented Oct 30, 2017

refack commented Oct 30, 2017

Trott commented Nov 2, 2017 • edited Loading

joyeecheung commented Nov 2, 2017

Trott commented Nov 2, 2017 • edited Loading

joyeecheung commented Nov 2, 2017

Trott commented Nov 2, 2017

Trott commented Nov 2, 2017

joyeecheung commented Nov 2, 2017 • edited Loading

Trott commented Nov 2, 2017

jasnell commented Nov 2, 2017

refack commented Nov 2, 2017

MylesBorins commented Nov 3, 2017

Trott commented Nov 4, 2017

Trott commented Nov 4, 2017 • edited Loading

Trott commented Nov 4, 2017 • edited Loading

addaleax commented Nov 4, 2017

joyeecheung commented Dec 27, 2017

joyeecheung commented Oct 15, 2017 •

edited

Loading

AndreasMadsen commented Oct 15, 2017 •

edited

Loading

joaocgreis commented Oct 16, 2017 •

edited

Loading

Trott commented Nov 2, 2017 •

edited

Loading

Trott commented Nov 2, 2017 •

edited

Loading

joyeecheung commented Nov 2, 2017 •

edited

Loading

Trott commented Nov 4, 2017 •

edited

Loading

Trott commented Nov 4, 2017 •

edited

Loading