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

joyeecheung · 2018-01-16T22:13:14Z

Version: master
Platform: windows, linux, arm(?)
Subsystem: async_wrap

Opening a separate issue for the flake reported in #13020 (comment) , I have not seem it for a while but tonight it has come back in different unrelated PRs.

Sample:

https://ci.nodejs.org/job/node-test-commit-linux/15590/nodes=alpine37-container-x64/console
https://ci.nodejs.org/job/node-test-binary-windows/14242/COMPILED_BY=vs2017,RUNNER=win10,RUN_SUBSET=3/console

not ok 1953 sequential/test-async-wrap-getasyncid
  ---
  duration_ms: 0.356
  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/alpine37-container-x64/test/common/index.js:497:10)
        at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/alpine37-container-x64/test/sequential/test-async-wrap-getasyncid.js:19:35)
        at Module._compile (module.js:660:30)
        at Object.Module._extensions..js (module.js:671:10)
        at Module.load (module.js:577:32)
        at tryModuleLoad (module.js:517:12)
        at Function.Module._load (module.js:509:3)
        at Function.Module.runMain (module.js:701:10)
        at startup (bootstrap_node.js:194:16)
  ...

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

tniessen · 2018-01-17T11:33:27Z

Also here (Alpine) and here (Windows 10).

BridgeAR · 2018-01-17T21:12:38Z

Closing as duplicate of #13020

joyeecheung · 2018-01-18T00:06:21Z

@BridgeAR This issue appears after the fix of #13020 landed, see #13020 (comment) and #13020 (comment)

joyeecheung · 2018-01-18T00:08:07Z

@BridgeAR I'll close the original issue. Have not seen a CRASHED in this test in these two months so we probably don't need to open a separate issue for #13020 (comment)

joyeecheung · 2018-01-18T03:57:28Z

This is similar to #16210, both beforeExit being emitted twice

apapirovski · 2018-01-18T13:34:14Z

@joyeecheung I have a strong feeling this might be related to eca73a2 or 791975d — this only started failing after those commits landed and at a quick glance, the test does use node_file.cc in a number of tests.

joyeecheung · 2018-01-18T16:01:52Z

@apapirovski The last CI run of eca73a2 was https://ci.nodejs.org/job/node-test-pull-request/12540/, which did not contain this flake. The CI run before 791975d landed was https://ci.nodejs.org/job/node-test-pull-request/12562/ (for another PR ) and there was already this flake...still investigating before those CI runs expired

joyeecheung · 2018-01-18T16:06:04Z

I think the flake first appeared in https://ci.nodejs.org/job/node-test-pull-request/12562/ for #18186 (has not yet landed), and it was rebasing onto 316b5ef

joyeecheung · 2018-01-18T16:08:00Z

Wait...I think I've seen one of the tests in 316b5ef failed on my mac this week (by looking at my out/Release/node shell history, I ran out/Release/node /Users/joyee/projects/node/test/addons-napi/test_typedarray/test.js because it failed). I was never able to reproduce it after make test-addons-napi-clean, so I thought it's probably something related to stale addon tests

joyeecheung · 2018-01-18T16:25:51Z

FLAKY: https://ci.nodejs.org/job/node-test-pull-request/12563/
refs/pull/17914/head -> 316b5ef
https://ci.nodejs.org/job/node-test-commit-linux/15590/nodes=alpine34-container-x64/console
(There are more)

FLAKY: https://ci.nodejs.org/job/node-test-pull-request/12562/
refs/pull/18186/head -> 316b5ef
https://ci.nodejs.org/job/node-test-binary-windows/14242/COMPILED_BY=vs2017,RUNNER=win10,RUN_SUBSET=3/console

PASS (different flake): https://ci.nodejs.org/job/node-test-pull-request/12561/
refs/pull/17615/head -> 4319780

FLAKY: https://ci.nodejs.org/job/node-test-pull-request/12560/
refs/pull/17914/head -> 316b5ef
https://ci.nodejs.org/job/node-test-commit-linux/15590/nodes=alpine34-container-x64/console
(There are more)

The flake did not appear in CI runs prior to 12560

PASS: https://ci.nodejs.org/job/node-test-pull-request/12559/
refs/pull/18182/head -> f75bc2c

12558 is targeting v8.x-staging
12557 failures had something to do with the PR

PASS: https://ci.nodejs.org/job/node-test-pull-request/12556/
refs/pull/17581/head -> 8229fc0

PASS: https://ci.nodejs.org/job/node-test-pull-request/12555/
refs/pull/17581/head -> 8229fc0

apapirovski · 2018-01-18T16:34:46Z

Ok, I know this is pushing it... but is there any way that https://ci.nodejs.org/job/node-test-pull-request/12562/ was wrong about what it was rebased on? It's the only outlier that doesn't point to the problem being with #17914 — the timestamps even align.

The other commit literally has nothing to do with the code being tested... :(

joyeecheung · 2018-01-18T16:40:56Z

The git-rebase log of https://ci.nodejs.org/job/node-test-pull-request/12562/

+ git rev-parse HEAD
85a4230b32d9efb33733a623b7348b090bf1268d
+ git rev-parse 316b5efd6b02379a490ce62c31a13122729ff1dd
316b5efd6b02379a490ce62c31a13122729ff1dd
+ git rebase 316b5efd6b02379a490ce62c31a13122729ff1dd
First, rewinding head to replay your work on top of it...
Applying: util: implement util.getErrorName()
Auto packing the repository in background for optimum performance.
See "git help gc" for manual housekeeping.
error: The last gc run reported the following. Please correct the root cause
and remove .git/gc.log.
Automatic cleanup will not be performed until the file is removed.

error: pack-objects died of signal 15
error: failed to run repack

[git-rebase] $ /bin/sh -xe /tmp/jenkins3416429728392910523.sh
+ git checkout -B jenkins-node-test-commit-windows-fanned-14926
Switched to a new branch 'jenkins-node-test-commit-windows-fanned-14926'
+ grep -q ^github.com /home/iojs/.ssh/known_hosts
+ git push git@github.com:janeasystems/node_binary_tmp.git +jenkins-node-test-commit-windows-fanned-14926
To git@github.com:janeasystems/node_binary_tmp.git
 * [new branch]      jenkins-node-test-commit-windows-fanned-14926 -> jenkins-node-test-commit-windows-fanned-14926

Also there wasn't this flake in the CI run of #18037

joyeecheung · 2018-01-18T16:43:36Z

We should do some stress tests on 316b5ef and 791975d

apapirovski · 2018-01-18T16:44:33Z

Ok... a shot in the dark: what if we have two different bugs here. Because the main issue occurring now is on alpine but that one issue above is on Windows. So perhaps #17914 introduced a more frequent failure on alpine but we also have some other failure that happens very infrequently.

joyeecheung · 2018-01-18T16:46:25Z

There was also #13020 (comment) which has the same error stack trace and it's on arm, although it has not appeared for a long time so I am not sure if that's related or not

apapirovski · 2018-01-18T16:50:25Z

I suppose we could also consider #18144 as the culprit, even though its CI didn't have any issues. *shrug*

joyeecheung · 2018-01-18T17:24:37Z

No idea how to fire sequential stress tests on sha's...opened #18238 cause it's easier to run CIs

joyeecheung · 2018-01-22T11:10:31Z

It showed up again...this was rebased onto 8803b69

https://ci.nodejs.org/job/node-test-commit-linux/15734/nodes=ubuntu1710-x64/console

not ok 1932 sequential/test-async-wrap-getasyncid
  ---
  duration_ms: 0.340
  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/ubuntu1710-x64/test/common/index.js:497:10)
        at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1710-x64/test/sequential/test-async-wrap-getasyncid.js:20:35)
        at Module._compile (module.js:660:30)
        at Object.Module._extensions..js (module.js:671:10)
        at Module.load (module.js:577:32)
        at tryModuleLoad (module.js:517:12)
        at Function.Module._load (module.js:509:3)
        at Function.Module.runMain (module.js:701:10)
        at startup (bootstrap_node.js:194:16)
  ...

apapirovski · 2018-01-22T16:14:05Z

FWIW I've done some preliminary debugging, the loop is being kept alive because there's a uv_close being called on some handle within the main event loop. Should be a good starting point if anyone wants to dig in.

apapirovski · 2018-01-22T21:54:35Z

Edit: Ignore me for now... I can't even tell if this is actually cares_wrap or not...

Since the `DestroyAsyncIdsCallback` in Node.js can be scheduled as a result of GC, that means that it can accidentally keep the event loop open when it shouldn't. Replace `SetImmediate` with the newly introduced `SetUnrefImmediate` and in addition introduce RunBeforeExit callbacks, of which `DestroyAsyncIdsCallback` is now the first. These callbacks will run before the `beforeExit` event is emitted (which will now only be emitted if the event loop is still not active). PR-URL: nodejs#18241 Fixes: nodejs#18190 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Andreas Madsen <amwebdk@gmail.com>

apapirovski · 2018-06-01T15:07:10Z

If anyone wants to help out, please have a look at the now closed #18307 and suggest better ways of accomplishing this. Or if you believe the original PR was good enough, let me know.

Instead of relying on garbage collection to close the handle, manage its state more explicitly. PR-URL: #21093 Fixes: #18190 Refs: #18307 Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

PR-URL: #21093 Fixes: #18190 Refs: #18307 Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

Instead of relying on garbage collection to close the timer handle, manage its state more explicitly. PR-URL: #21093 Fixes: #18190 Refs: #18307 Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

Instead of relying on garbage collection to close the handle, manage its state more explicitly. PR-URL: #21093 Fixes: #18190 Refs: #18307 Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

PR-URL: #21093 Fixes: #18190 Refs: #18307 Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

Instead of relying on garbage collection to close the timer handle, manage its state more explicitly. PR-URL: #21093 Fixes: #18190 Refs: #18307 Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

Instead of relying on garbage collection to close the handle, manage its state more explicitly. PR-URL: #21093 Fixes: #18190 Refs: #18307 Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

PR-URL: #21093 Fixes: #18190 Refs: #18307 Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>

joyeecheung added test Issues and PRs related to the tests. async_wrap flaky-test Issues and PRs related to the tests with unstable failures on the CI. labels Jan 16, 2018

kfarnung mentioned this issue Jan 17, 2018

build: update lint-cpp on Windows #18012

Closed

2 tasks

BridgeAR closed this as completed Jan 17, 2018

joyeecheung reopened this Jan 18, 2018

joyeecheung added the windows Issues and PRs related to the Windows platform. label Jan 18, 2018

joyeecheung mentioned this issue Jan 18, 2018

fs: fix options.end of fs.ReadStream() #18121

Closed

4 tasks

joyeecheung mentioned this issue Jan 18, 2018

Revert #17914 #18238

Closed

4 tasks

apapirovski mentioned this issue Jan 18, 2018

async_wrap: schedule destroy hook as unref #18241

Closed

3 tasks

apapirovski closed this as completed in 8803b69 Jan 21, 2018

joyeecheung reopened this Jan 22, 2018

apapirovski mentioned this issue Jan 23, 2018

src: schedule unref immediate for uv_close in destructors #18307

Closed

2 tasks

maclover7 closed this as completed Jan 26, 2018

BridgeAR reopened this Jan 26, 2018

apapirovski mentioned this issue Jun 2, 2018

src: manage handles more explicitly in cares_wrap, node_stat_watcher #21093

Closed

3 tasks

apapirovski closed this as completed in d6bdfac Jun 10, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

joyeecheung commented Jan 16, 2018 •

edited

Loading

tniessen commented Jan 17, 2018

BridgeAR commented Jan 17, 2018

joyeecheung commented Jan 18, 2018 •

edited

Loading

joyeecheung commented Jan 18, 2018

joyeecheung commented Jan 18, 2018

apapirovski commented Jan 18, 2018

joyeecheung commented Jan 18, 2018 •

edited

Loading

joyeecheung commented Jan 18, 2018

joyeecheung commented Jan 18, 2018 •

edited

Loading

joyeecheung commented Jan 18, 2018 •

edited

Loading

apapirovski commented Jan 18, 2018

joyeecheung commented Jan 18, 2018

joyeecheung commented Jan 18, 2018

apapirovski commented Jan 18, 2018

joyeecheung commented Jan 18, 2018

apapirovski commented Jan 18, 2018 •

edited

Loading

joyeecheung commented Jan 18, 2018

joyeecheung commented Jan 22, 2018

apapirovski commented Jan 22, 2018

apapirovski commented Jan 22, 2018 •

edited

Loading

apapirovski commented Jun 1, 2018

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

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

Comments

joyeecheung commented Jan 16, 2018 • edited Loading

tniessen commented Jan 17, 2018

BridgeAR commented Jan 17, 2018

joyeecheung commented Jan 18, 2018 • edited Loading

joyeecheung commented Jan 18, 2018

joyeecheung commented Jan 18, 2018

apapirovski commented Jan 18, 2018

joyeecheung commented Jan 18, 2018 • edited Loading

joyeecheung commented Jan 18, 2018

joyeecheung commented Jan 18, 2018 • edited Loading

joyeecheung commented Jan 18, 2018 • edited Loading

apapirovski commented Jan 18, 2018

joyeecheung commented Jan 18, 2018

joyeecheung commented Jan 18, 2018

apapirovski commented Jan 18, 2018

joyeecheung commented Jan 18, 2018

apapirovski commented Jan 18, 2018 • edited Loading

joyeecheung commented Jan 18, 2018

joyeecheung commented Jan 22, 2018

apapirovski commented Jan 22, 2018

apapirovski commented Jan 22, 2018 • edited Loading

apapirovski commented Jun 1, 2018

joyeecheung commented Jan 16, 2018 •

edited

Loading

joyeecheung commented Jan 18, 2018 •

edited

Loading

joyeecheung commented Jan 18, 2018 •

edited

Loading

joyeecheung commented Jan 18, 2018 •

edited

Loading

joyeecheung commented Jan 18, 2018 •

edited

Loading

apapirovski commented Jan 18, 2018 •

edited

Loading

apapirovski commented Jan 22, 2018 •

edited

Loading