test: investigate - async-hooks/test-graph.signal

[refack]

• Version: master
• Platform: linux
• Subsystem: async_hooks

https://ci.nodejs.org/job/node-test-commit-linux/11523/nodes=centos5-64

not ok 26 async-hooks/test-graph.signal
  ---
  duration_ms: 0.155
  severity: fail
  stack: |-
    Mismatched onsigusr2 function calls. Expected exactly 2, actual 0.
        at Object.exports.mustCall (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-64/test/common/index.js:475:10)
        at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-64/test/async-hooks/test-graph.signal.js:16:30)
        at Module._compile (module.js:573:30)
        at Object.Module._extensions..js (module.js:584:10)
        at Module.load (module.js:507:32)
        at tryModuleLoad (module.js:470:12)
        at Function.Module._load (module.js:462:3)
        at Function.Module.runMain (module.js:609:10)
        at startup (bootstrap_node.js:158:16)
  ...

code

...
hooks.enable();
process.on('SIGUSR2', common.mustCall(onsigusr2, 2));

let count = 0;
exec(`kill -USR2 ${process.pid}`);
...

/cc @nodejs/async_hooks @Fishrock123 @thlorenz

[refack]

Making sure it's just a flake: https://ci.nodejs.org/job/node-test-commit-linux/11526/

[BridgeAR]

@refack do you still know the outcome of that CI?

@nodejs/async_hooks it would be great if you could have a look at this. Having a green CI for the next Code & Learn would be really neat!

[refack]

It is a flake (did not reproduce under normal load).

[Trott]

https://ci.nodejs.org/job/node-test-commit-linux/14214/nodes=centos7-64/consoleFull:

not ok 27 async-hooks/test-graph.signal
  ---
  duration_ms: 0.205
  severity: fail
  stack: |-
    Mismatched onsigusr2Again function calls. Expected exactly 1, actual 0.
        at Object.exports.mustCall (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64/test/common/index.js:490:10)
        at process.onsigusr2 (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64/test/async-hooks/test-graph.signal.js:30:34)
        at process.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64/test/common/index.js:522:15)
        at process.emit (events.js:159:13)
        at Signal.wrap.onsignal (internal/process.js:198:44)

[Trott]

ubuntu1604_sharedlibs_fips20_x64 too:

https://ci.nodejs.org/job/node-test-commit-linux-linked/nodes=ubuntu1604_sharedlibs_fips20_x64/620/consoleFull

03:19:01 not ok 27 async-hooks/test-graph.signal
03:19:01   ---
03:19:01   duration_ms: 0.255
03:19:01   severity: fail
03:19:01   stack: |-
03:19:01     Mismatched onsigusr2Again function calls. Expected exactly 1, actual 0.
03:19:01         at Object.exports.mustCall (/home/iojs/build/workspace/node-test-commit-linux-linked/nodes/ubuntu1604_sharedlibs_fips20_x64/test/common/index.js:488:10)
03:19:01         at process.onsigusr2 (/home/iojs/build/workspace/node-test-commit-linux-linked/nodes/ubuntu1604_sharedlibs_fips20_x64/test/async-hooks/test-graph.signal.js:30:34)
03:19:01         at process.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux-linked/nodes/ubuntu1604_sharedlibs_fips20_x64/test/common/index.js:522:15)
03:19:01         at process.emit (events.js:126:13)
03:19:01         at Signal.wrap.onsignal (internal/process.js:198:44)
03:19:01   ...

[Trott]

Stress test under load (96 concurrent processes): https://ci.nodejs.org/job/node-stress-single-test/1556/nodes=centos5-64/

(UPDATE: clean)

[Trott]

Now trying a stress test without load, because wondering if maybe it's when something happens too fast or something:

https://ci.nodejs.org/job/node-stress-single-test/1557/nodes=centos5-64/console

(UPDATE: clean)

[Trott]

My theory at this point is that exec being asynchronous and/or kill returns control to the caller before the target of the signal has responded to it, and nothing is keeping the event loop open, so there's no reason the process just can't exit without ever receiving the signal.

If that makes sense, the solution might be to use an interval or something to keep the event loop open. Will experiment with that, but would prefer to be able to reproduce first...

[Trott]

Seeing if I have any better luck with a centos7-64 stress test:

1 process: https://ci.nodejs.org/job/node-stress-single-test/1558/nodes=centos7-64/

96 processes: https://ci.nodejs.org/job/node-stress-single-test/1559/nodes=centos7-64/

[Trott]

Hooray! The CentOS7-64 with 96 simultaneous processes is showing failures! So now I can try out a fix...

not ok 1745 async-hooks/test-graph.signal
  ---
  duration_ms: 8.664
  severity: fail
  stack: |-
    Mismatched onsigusr2Again function calls. Expected exactly 1, actual 0.
        at Object.exports.mustCall (/home/iojs/build/workspace/node-stress-single-test/nodes/centos7-64/test/common/index.js:488:10)
        at process.onsigusr2 (/home/iojs/build/workspace/node-stress-single-test/nodes/centos7-64/test/async-hooks/test-graph.signal.js:30:34)
        at process.<anonymous> (/home/iojs/build/workspace/node-stress-single-test/nodes/centos7-64/test/common/index.js:522:15)
        at process.emit (events.js:126:13)
        at Signal.wrap.onsignal (internal/process.js:198:44)

[Trott]

Proposed fix: #17509