1594637 - Intermittent TEST-UNEXPECTED-TIMEOUT | devtools/client/webconsole/test/browser/browser_webconsole_output_order.js | application timed out after 370 seconds with no output

Status: RESOLVED FIXED

(DevTools :: Console, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ccoroiu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=274986324&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/Bjg--lrDSauulqRgedUcXw/runs/1/artifacts/public/logs/live_backing.log

---

task 2019-11-07T02:23:19.732Z] 02:23:19 INFO - TEST-START | devtools/client/webconsole/test/browser/browser_webconsole_output_order.js
[task 2019-11-07T02:31:08.823Z] 02:31:01 INFO - Buffered messages logged at 02:23:19
[task 2019-11-07T02:32:09.420Z] 02:32:01 INFO - Entering test bound
[task 2019-11-07T02:32:20.143Z] 02:32:19 INFO - Adding a new tab with URL: http://example.com/browser/devtools/client/webconsole/test/browser/test-console.html
[task 2019-11-07T02:33:11.296Z] 02:33:11 INFO - Buffered messages logged at 02:23:21
[task 2019-11-07T02:33:11.299Z] 02:33:11 INFO - Tab added and finished loading
[task 2019-11-07T02:33:11.299Z] 02:33:11 INFO - Opening the toolbox
[task 2019-11-07T02:33:11.299Z] 02:33:11 INFO - Buffered messages logged at 02:23:24
[task 2019-11-07T02:33:11.299Z] 02:33:11 INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome://global/content/elements/panel.js" line: 62}]
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - Buffered messages logged at 02:23:40
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome://global/content/elements/panel.js" line: 62}]
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - Buffered messages logged at 02:23:46
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - Toolbox opened and focused
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - Buffered messages logged at 02:23:49
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - Matched a message with text: "console.log('foo', 'bar');", still waiting for 2 messages.
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - Buffered messages logged at 02:23:53
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - Matched a message with text: "undefined", still waiting for 1 messages.
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - Buffered messages finished
[task 2019-11-07T02:33:11.300Z] 02:33:11 ERROR - TEST-UNEXPECTED-TIMEOUT | devtools/client/webconsole/test/browser/browser_webconsole_output_order.js | application timed out after 370 seconds with no output
[task 2019-11-07T02:33:11.300Z] 02:33:11 ERROR - Force-terminating active process(es).
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - Determining child pids from psutil...
[task 2019-11-07T02:33:11.300Z] 02:33:11 INFO - [2890, 2913, 2966, 2997, 3025]
[task 2019-11-07T02:33:11.301Z] 02:33:11 INFO - ==> process 2835 launched child process 2856
[task 2019-11-07T02:33:11.301Z] 02:33:11 INFO - ==> process 2835 launched child process 2890
[task 2019-11-07T02:33:11.301Z] 02:33:11 INFO - ==> process 2835 launched child process 2913
[task 2019-11-07T02:33:11.302Z] 02:33:11 INFO - ==> process 2835 launched child process 2966
[task 2019-11-07T02:33:11.302Z] 02:33:11 INFO - ==> process 2835 launched child process 2997
[task 2019-11-07T02:33:11.302Z] 02:33:11 INFO - ==> process 2835 launched child process 3025
[task 2019-11-07T02:33:11.304Z] 02:33:11 INFO - Found child pids: set([2913, 2856, 2890, 3025, 2997, 2966])
[task 2019-11-07T02:33:11.304Z] 02:33:11 INFO - Failed to get child procs
[task 2019-11-07T02:33:11.305Z] 02:33:11 INFO - Killing process: 2913
[task 2019-11-07T02:33:11.305Z] 02:33:11 INFO - TEST-INFO | started process screentopng
[task 2019-11-07T02:33:14.634Z] 02:33:14 INFO - TEST-INFO | screentopng: exit 0
[task 2019-11-07T02:33:14.638Z] 02:33:14 INFO - Can't trigger Breakpad, just killing process
[task 2019-11-07T02:33:15.395Z] 02:33:15 INFO - psutil found pid 2913 dead
[task 2019-11-07T02:33:15.395Z] 02:33:15 INFO - Killing process: 2856
[task 2019-11-07T02:33:15.395Z] 02:33:15 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-11-07T02:33:15.396Z] 02:33:15 INFO - Can't trigger Breakpad, just killing process
[task 2019-11-07T02:33:15.396Z] 02:33:15 INFO - Error: Failed to kill process 2856: psutil.NoSuchProcess no process found with pid 2856
[task 2019-11-07T02:33:15.396Z] 02:33:15 INFO - Killing process: 2890
[task 2019-11-07T02:33:15.397Z] 02:33:15 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-11-07T02:33:15.397Z] 02:33:15 INFO - Can't trigger Breakpad, just killing process
[task 2019-11-07T02:33:19.333Z] 02:33:19 INFO - psutil found pid 2890 dead
[task 2019-11-07T02:33:19.334Z] 02:33:19 INFO - Killing process: 3025

Comment 1

[Nicolas Chevobbe [:nchevobbe]]

Attachment: Bug 1594637 - Fix browser_webconsole_output_order intermittent. r=Honza.

It's not obvious to me what the culprit is, but it may be because
of the clearOutput call somehow.
Let's see if this fix the intermittent.

Comment 2

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/526d08f2c191
Fix browser_webconsole_output_order intermittent. r=Honza.

Comment 3

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/526d08f2c191

Comment 4

[Intermittent Failures Robot]

1 failures in 4850 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1594637&startday=2019-11-04&endday=2019-11-10&tree=all