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

refack · 2017-11-05T14:35:09Z

Version: master
Platform: Windows
Subsystem: inspector,test

https://ci.nodejs.org/job/node-test-binary-windows/12525/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=3/console

not ok 506 sequential/test-inspector-stop-profile-after-done
  ---
  duration_ms: 124.922
  severity: fail
  stack: |-
    timeout
  ...

Refs: #14507

The text was updated successfully, but these errors were encountered:

refack · 2017-11-05T14:41:56Z

/cc @nodejs/v8-inspector

Trott · 2017-11-06T16:20:18Z

Again today: https://ci.nodejs.org/job/node-test-binary-windows/12549/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=3/console

not ok 506 sequential/test-inspector-stop-profile-after-done
  ---
  duration_ms: 128.785
  severity: fail
  stack: |-
    timeout
``

Trott · 2017-11-08T09:53:58Z

Now on Raspberry Pi too:

https://ci.nodejs.org/job/node-test-binary-arm/RUN_SUBSET=6,label=pi1-raspbian-wheezy/11617/console:

not ok 278 sequential/test-inspector-stop-profile-after-done
  ---
  duration_ms: 360.77
  severity: fail
  stack: |-
    timeout

Looks like this resulted in the device failing to build multiple times subsequently. @rvagg indicated it was due to a zombie process. So maybe it came about due to this test failure?

Trott · 2017-11-08T13:55:33Z

Another windows one. Looks like it only ever happens on win2016 vs2017 hosts in CI.

https://ci.nodejs.org/job/node-test-binary-windows/12634/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=3/console

not ok 507 sequential/test-inspector-stop-profile-after-done
  ---
  duration_ms: 123.544
  severity: fail
  stack: |-
    timeout

refack · 2017-11-08T14:06:28Z

In the reports I see 3/3 VS2017 fails, so this might be related to #15558

refack · 2017-11-08T14:10:29Z

See if we can repro (single test x 100 repeats)
win2012r2-mp-vs2015 - https://ci.nodejs.org/job/node-stress-single-test/1548/
win2012r2-mp-vs2017 - https://ci.nodejs.org/job/node-stress-single-test/1549/

Trott · 2017-11-17T08:18:35Z

Today on Raspberry Pi:

https://ci.nodejs.org/job/node-test-binary-arm/11870/RUN_SUBSET=4,label=pi1-raspbian-wheezy/console

20:26:43 not ok 282 sequential/test-inspector-stop-profile-after-done
20:26:43   ---
20:26:43   duration_ms: 360.111
20:26:43   severity: fail
20:26:43   stack: |-
20:26:43     timeout

mmarchini · 2017-11-21T17:44:34Z

Today on Raspbery Pi again:

https://ci.nodejs.org/job/node-test-binary-arm/11987/RUN_SUBSET=3,label=pi1-raspbian-wheezy/console

11:57:59 not ok 283 sequential/test-inspector-stop-profile-after-done
11:57:59   ---
11:57:59   duration_ms: 360.66
11:57:59   severity: fail
11:57:59   stack: |-
11:57:59     timeout

Trott · 2017-12-02T09:30:40Z

WIndows again but this time an assertion failure rather than a timeout:

https://ci.nodejs.org/job/node-test-binary-windows/13307/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=2/console

not ok 518 sequential/test-inspector-stop-profile-after-done
  ---
  duration_ms: 0.680
  severity: fail
  stack: |-
    [test] Connecting to a child Node process
    [test] Testing /json/list
    [err] Debugger listening on ws://127.0.0.1:61080/4b6bfeec-65aa-4129-b2c3-2cd3c829c1dc
    [err] For help see https://nodejs.org/en/docs/inspector
    [err] 
    [out] {}
    [out] 
    [out] {}
    [out] 
    [out] {}
    [out] 
    [out] {}
    [out] 
    [out] {}
    [out] 
    [out] {}
    [out] 
    [out] {}
    [out] 
    [out] {}
    [out] 
    [out] {}
    [out] 
    [out] {}
    [out] 
    [out] {}
    [out] 
    [err] Debugger attached.
    [err] Waiting for the debugger to disconnect...
    [err] 
    { AssertionError [ERR_ASSERTION]: 0 strictEqual 3221225477
        at runTests (c:\workspace\node-test-binary-windows\test\sequential\test-inspector-stop-profile-after-done.js:26:10)
        at <anonymous>
        at process._tickCallback (internal/process/next_tick.js:165:7)
      generatedMessage: true,
      name: 'AssertionError [ERR_ASSERTION]',
      code: 'ERR_ASSERTION',
      actual: 0,
      expected: 3221225477,
      operator: 'strictEqual' }
    1

Trott · 2017-12-23T15:56:41Z

Back to a timeout on Windows:

https://ci.nodejs.org/job/node-test-binary-windows/13846/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=1/console

not ok 524 sequential/test-inspector-stop-profile-after-done
  ---
  duration_ms: 127.567
  severity: fail
  stack: |-
    timeout
  ...

Trott · 2017-12-23T16:01:38Z

It does appear that this test takes an unusually large amount of time to run:

ok 524 sequential/test-inspector-stop-profile-after-done
  ---
  duration_ms: 35.635
  ...

In comparison, the test takes less than a second to run on (for example) our CentOS 7 test machine:

ok 2029 sequential/test-inspector-stop-profile-after-done
  ---
  duration_ms: 0.620

That's quite a difference....

Trott · 2017-12-23T16:08:50Z

If we could get the output of the test when it times out, that would let us know how far along it got. (One reason I'm not super-excited about the tendency to remove console.log()/console.error() statements from tests.)

@refack Any chance you can run the test locally and get an idea where it seems to do al its waiting?

Trott · 2017-12-23T16:09:27Z

@nodejs/platform-windows

Trott · 2017-12-28T13:52:10Z

Timeout again today.

https://ci.nodejs.org/job/node-test-binary-windows/13917/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=2/console

not ok 525 sequential/test-inspector-stop-profile-after-done
  ---
  duration_ms: 127.467
  severity: fail
  stack: |-
    timeout
  ...

Trott · 2017-12-28T13:53:23Z

@jBarz @nodejs/testing

Trott · 2018-01-12T19:41:03Z

Back on Raspberry Pi 1 devices:

https://ci.nodejs.org/job/node-test-binary-arm/12846/RUN_SUBSET=4,label=pi1-raspbian-wheezy/console

03:41:04 not ok 282 sequential/test-inspector-stop-profile-after-done
03:41:04   ---
03:41:04   duration_ms: 360.84
03:41:04   severity: fail
03:41:04   stack: |-
03:41:04     timeout

Trott · 2018-01-12T19:42:30Z

Doesn't take much time when successful, so some sort of race condition or something must be happening. Here's a successful run on a Pi 2:

03:21:29 ok 282 sequential/test-inspector-stop-profile-after-done
03:21:29   ---
03:21:29   duration_ms: 2.837

Trott · 2018-01-12T20:28:25Z

Replicated on macOS after 1700+ runs, but this time we have some output so we might have an idea of how/where it's getting stuck. Failure:

=== release test-inspector-stop-profile-after-done ===                     
Path: sequential/test-inspector-stop-profile-after-done
[test] Connecting to a child Node process
[test] Testing /json/list
[err] Debugger listening on ws://127.0.0.1:49485/23586fe0-dfa1-453b-8d7e-6acffa7c211b
[err] For help see https://nodejs.org/en/docs/inspector
[err] 
[err] Debugger attached.
[err] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[err] Waiting for the debugger to disconnect...
[err]
Command: out/Release/node /Users/trott/io.js/test/sequential/test-inspector-stop-profile-after-done.js
--- TIMEOUT ---

For comparison, here's success:

[test] Connecting to a child Node process
[test] Testing /json/list
[err] Debugger listening on ws://127.0.0.1:51256/d8a1ee2c-1189-49f1-8b3b-127177e8693f
[err] For help see https://nodejs.org/en/docs/inspector
[err] 
[err] Debugger attached.
[err] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[out] {}
[out] 
[err] Waiting for the debugger to disconnect...
[err]

Uhhh....no real difference in output....so I guess it's the exit/cleanup code?

Trott · 2018-01-16T16:47:17Z

Another one today...

https://ci.nodejs.org/job/node-test-binary-arm/12900/RUN_SUBSET=3,label=pi1-raspbian-wheezy/console

03:32:54 not ok 282 sequential/test-inspector-stop-profile-after-done
03:32:54   ---
03:32:54   duration_ms: 360.87
03:32:54   severity: fail
03:32:54   stack: |-
03:32:54     timeout

Trott · 2018-01-19T14:45:19Z

And today, back on Windows...

https://ci.nodejs.org/job/node-test-binary-windows/14329/COMPILED_BY=vs2017,RUNNER=win2016,RUN_SUBSET=1/console

not ok 515 sequential/test-inspector-stop-profile-after-done
  ---
  duration_ms: 122.356
  severity: fail
  stack: |-
    timeout

This test is consistently failing and making CI red. PR-URL: #18491 Refs: #16772 Reviewed-By: Gibson Fahnestock <[email protected]> Reviewed-By: Colin Ihrig <[email protected]>

In test/sequential/test-inspector-stop-profile-after-done.js, if `Profile.start` is received after the debugger is waiting to disconnect, then the process will not terminate. Fixes: nodejs#16772

Use common.platformTimeout() to give longer durations to Raspberry Pi devices to make test more reliable. PR-URL: nodejs#18126 Fixes: nodejs#16772 Reviewed-By: Anatoli Papirovski <[email protected]> Reviewed-By: Ruben Bridgewater <[email protected]> Reviewed-By: Eugene Ostroukhov <[email protected]> Reviewed-By: Richard Lau <[email protected]> Reviewed-By: James M Snell <[email protected]>

This test is consistently failing and making CI red. PR-URL: nodejs#18491 Refs: nodejs#16772 Reviewed-By: Gibson Fahnestock <[email protected]> Reviewed-By: Colin Ihrig <[email protected]>

Use common.platformTimeout() to give longer durations to Raspberry Pi devices to make test more reliable. PR-URL: nodejs#18126 Fixes: nodejs#16772 Reviewed-By: Anatoli Papirovski <[email protected]> Reviewed-By: Ruben Bridgewater <[email protected]> Reviewed-By: Eugene Ostroukhov <[email protected]> Reviewed-By: Richard Lau <[email protected]> Reviewed-By: James M Snell <[email protected]>

Use common.platformTimeout() to give longer durations to Raspberry Pi devices to make test more reliable. PR-URL: #18126 Fixes: #16772 Reviewed-By: Anatoli Papirovski <[email protected]> Reviewed-By: Ruben Bridgewater <[email protected]> Reviewed-By: Eugene Ostroukhov <[email protected]> Reviewed-By: Richard Lau <[email protected]> Reviewed-By: James M Snell <[email protected]>

refack 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 Nov 5, 2017

Trott mentioned this issue Jan 12, 2018

test: fix flaky inspector-stop-profile-after-done #18126

Closed

3 tasks

BridgeAR added windows Issues and PRs related to the Windows platform. arm Issues and PRs related to the ARM platform. labels Jan 19, 2018

Trott closed this as completed in 81d73fe Mar 2, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

refack commented Nov 5, 2017 •

edited

Loading

refack commented Nov 5, 2017

Trott commented Nov 6, 2017

Trott commented Nov 8, 2017

Trott commented Nov 8, 2017

refack commented Nov 8, 2017

refack commented Nov 8, 2017

Trott commented Nov 17, 2017

mmarchini commented Nov 21, 2017

Trott commented Dec 2, 2017

Trott commented Dec 23, 2017

Trott commented Dec 23, 2017 •

edited

Loading

Trott commented Dec 23, 2017

Trott commented Dec 23, 2017

Trott commented Dec 28, 2017

Trott commented Dec 28, 2017

Trott commented Jan 12, 2018

Trott commented Jan 12, 2018

Trott commented Jan 12, 2018 •

edited

Loading

Trott commented Jan 16, 2018

Trott commented Jan 19, 2018

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

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

Comments

refack commented Nov 5, 2017 • edited Loading

refack commented Nov 5, 2017

Trott commented Nov 6, 2017

Trott commented Nov 8, 2017

Trott commented Nov 8, 2017

refack commented Nov 8, 2017

refack commented Nov 8, 2017

Trott commented Nov 17, 2017

mmarchini commented Nov 21, 2017

Trott commented Dec 2, 2017

Trott commented Dec 23, 2017

Trott commented Dec 23, 2017 • edited Loading

Trott commented Dec 23, 2017

Trott commented Dec 23, 2017

Trott commented Dec 28, 2017

Trott commented Dec 28, 2017

Trott commented Jan 12, 2018

Trott commented Jan 12, 2018

Trott commented Jan 12, 2018 • edited Loading

Trott commented Jan 16, 2018

Trott commented Jan 19, 2018

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

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

refack commented Nov 5, 2017 •

edited

Loading

Trott commented Dec 23, 2017 •

edited

Loading

Trott commented Jan 12, 2018 •

edited

Loading