Repository navigation
Investigate flaky parallel/test-net-write-slow on FreeBSD #7516
Description
Activity
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.372Stress test to confirm it's reproducible via stress test: https://ci.nodejs.org/job/node-stress-single-test/789/nodes=freebsd102-64/console
Failures were both on test-digitalocean-freebsd10-x64-2. Stress test (with no failures yet) is also on test-digitalocean-freebsd10-x64-2. ¯_(ツ)_/¯
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.2953087: 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.5303085: 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.2893084: 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.4133083: 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.408Seems significant that
flushed(which is supposed to get up to 10) never gets past 1 on the failed runs./cc @nodejs/platform-freebsd
Stress test came up clean. I repeat: ¯_(ツ)_/¯
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/
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()forcommonand change theBufferinitialization to the old way (new Buffer()andbuf.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
1000to430, it will sometimes fail, and sometimes succeed.flushedis always4when it fails and I have a 4-processor machine. So that probably means that seeing1on 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
1000to9999and 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.
@Trott both freebsd machines have JOBS=2 set (and have 2 vcpus)
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/
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.279Here 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.506Here 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.3923132:
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.2823135:
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.329Trying something else that probably won't pan out but getting desperate: Running five
node-test-commit-freebsdjobs (3138 - 3142).Hey! That worked! 3138 failed! 3139 succeeded. Other three are yet to run...
3 of the 5 runs had this test fail. That's actually potentially useful...
Test runs of
node-test-commit-freebsdwith the timeout increased tenfold to 9999:- 3146 ✅ PASS (1.508s)
- 3148 ✅ PASS (1.744s)
- 3151 ✅ PASS (1.826s)
- 3156 ✅ PASS (1.540s)
Tests run of
node-test-commit-freebsdwith current master:- 3149 ❌ FAIL (1.391s)
- 3152 ❌ FAIL (1.378s)
- 3153 ❌ FAIL (1.377s)
- 3155 ✅ PASS (1.376s)
- 3158 ❌ FAIL (1.357s)
Good enough for me! PR'ing a change (although I still wonder if this test isn't a candidate for removal).
- added 2 commits that reference this issue
on Jul 6, 2016 - added a commit that references this issue
on Jul 13, 2016 - added 2 commits that reference this issue
on Jul 14, 2016
https://ci.nodejs.org/job/node-test-commit-freebsd/3080/nodes=freebsd10-64/console: