Investigate flaky test-tls-socket-close on macOS

[Trott]

• Version: v8.0.0-pre
• Platform: macOS
• Subsystem: test

From https://ci.nodejs.org/job/node-test-commit-osx/9995/nodes=osx1010/console:

not ok 1205 parallel/test-tls-socket-close
  ---
  duration_ms: 0.243
  severity: fail
  stack: |-
    events.js:182
          throw er; // Unhandled 'error' event
          ^
    
    Error: read ECONNRESET
        at exports._errnoException (util.js:1026:11)
        at TLSWrap.onread (net.js:607:25)

I was able to replicate this with:

$ tools/test.py --repeat 64 -j 16 test/parallel/test-tls-socket-close.js 
=== release test-tls-socket-close ===                    
Path: parallel/test-tls-socket-close
events.js:182
      throw er; // Unhandled 'error' event
      ^

Error: read ECONNRESET
    at exports._errnoException (util.js:1026:11)
    at TLSWrap.onread (net.js:607:25)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-tls-socket-close.js
[00:03|% 100|+  63|-   1]: Done 
$

So it's possible the solution is to move it to sequential. But it's also possible that this is a race condition somewhere in the code.

[sebastianplesciuc]

Just a very uninformed guess. I was able to replicate the issue using the command you mention. If I move this code https://github.com/nodejs/node/blob/master/test/parallel/test-tls-socket-close.js#L27-L58 into the tls.createServer() callback I am no longer able to replicate the issue.

[Trott]

@sebastianplesciuc Thanks for trying to figure this one out! Unfortunately, that change invalidates the test as Node.js 7.7.3 no longer segfaults on that test if that change is made.

[sebastianplesciuc]

Running with export NODE_DEBUG=net yields the following:

NET 24869: setupListenHandle null 0 4 0 undefined
NET 24869: setupListenHandle: create a handle
NET 24869: bind to ::
NET 24869: pipe false undefined
NET 24869: connect: find host localhost
NET 24869: connect: dns options { family: undefined, hints: 1024 }
NET 24869: _read
NET 24869: _read wait for connection
NET 24869: afterConnect
NET 24869: _read
NET 24869: Socket._read readStart
NET 24869: onconnection
NET 24869: _read
NET 24869: Socket._read readStart
NET 24869: _read
NET 24869: afterWrite 0
NET 24869: afterWrite call cb
NET 24869: _onTimeout
NET 24869: destroy
NET 24869: close
NET 24869: close handle
NET 24869: has server
NET 24869: SERVER _emitCloseIfDrained
NET 24869: SERVER handle? true   connections? 0
NET 24869: onread -54
NET 24869: destroy
NET 24869: close
NET 24869: close handle
events.js:182
      throw er; // Unhandled 'error' event
      ^

Error: read ECONNRESET
    at exports._errnoException (util.js:1026:11)
    at TLSWrap.onread (net.js:607:25)

I don't understand it yet, but I thought it might help someone who can.

[Trott]

Still a thing:

https://ci.nodejs.org/job/node-test-commit-osx/10336/nodes=osx1010/console

not ok 1276 parallel/test-tls-socket-close
  ---
  duration_ms: 0.164
  severity: fail
  stack: |-
    events.js:182
          throw er; // Unhandled 'error' event
          ^
    
    Error: read ECONNRESET
        at exports._errnoException (util.js:1012:11)
        at TLSWrap.onread (net.js:607:25)
  ...

[Trott]

Adding an error listener that ignores ECONNRESET makes the test reliable while still seg-faulting as expected on Node.js v7.7.3. Race condition, I suppose. Quite possibly unavoidable (if we want to keep the segfault on relevant versions of Node.js, which we do because it's the whole point of the test). PR coming momentarily.

[Trott]

PR to fix: #13529