Investigate flaky parallel/test-net-write-slow on FreeBSD

[Trott]

https://ci.nodejs.org/job/node-test-commit-freebsd/3080/nodes=freebsd10-64/console:

not ok 688 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1506964/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.352

[Trott]

And again:

https://ci.nodejs.org/job/node-test-commit-freebsd/3107/nodes=freebsd10-64/console:

not ok 688 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1638036/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.372

[Trott]

Stress test to confirm it's reproducible via stress test: https://ci.nodejs.org/job/node-stress-single-test/789/nodes=freebsd102-64/console

[Trott]

Failures were both on test-digitalocean-freebsd10-x64-2. Stress test (with no failures yet) is also on test-digitalocean-freebsd10-x64-2. ¯_(ツ)_/¯

[Trott]

Other recent failures besides 3080 and 3107:

3089: https://ci.nodejs.org/job/node-test-commit-freebsd/3089/nodes=freebsd10-64/console

not ok 687 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1638036/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.295

3087: https://ci.nodejs.org/job/node-test-commit-freebsd/3087/nodes=freebsd10-64/console

  ...
not ok 687 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1769108/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.530

3085: https://ci.nodejs.org/job/node-test-commit-freebsd/3085/nodes=freebsd10-64/console

not ok 688 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1703572/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.289

3084: https://ci.nodejs.org/job/node-test-commit-freebsd/3084/nodes=freebsd10-64/console

  ...
not ok 688 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1375892/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.413

3083: https://ci.nodejs.org/job/node-test-commit-freebsd/3083/nodes=freebsd10-64/console

not ok 687 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1769108/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.408

[Trott]

Seems significant that flushed (which is supposed to get up to 10) never gets past 1 on the failed runs.

/cc @nodejs/platform-freebsd

[Trott]

Stress test came up clean. I repeat: ¯_(ツ)_/¯

[Trott]

Stress test label for FreeBSD has been updated to match that of node-test-pull-request. I don't think it's any different than the test I already ran, but just in case, and because I'm running out of things to try without spinning up my own FreeBSD instance: https://ci.nodejs.org/job/node-stress-single-test/791/nodes=freebsd10-64/

[Trott]

This test was introduced in 0f0af55a after 0.6.10 and before 0.6.11. It was intended to fix nodejs/node-v0.x-archive#2678.

So it should fail in 0.6.10 and pass in 0.6.11 and later.

However, for me, it does not fail in 0.6.10 in its current form. (You'll need to comment out the require() for common and change the Buffer initialization to the old way (new Buffer() and buf.fill(), so not quite its current form but as close as you can get and still run the test.)

The original form fails or succeeds in both 0.6.x versions depending on how the two timeout values are tweaked.

In fact, the same is true of the current form of the test running Node 6.2.2. On my laptop, if I change 1000 to 430, it will sometimes fail, and sometimes succeed. flushed is always 4 when it fails and I have a 4-processor machine. So that probably means that seeing 1 on FreeBSD CI just means it's a single-processor machine. (/cc @joaocgreis @jbergstroem for confirmation?)

A factor of two is not a lot of head room, in my opinion. At this point, I'm not sure if the thing to try is change 1000 to 9999 and see if the problem goes away, or if the thing to do is to remove the test entirely. Thoughts, @nodejs/testing?

/cc @koichik who wrote the test originally, in case there's additional light to be shed.

[jbergstroem]

@Trott both freebsd machines have JOBS=2 set (and have 2 vcpus)

[Trott]

Trying to run on all platforms as a stress test to see if any of them fail: https://ci.nodejs.org/job/node-stress-single-test/792/

[Trott]

Still occurring on FreeBSD but still unable to replicate in stress test. They do seem to cluster. (Could the time of day be relevant? Something else running on those machines at a particular time?)

Here it is in 3118. https://ci.nodejs.org/job/node-test-commit-freebsd/3118/nodes=freebsd10-64/console:

not ok 687 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1572500/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.279

Here it is in 3130. https://ci.nodejs.org/job/node-test-commit-freebsd/3130/nodes=freebsd10-64/console

not ok 687 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1638036/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.506

Here it is in 3131. https://ci.nodejs.org/job/node-test-commit-freebsd/3131/nodes=freebsd10-64/console:

not ok 688 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1638036/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.392

3132:

not ok 683 parallel/test-net-write-slow
# 
# assert.js:90
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1572500/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.282

3135:

not ok 686 parallel/test-net-write-slow
# 
# assert.js:89
#   throw new assert.AssertionError({
#   ^
# AssertionError: flushed: 1, received: 1441428/2000000
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-net-write-slow.js:16:12)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:224:11)
#     at Timer.listOnTimeout (timers.js:198:5)
  ---
  duration_ms: 1.329