1757655 - Intermittent TEST-UNEXPECTED-TIMEOUT | devtools/client/debugger/test/mochitest/browser_dbg-react-app.js | application timed out after 370 seconds with no output

Status: RESOLVED INCOMPLETE

(DevTools :: Debugger, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=369609968&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VyJGrqARSHeays0PHHHjuA/runs/2/artifacts/public/logs/live_backing.log

---

[task 2022-03-01T22:34:16.671Z] 22:34:16     INFO - TEST-START | devtools/client/debugger/test/mochitest/browser_dbg-react-app.js
[task 2022-03-01T22:40:49.893Z] 22:40:49     INFO - Buffered messages logged at 22:34:16
[task 2022-03-01T22:40:54.523Z] 22:40:54     INFO - Entering test bound 
[task 2022-03-01T22:40:58.420Z] 22:40:58     INFO - Adding a new tab with URL: https://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-react.html
[task 2022-03-01T22:41:01.016Z] 22:41:00     INFO - Buffered messages logged at 22:34:21
[task 2022-03-01T22:41:05.074Z] 22:41:04     INFO - Tab added and finished loading
[task 2022-03-01T22:41:08.571Z] 22:41:08     INFO - Opening the toolbox
[task 2022-03-01T22:41:12.746Z] 22:41:12     INFO - Buffered messages logged at 22:34:26
[task 2022-03-01T22:41:13.494Z] 22:41:12     INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome" line: 511}]
[task 2022-03-01T22:41:15.128Z] 22:41:14     INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome" line: 511}]
[task 2022-03-01T22:41:17.829Z] 22:41:17     INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome" line: 62}]
[task 2022-03-01T22:41:20.222Z] 22:41:20     INFO - Buffered messages logged at 22:34:31
[task 2022-03-01T22:41:22.678Z] 22:41:22     INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome" line: 511}]
[task 2022-03-01T22:41:24.880Z] 22:41:24     INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome" line: 511}]
[task 2022-03-01T22:41:27.683Z] 22:41:27     INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome" line: 62}]
[task 2022-03-01T22:41:30.326Z] 22:41:30     INFO - Buffered messages finished
[task 2022-03-01T22:41:31.789Z] 22:41:31    ERROR - TEST-UNEXPECTED-TIMEOUT | devtools/client/debugger/test/mochitest/browser_dbg-react-app.js | application timed out after 370 seconds with no output
[task 2022-03-01T22:41:33.877Z] 22:41:33    ERROR - Force-terminating active process(es).
[task 2022-03-01T22:41:35.696Z] 22:41:35     INFO - Determining child pids from psutil...
[task 2022-03-01T22:41:35.870Z] 22:41:35     INFO - [1710, 1728, 1803, 1838, 1857, 2091]
[task 2022-03-01T22:41:36.843Z] 22:41:36     INFO - ==> process 1600 launched child process 1621
[task 2022-03-01T22:41:37.905Z] 22:41:37     INFO - ==> process 1600 launched child process 1710
[task 2022-03-01T22:41:37.916Z] 22:41:37     INFO - ==> process 1600 launched child process 1728
[task 2022-03-01T22:41:37.917Z] 22:41:37     INFO - ==> process 1600 launched child process 1803
[task 2022-03-01T22:41:37.918Z] 22:41:37     INFO - ==> process 1600 launched child process 1838
[task 2022-03-01T22:41:37.918Z] 22:41:37     INFO - ==> process 1600 launched child process 1857
[task 2022-03-01T22:41:37.918Z] 22:41:37     INFO - ==> process 1600 launched child process 2091
[task 2022-03-01T22:41:38.963Z] 22:41:38     INFO - Found child pids: {1728, 1857, 1803, 2091, 1838, 1710, 1621}
[task 2022-03-01T22:41:40.089Z] 22:41:39     INFO - Failed to get child procs
[task 2022-03-01T22:41:41.075Z] 22:41:40     INFO - Killing process: 1728
[task 2022-03-01T22:41:41.181Z] 22:41:41     INFO - TEST-INFO | started process screentopng
[task 2022-03-01T22:43:11.536Z] 22:43:11     INFO - TEST-INFO | screentopng: exit 0
[task 2022-03-01T22:43:11.543Z] 22:43:11     INFO - Can't trigger Breakpad, just killing process
[task 2022-03-01T22:43:13.735Z] 22:43:13     INFO - psutil found pid 1728 dead
[task 2022-03-01T22:43:13.737Z] 22:43:13     INFO - Killing process: 1857
[task 2022-03-01T22:43:13.737Z] 22:43:13     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-03-01T22:43:13.737Z] 22:43:13     INFO - Can't trigger Breakpad, just killing process
[task 2022-03-01T22:43:13.846Z] 22:43:13     INFO - psutil found pid 1857 dead
[task 2022-03-01T22:43:13.847Z] 22:43:13     INFO - Killing process: 1803
[task 2022-03-01T22:43:13.847Z] 22:43:13     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-03-01T22:43:13.847Z] 22:43:13     INFO - Can't trigger Breakpad, just killing process
[task 2022-03-01T22:43:14.184Z] 22:43:14     INFO - psutil found pid 1803 dead
[task 2022-03-01T22:43:14.185Z] 22:43:14     INFO - Killing process: 2091
[task 2022-03-01T22:43:14.186Z] 22:43:14     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-03-01T22:43:14.186Z] 22:43:14     INFO - Can't trigger Breakpad, just killing process
[task 2022-03-01T22:43:14.443Z] 22:43:14     INFO - psutil found pid 2091 dead
[task 2022-03-01T22:43:14.443Z] 22:43:14     INFO - Killing process: 1838
[task 2022-03-01T22:43:14.443Z] 22:43:14     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-03-01T22:43:14.443Z] 22:43:14     INFO - Can't trigger Breakpad, just killing process
[task 2022-03-01T22:43:14.548Z] 22:43:14     INFO - psutil found pid 1838 dead
[task 2022-03-01T22:43:14.550Z] 22:43:14     INFO - Killing process: 1710
[task 2022-03-01T22:43:14.550Z] 22:43:14     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-03-01T22:43:14.550Z] 22:43:14     INFO - Can't trigger Breakpad, just killing process
[task 2022-03-01T22:43:14.724Z] 22:43:14     INFO - psutil found pid 1710 dead
[task 2022-03-01T22:43:14.725Z] 22:43:14     INFO - Killing process: 1621
[task 2022-03-01T22:43:14.725Z] 22:43:14     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-03-01T22:43:14.726Z] 22:43:14     INFO - Can't trigger Breakpad, just killing process
[task 2022-03-01T22:43:14.726Z] 22:43:14     INFO - Error: Failed to kill process 1621: psutil.NoSuchProcess no process found with pid 1621
[task 2022-03-01T22:43:14.727Z] 22:43:14     INFO - Killing process: 1600
[task 2022-03-01T22:43:14.727Z] 22:43:14     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-03-01T22:43:14.728Z] 22:43:14     INFO - Can't trigger Breakpad, just killing process
[task 2022-03-01T22:43:44.746Z] 22:43:44     INFO - psutil found pid 1600 dead
[task 2022-03-01T22:43:44.746Z] 22:43:44     INFO - failed to kill pid 2291 after 30s
[task 2022-03-01T22:43:44.746Z] 22:43:44     INFO - psutil found pid 1600 dead
[task 2022-03-01T22:43:44.747Z] 22:43:44     INFO - TEST-INFO | Main app process: exit 0
[task 2022-03-01T22:43:44.748Z] 22:43:44     INFO - runtests.py | Application ran for: 0:24:11.892026
[task 2022-03-01T22:43:44.748Z] 22:43:44     INFO - zombiecheck | Reading PID log: /tmp/tmpz5jyxpripidlog
[task 2022-03-01T22:43:44.748Z] 22:43:44     INFO - ==> process 1600 launched child process 1621
[task 2022-03-01T22:43:44.750Z] 22:43:44     INFO - ==> process 1600 launched child process 1710
[task 2022-03-01T22:43:44.752Z] 22:43:44     INFO - ==> process 1600 launched child process 1728
[task 2022-03-01T22:43:44.752Z] 22:43:44     INFO - ==> process 1600 launched child process 1803
[task 2022-03-01T22:43:44.752Z] 22:43:44     INFO - ==> process 1600 launched child process 1838
[task 2022-03-01T22:43:44.752Z] 22:43:44     INFO - ==> process 1600 launched child process 1857
[task 2022-03-01T22:43:44.752Z] 22:43:44     INFO - ==> process 1600 launched child process 2091
[task 2022-03-01T22:43:44.752Z] 22:43:44     INFO - ==> process 1600 launched child process 2291
[task 2022-03-01T22:43:44.752Z] 22:43:44     INFO - zombiecheck | Checking for orphan process with PID: 1728
[task 2022-03-01T22:43:44.752Z] 22:43:44     INFO - zombiecheck | Checking for orphan process with PID: 1857
[task 2022-03-01T22:43:44.753Z] 22:43:44     INFO - zombiecheck | Checking for orphan process with PID: 1803
[task 2022-03-01T22:43:44.753Z] 22:43:44     INFO - zombiecheck | Checking for orphan process with PID: 2091
[task 2022-03-01T22:43:44.753Z] 22:43:44     INFO - zombiecheck | Checking for orphan process with PID: 1838
[task 2022-03-01T22:43:44.753Z] 22:43:44     INFO - zombiecheck | Checking for orphan process with PID: 1710
[task 2022-03-01T22:43:44.753Z] 22:43:44     INFO - zombiecheck | Checking for orphan process with PID: 2291
[task 2022-03-01T22:43:44.753Z] 22:43:44     INFO - zombiecheck | Checking for orphan process with PID: 1621
[task 2022-03-01T22:43:44.754Z] 22:43:44     INFO - Stopping web server
[task 2022-03-01T22:43:44.780Z] 22:43:44     INFO - Server shut down.
[task 2022-03-01T22:43:44.803Z] 22:43:44     INFO - Web server killed.
[task 2022-03-01T22:43:44.804Z] 22:43:44     INFO - Stopping web socket server
[task 2022-03-01T22:43:44.824Z] 22:43:44     INFO - Stopping ssltunnel
[task 2022-03-01T22:43:44.844Z] 22:43:44  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2022-03-01T22:43:44.845Z] 22:43:44     INFO - runtests.py | Running tests: end.
[task 2022-03-01T22:43:44.928Z] 22:43:44     INFO - Buffered messages finished
[task 2022-03-01T22:43:44.928Z] 22:43:44     INFO -  TEST-INFO | checking window state
[task 2022-03-01T22:43:44.928Z] 22:43:44     INFO -  Browser Chrome Test Summary
[task 2022-03-01T22:43:44.929Z] 22:43:44     INFO -  	Passed: 0
[task 2022-03-01T22:43:44.930Z] 22:43:44     INFO -  	Failed: 0
[task 2022-03-01T22:43:44.930Z] 22:43:44     INFO -  	Todo: 0
[task 2022-03-01T22:43:44.930Z] 22:43:44     INFO -  	Mode: e10s
[task 2022-03-01T22:43:44.930Z] 22:43:44     INFO -  *** End BrowserChrome Test Results ***
[task 2022-03-01T22:43:44.930Z] 22:43:44     INFO - Buffered messages finished
[task 2022-03-01T22:43:44.930Z] 22:43:44     INFO - SUITE-END | took 1453s
[task 2022-03-01T22:43:45.011Z] 22:43:45    ERROR - Return code: 1
[task 2022-03-01T22:43:45.016Z] 22:43:45     INFO - TinderboxPrint: mochitest-mochitest-devtools-chrome<br/>124/0/0
[task 2022-03-01T22:43:45.016Z] 22:43:45    ERROR - # TBPL FAILURE #
[task 2022-03-01T22:43:45.016Z] 22:43:45  WARNING - setting return code to 2
[task 2022-03-01T22:43:45.016Z] 22:43:45    ERROR - The mochitest suite: mochitest-devtools-chrome ran with return status: FAILURE

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1757655&startday=2022-02-28&endday=2022-03-06&tree=all

Comment 2

[Intermittent Failures Robot]

2 failures in 2837 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• linux1804-64-asan-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1757655&startday=2022-03-07&endday=2022-03-13&tree=all

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.