test: investigate async-hooks/test-tlswrap

[refack]

• Version: master
• Platform: macOS
• Subsystem: async-hooks,tls

Has been spotted on macOS:

 tools/test.py -j92 --repeat 920 test/async-hooks/test-tlswrap.js 
=== release test-tlswrap ===                    
Path: async-hooks/test-tlswrap
assert.js:43
  throw new errors.AssertionError({
  ^

AssertionError [ERR_ASSERTION]: Checking invocations at stage "client: when client destroyed":
     Called "before" 2 time(s), but expected 3 invocation(s).
    at checkHook (/Users/trott/io.js/test/async-hooks/hook-checks.js:51:14)
    at Array.forEach (<anonymous>)
    at checkInvocations (/Users/trott/io.js/test/async-hooks/hook-checks.js:28:44)
    at tick1 (/Users/trott/io.js/test/async-hooks/test-tlswrap.js:93:5)
    at Immediate.ontick (/Users/trott/io.js/test/async-hooks/tick.js:7:37)
    at runCallback (timers.js:781:20)
    at tryOnImmediate (timers.js:743:5)
    at processImmediate [as _immediateCallback] (timers.js:714:5)
Command: out/Release/node /Users/trott/io.js/test/async-hooks/test-tlswrap.js

[Trott]

Probably race condition. The comment around before line 93 (where the test fails) kind of suggests that too:

    // TODO: why is client not destroyed here even after 5 ticks?
    // or could it be that it isn't actually destroyed until
    // the server is closed?

[mcollina]

I've tested it on 8.2.0 as well, same error.

[targos]

Windows is also affected: https://ci.nodejs.org/job/node-test-binary-windows/11046/RUN_SUBSET=2,VS_VERSION=vs2015-x86,label=win2008r2/console

[BridgeAR]

FreeBSD is also affected https://ci.nodejs.org/job/node-test-commit-freebsd/11775/nodes=freebsd10-64/console

I guess it is system independent.

[BridgeAR]

@nodejs/async_hooks it would be great if this could be looked at.

Having a green CI for the next Code & Learn would be really neat.

[Trott]

I managed to replicate this locally on macOS. Did it by running 96 simultaneous copies of the test. Definitely strengthens the case that this is a race condition...

$ tools/test.py -j 96 --repeat 192 async-hooks/test-tlswrap
=== release test-tlswrap ===                    
Path: async-hooks/test-tlswrap
assert.js:45
  throw new errors.AssertionError({
  ^

AssertionError [ERR_ASSERTION]: Checking invocations at stage "client: when client destroyed":
     Called "before" 2 time(s), but expected 3 invocation(s).
    at checkHook (/Users/trott/io.js/test/async-hooks/hook-checks.js:51:14)
    at Array.forEach (<anonymous>)
    at checkInvocations (/Users/trott/io.js/test/async-hooks/hook-checks.js:28:44)
    at tick1 (/Users/trott/io.js/test/async-hooks/test-tlswrap.js:94:5)
    at Immediate.ontick [as _onImmediate] (/Users/trott/io.js/test/async-hooks/tick.js:7:37)
    at runCallback (timers.js:798:20)
    at tryOnImmediate (timers.js:760:5)
    at processImmediate [as _immediateCallback] (timers.js:731:5)
Command: out/Release/node /Users/trott/io.js/test/async-hooks/test-tlswrap.js
[00:19|% 100|+ 191|-   1]: Done  
$

[Trott]

Hmmm....I see this test uses common.PORT but asynch-hooks tests are run in parallel, so that's a bug (because another test using port 0 could result in a port collision).

[Trott]

PR to fix the common.PORT thing in #15742 but unsurprisingly that change doesn't fix this issue.

[Trott]

Proposed fix for this issue: #15744

[refack]

@Trott did you manage to repro on CI?

[Trott]

@Trott did you manage to repro on CI?

@refack Yes. https://ci.nodejs.org/job/node-stress-single-test/1436/nodes=osx1010/console