investigate flaky test-inspector-stop-profile-after-done on Windows #14507

Trott · 2017-07-26T22:42:02Z

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

Trott · 2017-07-26T22:44:20Z

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 · 2017-07-26T22:47:25Z

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?

eugeneo · 2017-07-26T22:53:22Z

I will try a stress test run.

If JSON.parse() fails, print a message showing the JSON that failed to parse. This is to help with debugging a current test failure on CI. Refs: nodejs#14507

Trott · 2017-07-28T14:39:56Z

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.

eugeneo · 2017-07-28T17:41:30Z

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 ***@***.***> 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 <#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 <#14507 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AARkrbv_QbRz6WWUsAPUzEi78RVXE3tTks5sSfLBgaJpZM4OklEY> .

eugeneo · 2017-07-28T18:20:26Z

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

Will try 1000 runs on win10

eugeneo · 2017-07-28T19:08:06Z

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

If JSON.parse() fails, print a message showing the JSON that failed to parse. This is to help with debugging a current test failure on CI. PR-URL: nodejs#14508 Ref: nodejs#14507 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Luigi Pinca <[email protected]> Reviewed-By: Refael Ackermann <[email protected]>

If JSON.parse() fails, print a message showing the JSON that failed to parse. This is to help with debugging a current test failure on CI. PR-URL: #14508 Ref: #14507 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Luigi Pinca <[email protected]> Reviewed-By: Refael Ackermann <[email protected]>

tniessen · 2017-07-31T10:30:45Z

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)
  ...

refack · 2017-07-31T12:12:48Z

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)

Trott · 2017-07-31T13:49:10Z

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 · 2017-08-01T17:07:32Z

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 · 2017-08-01T17:08:58Z

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

refack · 2017-08-01T17:21:59Z

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)

MylesBorins · 2017-08-01T18:03:44Z

Just showed up

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

bzoz · 2017-08-02T12:09:38Z

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.

Fix a bug when messages bigger than 64kb where incorrectly parsed by the inspector-helper. Fixes: nodejs#14507

bzoz · 2017-08-02T13:41:35Z

It looks like this was the issue, I've opened a PR: #14596

Fix a bug when messages bigger than 64kb where incorrectly parsed by the inspector-helper. PR-URL: #14596 Fixes: #14507 Reviewed-By: Luigi Pinca <[email protected]> Reviewed-By: Eugene Ostroukhov <[email protected]> Reviewed-By: Refael Ackermann <[email protected]> Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

If JSON.parse() fails, print a message showing the JSON that failed to parse. This is to help with debugging a current test failure on CI. PR-URL: #14508 Ref: #14507 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Luigi Pinca <[email protected]> Reviewed-By: Refael Ackermann <[email protected]>

Fix a bug when messages bigger than 64kb where incorrectly parsed by the inspector-helper. PR-URL: #14596 Fixes: #14507 Reviewed-By: Luigi Pinca <[email protected]> Reviewed-By: Eugene Ostroukhov <[email protected]> Reviewed-By: Refael Ackermann <[email protected]> Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: James M Snell <[email protected]>

Trott added flaky-test Issues and PRs related to the tests with unstable failures on the CI. inspector Issues and PRs related to the V8 inspector protocol test Issues and PRs related to the tests. labels Jul 26, 2017

Trott added the windows Issues and PRs related to the Windows platform. label Jul 26, 2017

Trott mentioned this issue Jul 27, 2017

test: fix error when foo in path to git clone #14506

Closed

3 tasks

Trott mentioned this issue Jul 27, 2017

test: improve error logging for inspector test #14508

Closed

2 tasks

Trott added a commit to Trott/io.js that referenced this issue Jul 27, 2017

test: improve error logging for inspector test

31bc3c1

If JSON.parse() fails, print a message showing the JSON that failed to parse. This is to help with debugging a current test failure on CI. Refs: nodejs#14507

bzoz added a commit to JaneaSystems/node that referenced this issue Aug 2, 2017

test: read proper inspector message size

993636a

Fix a bug when messages bigger than 64kb where incorrectly parsed by the inspector-helper. Fixes: nodejs#14507

bzoz mentioned this issue Aug 2, 2017

test: read proper inspector message size #14596

Closed

2 tasks

Trott closed this as completed in 2dc09f6 Aug 4, 2017

MylesBorins mentioned this issue Aug 8, 2017

v8.3.0 proposal #14594

Merged

refack mentioned this issue Nov 5, 2017

flake: sequential/test-inspector-stop-profile-after-done #16772

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

investigate flaky test-inspector-stop-profile-after-done on Windows #14507

investigate flaky test-inspector-stop-profile-after-done on Windows #14507

Trott commented Jul 26, 2017

Trott commented Jul 26, 2017

Trott commented Jul 26, 2017

eugeneo commented Jul 26, 2017

Trott commented Jul 28, 2017

eugeneo commented Jul 28, 2017 via email

eugeneo commented Jul 28, 2017

eugeneo commented Jul 28, 2017

tniessen commented Jul 31, 2017

refack commented Jul 31, 2017

Trott commented Jul 31, 2017

Trott commented Aug 1, 2017

Trott commented Aug 1, 2017

refack commented Aug 1, 2017

MylesBorins commented Aug 1, 2017

bzoz commented Aug 2, 2017

bzoz commented Aug 2, 2017

investigate flaky test-inspector-stop-profile-after-done on Windows #14507

investigate flaky test-inspector-stop-profile-after-done on Windows #14507

Comments

Trott commented Jul 26, 2017

Trott commented Jul 26, 2017

Trott commented Jul 26, 2017

eugeneo commented Jul 26, 2017

Trott commented Jul 28, 2017

eugeneo commented Jul 28, 2017 via email

eugeneo commented Jul 28, 2017

eugeneo commented Jul 28, 2017

tniessen commented Jul 31, 2017

refack commented Jul 31, 2017

Trott commented Jul 31, 2017

Trott commented Aug 1, 2017

Trott commented Aug 1, 2017

refack commented Aug 1, 2017

MylesBorins commented Aug 1, 2017

bzoz commented Aug 2, 2017

bzoz commented Aug 2, 2017