Closed Bug 1588252 Opened 5 years ago Closed 18 hours ago

Perma [tier2] [fission] TEST-UNEXPECTED-FAIL | damp | styleeditor/complicated.js: Test timed out

Categories

(DevTools :: Console, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, leave-open, regression, Whiteboard: [retriggered][stockwell disabled])

Filed by: cbrindusan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=270961519&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/bvHOpoEbSYqmAUcYoHaPyg/runs/0/artifacts/public/logs/live_backing.log


[task 2019-10-12T00:02:00.603Z] 00:02:00 INFO - PID 2005 | 'complicated.webconsole.open.settle.DAMP' took 43.87624699994922ms.
[task 2019-10-12T00:02:00.603Z] 00:02:00 INFO - PID 2005 | Garbage collect
[task 2019-10-12T00:02:02.172Z] 00:02:02 INFO - PID 2005 | Reload page on 'complicated.webconsole'
[task 2019-10-12T00:02:04.559Z] 00:02:04 INFO - PID 2005 | Wait for pending paints on 'complicated.webconsole'
[task 2019-10-12T00:02:04.639Z] 00:02:04 INFO - PID 2005 | 'complicated.webconsole.reload.settle.DAMP' took 76.02114800002892ms.
[task 2019-10-12T00:02:04.639Z] 00:02:04 INFO - PID 2005 | Close toolbox on 'complicated.webconsole'
[task 2019-10-12T00:02:04.686Z] 00:02:04 INFO - PID 2005 | Garbage collect
[task 2019-10-12T00:02:06.282Z] 00:02:06 INFO - PID 2005 | webconsole/complicated.js took 7463ms.
[task 2019-10-12T00:02:06.282Z] 00:02:06 INFO - PID 2005 | Loading test 'inspector/complicated.js'
[task 2019-10-12T00:02:06.282Z] 00:02:06 INFO - PID 2005 | Executing test 'inspector/complicated.js'
[task 2019-10-12T00:02:08.178Z] 00:02:08 INFO - PID 2005 | 'complicated.inspector.open.settle.DAMP' took 0.2078779999865219ms.
[task 2019-10-12T00:02:08.179Z] 00:02:08 INFO - PID 2005 | Garbage collect
[task 2019-10-12T00:02:09.830Z] 00:02:09 INFO - PID 2005 | Reload page on 'complicated.inspector'
[task 2019-10-12T00:02:09.830Z] 00:02:09 INFO - PID 2005 | console.error: "Error while calling actor 'pagestyle's method 'getUsedFontFaces'" "node is null"
[task 2019-10-12T00:02:09.830Z] 00:02:09 INFO - PID 2005 | console.error: "getUsedFontFaces@resource://devtools/server/actors/styles.js:382:24\nhandler@resource://devtools/shared/protocol/Actor.js:154:37\nonPacket@resource://devtools/server/debugger-server-connection.js:378:58\nreceiveMessage@resource://devtools/shared/transport/child-transport.js:66:16\nMessageListener.receiveMessage*_addListener@resource://devtools/shared/transport/child-transport.js:40:14\nready@resource://devtools/shared/transport/child-transport.js:57:10\n_onConnection@resource://devtools/server/debugger-server.js:450:15\nconnectToParent@resource://devtools/server/debugger-server.js:331:17\nonConnect<@resource://devtools/server/startup/frame.js:62:35\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\nMessageListener.receiveMessage*@resource://devtools/server/startup/frame.js:92:23\n@resource://devtools/server/startup/frame.js:174:5\n"
[task 2019-10-12T00:02:09.830Z] 00:02:09 INFO - PID 2005 | console.error: "Error while calling actor 'pagestyle's method 'getApplied'" "node is null"
[task 2019-10-12T00:02:09.830Z] 00:02:09 INFO - PID 2005 | console.error: "getApplied@resource://devtools/server/actors/styles.js:585:5\nhandler@resource://devtools/shared/protocol/Actor.js:154:37\nonPacket@resource://devtools/server/debugger-server-connection.js:378:58\nreceiveMessage@resource://devtools/shared/transport/child-transport.js:66:16\nMessageListener.receiveMessage*_addListener@resource://devtools/shared/transport/child-transport.js:40:14\nready@resource://devtools/shared/transport/child-transport.js:57:10\n_onConnection@resource://devtools/server/debugger-server.js:450:15\nconnectToParent@resource://devtools/server/debugger-server.js:331:17\nonConnect<@resource://devtools/server/startup/frame.js:62:35\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\nMessageListener.receiveMessage*@resource://devtools/server/startup/frame.js:92:23\n@resource://devtools/server/startup/frame.js:174:5\n"
[task 2019-10-12T00:02:09.833Z] 00:02:09 INFO - PID 2005 | console.error: "Could not get the list of font families" "Protocol error (unknownError): node is null"
[task 2019-10-12T00:02:09.867Z] 00:02:09 INFO - PID 2005 | console.error: "Protocol error (unknownError): node is null"
[task 2019-10-12T00:02:11.986Z] 00:02:11 INFO - PID 2005 | Wait for pending paints on 'complicated.inspector'
[task 2019-10-12T00:02:12.029Z] 00:02:12 INFO - PID 2005 | 'complicated.inspector.reload.settle.DAMP' took 44.53851500002202ms.
[task 2019-10-12T00:02:12.029Z] 00:02:12 INFO - PID 2005 | Close toolbox on 'complicated.inspector'
[task 2019-10-12T00:02:12.162Z] 00:02:12 INFO - PID 2005 | Garbage collect
[task 2019-10-12T00:02:13.836Z] 00:02:13 INFO - PID 2005 | inspector/complicated.js took 7555ms.
[task 2019-10-12T00:02:13.836Z] 00:02:13 INFO - PID 2005 | Loading test 'debugger/complicated.js'
[task 2019-10-12T00:02:13.836Z] 00:02:13 INFO - PID 2005 | Executing test 'debugger/complicated.js'
[task 2019-10-12T00:02:15.889Z] 00:02:15 INFO - PID 2005 | Waiting for state change: has source http://127.0.0.1:50048/tests/tp5n/bild.de/www.bild.de/index.html
[task 2019-10-12T00:02:15.889Z] 00:02:15 INFO - PID 2005 | Finished waiting for state change: has source http://127.0.0.1:50048/tests/tp5n/bild.de/www.bild.de/index.html
[task 2019-10-12T00:02:15.889Z] 00:02:15 INFO - PID 2005 | Selecting source: ga.js
[task 2019-10-12T00:02:15.949Z] 00:02:15 INFO - PID 2005 | Waiting for state change: selected source
[task 2019-10-12T00:02:16.637Z] 00:02:16 INFO - PID 2005 | Finished waiting for state change: selected source
[task 2019-10-12T00:02:16.637Z] 00:02:16 INFO - PID 2005 | Waiting until: text is visible
[task 2019-10-12T00:02:16.702Z] 00:02:16 INFO - PID 2005 | Finished Waiting until: text is visible
[task 2019-10-12T00:02:16.702Z] 00:02:16 INFO - PID 2005 | Waiting until: has file metadata
[task 2019-10-12T00:02:16.862Z] 00:02:16 INFO - PID 2005 | Finished Waiting until: has file metadata
[task 2019-10-12T00:02:16.862Z] 00:02:16 INFO - PID 2005 | 'complicated.jsdebugger.open.settle.DAMP' took 0.19360999995842576ms.
[task 2019-10-12T00:02:16.862Z] 00:02:16 INFO - PID 2005 | Garbage collect
[task 2019-10-12T00:02:18.376Z] 00:02:18 INFO - PID 2005 | Reload page on 'complicated.jsdebugger'
[task 2019-10-12T00:02:18.414Z] 00:02:18 INFO - PID 2005 | Waiting for state change: count sources
[task 2019-10-12T00:02:19.829Z] 00:02:19 INFO - PID 2005 | Finished waiting for state change: count sources
[task 2019-10-12T00:02:19.830Z] 00:02:19 INFO - PID 2005 | Finished waiting for state change: count sources
[task 2019-10-12T00:02:19.896Z] 00:02:19 INFO - PID 2005 | Waiting until: text is visible
[task 2019-10-12T00:02:20.683Z] 00:02:20 INFO - PID 2005 | Finished Waiting until: text is visible
[task 2019-10-12T00:02:20.683Z] 00:02:20 INFO - PID 2005 | Waiting until: has file metadata
[task 2019-10-12T00:02:21.122Z] 00:02:21 INFO - PID 2005 | Finished Waiting until: has file metadata
[task 2019-10-12T00:02:21.122Z] 00:02:21 INFO - PID 2005 | Wait for pending paints on 'complicated.jsdebugger'
[task 2019-10-12T00:02:21.147Z] 00:02:21 INFO - PID 2005 | 'complicated.jsdebugger.reload.settle.DAMP' took 21.780447999946773ms.
[task 2019-10-12T00:02:21.147Z] 00:02:21 INFO - PID 2005 | Close toolbox on 'complicated.jsdebugger'
[task 2019-10-12T00:02:21.243Z] 00:02:21 INFO - PID 2005 | Garbage collect
[task 2019-10-12T00:02:22.064Z] 00:02:22 INFO - PID 2005 | debugger/complicated.js took 8215ms.
[task 2019-10-12T00:02:22.064Z] 00:02:22 INFO - PID 2005 | Loading test 'styleeditor/complicated.js'
[task 2019-10-12T00:02:22.064Z] 00:02:22 INFO - PID 2005 | Executing test 'styleeditor/complicated.js'
[task 2019-10-12T00:02:22.102Z] 00:02:22 INFO - PID 2005 |
[task 2019-10-12T00:02:22.102Z] 00:02:22 INFO - PID 2005 | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-10-12T00:02:22.102Z] 00:02:22 INFO - PID 2005 |
[task 2019-10-12T00:02:23.161Z] 00:02:23 INFO - PID 2005 | dyld: Library not loaded: @executable_path/libmozglue.dylib
[task 2019-10-12T00:02:23.161Z] 00:02:23 INFO - PID 2005 | Referenced from: /Users/cltbld/tasks/task_1570833511/build/application/Firefox Nightly.app/Contents/MacOS/crashreporter.app/Contents/MacOS/minidump-analyzer
[task 2019-10-12T00:02:23.161Z] 00:02:23 INFO - PID 2005 | Reason: image not found
[task 2019-10-12T00:07:22.059Z] 00:07:22 INFO - PID 2005 | TEST-UNEXPECTED-FAIL | damp | styleeditor/complicated.js: Test timed out

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → INCOMPLETE

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=292133415&repo=autoland&lineNumber=10461

[task 2020-03-08T00:33:29.128Z] 00:33:29     INFO -  PID 2507 | Selecting source: ga.js
[task 2020-03-08T00:33:29.192Z] 00:33:29     INFO -  PID 2507 | Waiting for state change: selected source
[task 2020-03-08T00:33:29.876Z] 00:33:29     INFO -  PID 2507 | Finished waiting for state change: selected source
[task 2020-03-08T00:33:29.876Z] 00:33:29     INFO -  PID 2507 | Waiting until: text is visible
[task 2020-03-08T00:33:29.941Z] 00:33:29     INFO -  PID 2507 | Finished Waiting until: text is visible
[task 2020-03-08T00:33:29.941Z] 00:33:29     INFO -  PID 2507 | Waiting until: has file metadata
[task 2020-03-08T00:33:30.077Z] 00:33:30     INFO -  PID 2507 | Finished Waiting until: has file metadata
[task 2020-03-08T00:33:30.077Z] 00:33:30     INFO -  PID 2507 | Wait for pending paints on 'complicated.jsdebugger.open'
[task 2020-03-08T00:33:30.077Z] 00:33:30     INFO -  PID 2507 | 'complicated.jsdebugger.open.settle.DAMP' took 18.479682999983197ms.
[task 2020-03-08T00:33:30.077Z] 00:33:30     INFO -  PID 2507 | Garbage collect
[task 2020-03-08T00:33:31.542Z] 00:33:31     INFO -  PID 2507 | Reload page on 'complicated.jsdebugger'
[task 2020-03-08T00:33:31.593Z] 00:33:31     INFO -  PID 2507 | Waiting for state change: count sources
[task 2020-03-08T00:33:32.791Z] 00:33:32     INFO -  PID 2507 | Finished waiting for state change: count sources
[task 2020-03-08T00:33:32.815Z] 00:33:32     INFO -  PID 2507 | Finished waiting for state change: count sources
[task 2020-03-08T00:33:32.849Z] 00:33:32     INFO -  PID 2507 | Waiting until: text is visible
[task 2020-03-08T00:33:33.931Z] 00:33:33     INFO -  PID 2507 | Finished Waiting until: text is visible
[task 2020-03-08T00:33:33.933Z] 00:33:33     INFO -  PID 2507 | Waiting until: has file metadata
[task 2020-03-08T00:33:34.444Z] 00:33:34     INFO -  PID 2507 | Finished Waiting until: has file metadata
[task 2020-03-08T00:33:34.444Z] 00:33:34     INFO -  PID 2507 | Wait for pending paints on 'complicated.jsdebugger.reload'
[task 2020-03-08T00:33:34.444Z] 00:33:34     INFO -  PID 2507 | 'complicated.jsdebugger.reload.settle.DAMP' took 0.12837500000023283ms.
[task 2020-03-08T00:33:34.444Z] 00:33:34     INFO -  PID 2507 | Close toolbox on 'complicated.jsdebugger'
[task 2020-03-08T00:33:34.578Z] 00:33:34     INFO -  PID 2507 | Garbage collect
[task 2020-03-08T00:33:35.332Z] 00:33:35     INFO -  PID 2507 | debugger/complicated.js took 8466ms.
[task 2020-03-08T00:33:35.332Z] 00:33:35     INFO -  PID 2507 | Loading test 'styleeditor/complicated.js'
[task 2020-03-08T00:33:35.332Z] 00:33:35     INFO -  PID 2507 | Executing test 'styleeditor/complicated.js'
[task 2020-03-08T00:38:35.439Z] 00:38:35     INFO -  PID 2507 | TEST-UNEXPECTED-FAIL | damp | styleeditor/complicated.js: Test timed out
[task 2020-03-08T00:38:35.631Z] 00:38:35     INFO -  Terminating psutil.Process(pid=2507, name='firefox', started='00:30:15')
[task 2020-03-08T00:38:35.678Z] 00:38:35     INFO -  PID 2507 | Exiting due to channel error.
[task 2020-03-08T00:38:35.678Z] 00:38:35     INFO -  PID 2507 | Exiting due to channel error.
[task 2020-03-08T00:38:35.680Z] 00:38:35     INFO -  PID 2507 | Exiting due to channel error.
[task 2020-03-08T00:38:35.801Z] 00:38:35     INFO -  TEST-UNEXPECTED-ERROR | damp | unexpected error
[task 2020-03-08T00:38:35.801Z] 00:38:35    ERROR -  Traceback (most recent call last):
[task 2020-03-08T00:38:35.801Z] 00:38:35     INFO -    File "/Users/cltbld/tasks/task_1583624010/build/tests/talos/talos/run_tests.py", line 306, in run_tests
[task 2020-03-08T00:38:35.801Z] 00:38:35     INFO -      talos_results.add(mytest.runTest(browser_config, test))
[task 2020-03-08T00:38:35.801Z] 00:38:35     INFO -    File "/Users/cltbld/tasks/task_1583624010/build/tests/talos/talos/ttest.py", line 64, in runTest
[task 2020-03-08T00:38:35.801Z] 00:38:35     INFO -      return self._runTest(browser_config, test_config, setup)
[task 2020-03-08T00:38:35.802Z] 00:38:35     INFO -    File "/Users/cltbld/tasks/task_1583624010/build/tests/talos/talos/ttest.py", line 216, in _runTest
[task 2020-03-08T00:38:35.802Z] 00:38:35     INFO -      debugger_args=browser_config['debugger_args']
[task 2020-03-08T00:38:35.802Z] 00:38:35     INFO -    File "/Users/cltbld/tasks/task_1583624010/build/tests/talos/talos/talos_process.py", line 156, in run_browser
[task 2020-03-08T00:38:35.802Z] 00:38:35     INFO -      raise TalosError("unexpected error")
[task 2020-03-08T00:38:35.802Z] 00:38:35     INFO -  TalosError: unexpected error
[task 2020-03-08T00:38:35.802Z] 00:38:35     INFO -  TEST-INFO took 3550040ms
[task 2020-03-08T00:38:35.802Z] 00:38:35     INFO -  SUITE-END | took 3550s
[task 2020-03-08T00:38:36.179Z] 00:38:36    ERROR - Return code: 2
[task 2020-03-08T00:38:36.179Z] 00:38:36  WARNING - setting return code to 2
[task 2020-03-08T00:38:36.179Z] 00:38:36    ERROR - # TBPL FAILURE #
[task 2020-03-08T00:38:36.179Z] 00:38:36     INFO - Running post-action listener: _package_coverage_data
[task 2020-03-08T00:38:36.179Z] 00:38:36     INFO - Running post-action listener: _resource_record_post_action
[task 2020-03-08T00:38:36.179Z] 00:38:36     INFO - Running post-action listener: process_java_coverage_data
[task 2020-03-08T00:38:36.179Z] 00:38:36     INFO - [mozharness: 2020-03-08 00:38:36.179653Z] Finished run-tests step (success)
[task 2020-03-08T00:38:36.179Z] 00:38:36     INFO - Running post-run listener: _resource_record_post_run
[task 2020-03-08T00:38:36.387Z] 00:38:36     INFO - Total resource usage - Wall time: 3571s; CPU: 20.0%; Read bytes: 198168576; Write bytes: 2304249856; Read time: 3058; Write time: 18552
[task 2020-03-08T00:38:36.387Z] 00:38:36     INFO - TinderboxPrint: CPU usage<br/>19.9%
[task 2020-03-08T00:38:36.387Z] 00:38:36     INFO - TinderboxPrint: I/O read bytes / time<br/>198,168,576 / 3,058
[task 2020-03-08T00:38:36.387Z] 00:38:36     INFO - TinderboxPrint: I/O write bytes / time<br/>2,304,249,856 / 18,552
[task 2020-03-08T00:38:36.387Z] 00:38:36     INFO - TinderboxPrint: CPU idle<br/>9,212.6 (64.5%)
[task 2020-03-08T00:38:36.387Z] 00:38:36     INFO - TinderboxPrint: CPU system<br/>797.4 (5.6%)
[task 2020-03-08T00:38:36.387Z] 00:38:36     INFO - TinderboxPrint: CPU user<br/>4,272.1 (29.9%)
[task 2020-03-08T00:38:36.387Z] 00:38:36     INFO - TinderboxPrint: Swap in / out<br/>363,794,432 / 0
[task 2020-03-08T00:38:36.390Z] 00:38:36     INFO - install - Wall time: 20s; CPU: 38.0%; Read bytes: 257967616; Write bytes: 244715520; Read time: 16102; Write time: 459
[task 2020-03-08T00:38:36.412Z] 00:38:36     INFO - run-tests - Wall time: 3551s; CPU: 20.0%; Read bytes: 190631936; Write bytes: 2023034880; Read time: 2997; Write time: 18014
[task 2020-03-08T00:38:37.103Z] 00:38:37  WARNING - returning nonzero exit status 2
[fetches 2020-03-08T00:38:37.127Z] removing /Users/cltbld/tasks/task_1583624010/fetches
[fetches 2020-03-08T00:38:37.129Z] finished
[taskcluster 2020-03-08T00:38:37.139Z]    Exit Code: 2
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

:ochameau can you take a look over these intermittent failures ?

Flags: needinfo?(poirot.alex)
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Flags: needinfo?(poirot.alex)
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent PID 2005 | TEST-UNEXPECTED-FAIL | damp | styleeditor/complicated.js: Test timed out → Intermittent TEST-UNEXPECTED-FAIL | damp | styleeditor/complicated.js: Test timed out
Component: Talos → Console
Product: Testing → DevTools
Version: Version 3 → unspecified
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Hi Andreea!

I tried the following command to confirm this issue in my local env.
./mach talos-test --activeTests damp --cycles 1 --tppagecycles 1
But, since I got the following error, could not test locally.
IOError: [Errno 2] No such file or directory: u'$MCDIR/obj-x86_64-apple-darwin18.7.0/testing/talos-venv/bin/activate_this.py'
Do you know how to fix this issue??

What I had tried to fix this one are mach bootstrap, mach clobber and mach build again.

Hi, unfortunately I don't, however maybe Aryx does.

Flags: needinfo?(aryx.bugmail)

Alexandre, please guide Daisuke how to run the damp test locally.

Flags: needinfo?(aryx.bugmail) → needinfo?(poirot.alex)

(I'm on PTO)
This isn't so much about DAMP, but rather about Talos.

Ionut, do you know who maintain Talos these days?
Daisuke is having an issue in running Talos from Mac OS, see comment 18.

Flags: needinfo?(poirot.alex) → needinfo?(ionut.goldan)

Important detail, recently this failure only seems to happen when running against Fission (see https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-03-17&endday=2020-07-15&tree=trunk&bug=1588252 )

See Also: → 1652983

No failure since Bug 1649910 landed. Since the intermittent was fission-only, maybe the patch for Bug 1649910 also fixed this one.

Summary: Intermittent TEST-UNEXPECTED-FAIL | damp | styleeditor/complicated.js: Test timed out → Perma [tier2] [fission] TEST-UNEXPECTED-FAIL | damp | styleeditor/complicated.js: Test timed out
See Also: → 1678741
Flags: needinfo?(nchevobbe)
Keywords: leave-open
Whiteboard: [retriggered][stockwell needswork:owner] → [retriggered][stockwell disabled]
See Also: → 1724340
Has Regression Range: --- → yes
Severity: normal → S3
Status: REOPENED → RESOLVED
Closed: 4 years ago18 hours ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.