Node: investigate flaky test-inspector-stop-profile-after-done on Windows

Created on 27 Jul 2017 · 16Comments · Source: nodejs/node

Version: v9.0.0-pre
Platform: vs2015-x86,win2008r2
Subsystem: test inspector

https://ci.nodejs.org/job/node-test-binary-windows/10112/RUN_SUBSET=1,VS_VERSION=vs2015-x86,label=win2008r2/console

not ok 388 inspector/test-inspector-stop-profile-after-done
  ---
  duration_ms: 4.313
  severity: fail
  stack: |-
    [err] Debugger listening on ws://127.0.0.1:9229/399ca1a5-7090-4eae-8ad9-15414cae3b60
    [err] For help see https://nodejs.org/en/docs/inspector
    [err] 
    [err] Debugger attached.
    [err] Waiting for the debugger to disconnect...
    [err] 
    SyntaxError: Unexpected end of JSON input
        at JSON.parse (<anonymous>)
        at parseWSFrame (c:\workspace\node-test-binary-windows\RUN_SUBSET\1\VS_VERSION\vs2015-x86\label\win2008r2\test\inspector\inspector-helper.js:76:24)
        at Socket.TestSession.socket.on (c:\workspace\node-test-binary-windows\RUN_SUBSET\1\VS_VERSION\vs2015-x86\label\win2008r2\test\inspector\inspector-helper.js:155:18)
        at emitOne (events.js:115:13)
        at Socket.emit (events.js:210:7)
        at addChunk (_stream_readable.js:252:12)
        at readableAddChunk (_stream_readable.js:239:11)
        at Socket.Readable.push (_stream_readable.js:197:10)
        at TCP.onread (net.js:591:20)

@nodejs/v8-inspector

CI / flaky test inspector test windows

Source

Trott

Most helpful comment

It looks like this was the issue, I've opened a PR: https://github.com/nodejs/node/pull/14596

bzoz on 2 Aug 2017

🎉2

All 16 comments

Hmmm, looks like this may be actually totally not working at all rather than flaky?

https://ci.nodejs.org/job/node-test-binary-windows/10113/RUN_SUBSET=1,VS_VERSION=vs2015,label=win2012r2/console

not ok 388 inspector/test-inspector-stop-profile-after-done
  ---
  duration_ms: 6.723
  severity: fail
  stack: |-
    [err] Debugger listening on ws://127.0.0.1:9229/8f3a9315-ad33-4983-83c9-e1ee04064406
    [err] For help see https://nodejs.org/en/docs/inspector
    [err] 
    [err] Debugger attached.
    [err] Waiting for the debugger to disconnect...
    [err] 
    SyntaxError: Unexpected end of JSON input
        at JSON.parse (<anonymous>)
        at parseWSFrame (c:\workspace\node-test-binary-windows\RUN_SUBSET\1\VS_VERSION\vs2015\label\win2012r2\test\inspector\inspector-helper.js:76:24)
        at Socket.TestSession.socket.on (c:\workspace\node-test-binary-windows\RUN_SUBSET\1\VS_VERSION\vs2015\label\win2012r2\test\inspector\inspector-helper.js:155:18)
        at emitOne (events.js:115:13)
        at Socket.emit (events.js:210:7)
        at addChunk (_stream_readable.js:252:12)
        at readableAddChunk (_stream_readable.js:239:11)
        at Socket.Readable.push (_stream_readable.js:197:10)
        at TCP.onread (net.js:591:20)

@nodejs/platform-windows

Trott on 27 Jul 2017

OK, only two failures in a row, it was working reliably before that, although it's only been landed for a short time.

@nodejs/build in case something's up with the host maybe?

Trott on 27 Jul 2017

I will try a stress test run.

eugeneo on 27 Jul 2017

Still happening with some frequency.

https://ci.nodejs.org/job/node-test-binary-windows/10142/RUN_SUBSET=3,VS_VERSION=vcbt2015,label=win10/console

not ok 388 inspector/test-inspector-stop-profile-after-done
  ---
  duration_ms: 2.510
  severity: fail
  stack: |-
    [err] Debugger listening on ws://127.0.0.1:9229/48004924-ed61-437f-9235-d6a9fa16b51d
    [err] For help see https://nodejs.org/en/docs/inspector
    [err] 
    [err] Debugger attached.
    [err] Waiting for the debugger to disconnect...
    [err] 
    SyntaxError: Unexpected end of JSON input
        at JSON.parse (<anonymous>)
        at parseWSFrame (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\inspector\inspector-helper.js:76:24)
        at Socket.TestSession.socket.on (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\inspector\inspector-helper.js:155:18)
        at emitOne (events.js:115:13)
        at Socket.emit (events.js:210:7)
        at addChunk (_stream_readable.js:252:12)
        at readableAddChunk (_stream_readable.js:239:11)
        at Socket.Readable.push (_stream_readable.js:197:10)
        at TCP.onread (net.js:591:20)

Would like to get #14508 landed so we get better information about what the JSON looks like when it fails.

Trott on 28 Jul 2017

I tried to use the stress test runner in CI - but got some puzzling errors.
Retrying.

On Fri, Jul 28, 2017 at 7:40 AM Rich Trott notifications@github.com wrote:

Still happening with some frequency.

https://ci.nodejs.org/job/node-test-binary-windows/10142/RUN_SUBSET=3,VS_VERSION=vcbt2015,label=win10/console

not ok 388 inspector/test-inspector-stop-profile-after-done ---

duration_ms: 2.510 severity: fail stack: |- [err] Debugger listening on ws://127.0.0.1:9229/48004924-ed61-437f-9235-d6a9fa16b51d
[err] For help see https://nodejs.org/en/docs/inspector    [err]     [err] Debugger attached.    [err] Waiting for the debugger to disconnect...    [err]     SyntaxError: Unexpected end of JSON input        at JSON.parse (<anonymous>)

    at parseWSFrame (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\inspector\inspector-helper.js:76:24)        at Socket.TestSession.socket.on (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\inspector\inspector-helper.js:155:18)

    at emitOne (events.js:115:13)        at Socket.emit (events.js:210:7)        at addChunk (_stream_readable.js:252:12)        at readableAddChunk (_stream_readable.js:239:11)        at Socket.Readable.push (_stream_readable.js:197:10)        at TCP.onread (net.js:591:20)
Would like to get #14508 https://github.com/nodejs/node/pull/14508
landed so we get better information about what the JSON looks like when it
fails.

—
You are receiving this because you are on a team that was mentioned.
Reply to this email directly, view it on GitHub
https://github.com/nodejs/node/issues/14507#issuecomment-318669794, or mute
the thread
https://github.com/notifications/unsubscribe-auth/AARkrbv_QbRz6WWUsAPUzEi78RVXE3tTks5sSfLBgaJpZM4OklEY
.

eugeneo on 28 Jul 2017

100 runs were not flaky: https://ci.nodejs.org/job/node-stress-single-test/1349/nodes=win2012r2/

Will try 1000 runs on win10

eugeneo on 28 Jul 2017

https://ci.nodejs.org/job/node-stress-single-test/1350/nodes=win10/console - I am not sure what the failure here is...

eugeneo on 28 Jul 2017

Still flaky: https://ci.nodejs.org/job/node-test-binary-windows/10187/RUN_SUBSET=3,VS_VERSION=vcbt2015,label=win10/console

not ok 388 inspector/test-inspector-stop-profile-after-done
  ---
  duration_ms: 1.727
  severity: fail
  stack: |-
    [err] Debugger listening on ws://127.0.0.1:9229/34e55786-8bc9-4a04-ac79-6a512c524ee7
    [err] For help see https://nodejs.org/en/docs/inspector
    [err] 
    [err] Debugger attached.
    [err] Waiting for the debugger to disconnect...
    [err] 
    JSON.parse() failed for: 
    SyntaxError: Unexpected end of JSON input
        at JSON.parse (<anonymous>)
        at parseWSFrame (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\inspector\inspector-helper.js:80:20)
        at Socket.TestSession.socket.on (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\inspector\inspector-helper.js:162:18)
        at emitOne (events.js:115:13)
        at Socket.emit (events.js:210:7)
        at addChunk (_stream_readable.js:252:12)
        at readableAddChunk (_stream_readable.js:239:11)
        at Socket.Readable.push (_stream_readable.js:197:10)
        at TCP.onread (net.js:591:20)
  ...

tniessen on 31 Jul 2017

https://ci.nodejs.org/job/node-stress-single-test/1350/nodes=win10/console - I am not sure what the failure here is...

@eugeneo FWIW that's the error:

builtins\x64\builtins-x64.cc(3116): error C2078: too many initializers [c:\workspace\node-stress-single-test\nodes\win10\deps\v8\src\v8_base_2.vcxproj]
builtins\x64\builtins-x64.cc(3117): error C2078: too many initializers [c:\workspace\node-stress-single-test\nodes\win10\deps\v8\src\v8_base_2.vcxproj]

I've seen this happen locally sometimes (I think when it's not a clean build)

refack on 31 Jul 2017

Got it again today. If it's helpful, code was added to log the string for which JSON parse is failing. Looks like it's an empty string.

https://ci.nodejs.org/job/node-test-binary-windows/10196/RUN_SUBSET=3,VS_VERSION=vcbt2015,label=win10/console

not ok 388 inspector/test-inspector-stop-profile-after-done
  ---
  duration_ms: 1.864
  severity: fail
  stack: |-
    [err] Debugger listening on ws://127.0.0.1:9229/3e1b0ec1-10f8-461f-a1ce-2e077e87c9ea
    [err] For help see https://nodejs.org/en/docs/inspector
    [err] 
    [err] Debugger attached.
    [err] Waiting for the debugger to disconnect...
    [err] 
    JSON.parse() failed for: 
    SyntaxError: Unexpected end of JSON input
        at JSON.parse (<anonymous>)
        at parseWSFrame (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\inspector\inspector-helper.js:80:20)
        at Socket.TestSession.socket.on (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\inspector\inspector-helper.js:162:18)
        at emitOne (events.js:115:13)
        at Socket.emit (events.js:210:7)
        at addChunk (_stream_readable.js:252:12)
        at readableAddChunk (_stream_readable.js:239:11)
        at Socket.Readable.push (_stream_readable.js:197:10)
        at TCP.onread (net.js:591:20)

Trott on 31 Jul 2017

https://ci.nodejs.org/job/node-test-binary-windows/10208/RUN_SUBSET=3,VS_VERSION=vcbt2015,label=win10/console

not ok 389 inspector/test-inspector-stop-profile-after-done
  ---
  duration_ms: 3.844
  severity: fail
  stack: |-
    [err] Debugger listening on ws://127.0.0.1:9229/471ca581-1f37-446d-9466-6c05573cc326
    [err] For help see https://nodejs.org/en/docs/inspector
    [err] 
    [err] Debugger attached.
    [err] Waiting for the debugger to disconnect...
    [err] 
    JSON.parse() failed for: 
    SyntaxError: Unexpected end of JSON input
        at JSON.parse (<anonymous>)
        at parseWSFrame (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\inspector\inspector-helper.js:80:20)
        at Socket.TestSession.socket.on (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\inspector\inspector-helper.js:162:18)
        at emitOne (events.js:115:13)
        at Socket.emit (events.js:210:7)
        at addChunk (_stream_readable.js:252:12)
        at readableAddChunk (_stream_readable.js:239:11)
        at Socket.Readable.push (_stream_readable.js:197:10)
        at TCP.onread (net.js:591:20)
  ...

Trott on 1 Aug 2017

Seems to be happening on different flavors of Windows (win10, win2012r2, win2008r2) but only Windows.
¯\_(ツ)_/¯

Trott on 1 Aug 2017

Sorry for not RTFMing but I'm getting timeouts (also when using WebStorm), can anyone offer quick advice?

d:\code\node$ node test\inspector\test-inspector-stop-profile-after-done.js
[err] Debugger listening on ws://127.0.0.1:9229/87931cfe-2e96-490f-926e-a874458ebf8e
[err] For help see https://nodejs.org/en/docs/inspector
[err]
[err] Debugger attached.
[err] Waiting for the debugger to disconnect...
[err]
AssertionError [ERR_ASSERTION]: Messages without response: 5
    at Timeout.setTimeout [as _onTimeout] (d:\code\node\test\inspector\inspector-helper.js:247:16)
    at ontimeout (timers.js:488:11)
    at tryOnTimeout (timers.js:323:5)
    at Timer.listOnTimeout (timers.js:283:5)

refack on 1 Aug 2017

Just showed up

https://ci.nodejs.org/job/node-test-binary-windows/10222/RUN_SUBSET=0,VS_VERSION=vcbt2015,label=win10/console

MylesBorins on 1 Aug 2017

Did some testing, it looks like it is more likely to happen if the machine load is high. Also, I've got it to reproduce more often on win2008 than on win2012 or win2016.

I've added displaying what is in the buffer when it is passed to parseWSFrame in insepecot-helper.js. I've found this: gist1, gist2, gist3.

In all cases, buffer starts with expected 0x81 byte, followed by 0x7F which looks like 'data length is 32-bit' marker. Then it is followed by 8 bytes of binary data, and then JSON text. I guess the error is in this line - it reads only 4 bytes for uint, but moves the bodyOffset by 8. I'll run some test and if it stops reproducing I'll open a PR.

My guess is that with high-load, test runs long enough that it produces enough samples to hit this biggest dataLen marker, and so this is why this test fails intermittently.

bzoz on 2 Aug 2017

👍1

It looks like this was the issue, I've opened a PR: https://github.com/nodejs/node/pull/14596

bzoz on 2 Aug 2017

🎉2

Was this page helpful?

0 / 5 - 0 ratings