Open Bug 1582327 Opened 5 years ago Updated 10 months ago

Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/content/tests/chrome/test_bug331215.xhtml | application timed out after 370 seconds with no output

Categories

(Toolkit :: Find Toolbar, defect, P5)

defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

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

Attachments

(1 file)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=267343567&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/fPZQbuTkTiydoOnnf_cr1A/runs/0/artifacts/public/logs/live_backing.log


[task 2019-09-18T23:52:26.605Z] 23:52:26 INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | Findfield status attribute should not have been 'notfound' after entering latest
[task 2019-09-18T23:52:26.605Z] 23:52:26 INFO - Starting test with browser 'content-remote'
[task 2019-09-18T23:52:26.605Z] 23:52:26 INFO - Buffered messages finished
[task 2019-09-18T23:52:26.605Z] 23:52:26 ERROR - TEST-UNEXPECTED-TIMEOUT | toolkit/content/tests/chrome/test_bug331215.xul | application timed out after 370 seconds with no output
[task 2019-09-18T23:52:26.605Z] 23:52:26 ERROR - Force-terminating active process(es).
[task 2019-09-18T23:52:26.605Z] 23:52:26 INFO - Determining child pids from psutil...
[task 2019-09-18T23:52:26.605Z] 23:52:26 INFO - [2068, 2071]
[task 2019-09-18T23:52:26.606Z] 23:52:26 INFO - ==> process 2067 launched child process 2068
[task 2019-09-18T23:52:26.606Z] 23:52:26 INFO - ==> process 2067 launched child process 2069
[task 2019-09-18T23:52:26.611Z] 23:52:26 INFO - ==> process 2067 launched child process 2070
[task 2019-09-18T23:52:26.611Z] 23:52:26 INFO - ==> process 2067 launched child process 2071
[task 2019-09-18T23:52:26.612Z] 23:52:26 INFO - Found child pids: set([2068, 2069, 2070, 2071])
[task 2019-09-18T23:52:26.612Z] 23:52:26 INFO - Failed to get child procs
[task 2019-09-18T23:52:26.612Z] 23:52:26 INFO - Killing process: 2068
[task 2019-09-18T23:52:26.612Z] 23:52:26 INFO - TEST-INFO | started process screencapture
[task 2019-09-18T23:52:26.731Z] 23:52:26 INFO - TEST-INFO | screencapture: exit 0
[task 2019-09-18T23:52:26.731Z] 23:52:26 INFO - Killing process: 2069
[task 2019-09-18T23:52:26.731Z] 23:52:26 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-18T23:52:26.731Z] 23:52:26 INFO - Can't trigger Breakpad, process no longer exists
[task 2019-09-18T23:52:26.731Z] 23:52:26 INFO - Killing process: 2070
[task 2019-09-18T23:52:26.731Z] 23:52:26 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-18T23:52:26.731Z] 23:52:26 INFO - Can't trigger Breakpad, process no longer exists
[task 2019-09-18T23:52:26.731Z] 23:52:26 INFO - Killing process: 2071
[task 2019-09-18T23:52:26.731Z] 23:52:26 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-18T23:52:26.733Z] 23:52:26 INFO - Killing process: 2067
[task 2019-09-18T23:52:26.733Z] 23:52:26 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-18T23:52:27.108Z] 23:52:27 INFO - psutil found pid 2067 dead
[task 2019-09-18T23:52:27.173Z] 23:52:27 WARNING - runtests.py | Failed to get app exit code - running/crashed?
[task 2019-09-18T23:52:27.173Z] 23:52:27 INFO - TEST-INFO | Main app process: exit 0
[task 2019-09-18T23:52:27.173Z] 23:52:27 INFO - runtests.py | Application ran for: 0:07:07.980306
[task 2019-09-18T23:52:27.174Z] 23:52:27 INFO - zombiecheck | Reading PID log: /var/folders/4z/gmjb5mfn7m15rdy406rr641h000017/T/tmp8s2BJgpidlog
[task 2019-09-18T23:52:27.174Z] 23:52:27 INFO - ==> process 2067 launched child process 2068
[task 2019-09-18T23:52:27.174Z] 23:52:27 INFO - ==> process 2067 launched child process 2069
[task 2019-09-18T23:52:27.175Z] 23:52:27 INFO - ==> process 2067 launched child process 2070
[task 2019-09-18T23:52:27.175Z] 23:52:27 INFO - ==> process 2067 launched child process 2071
[task 2019-09-18T23:52:27.175Z] 23:52:27 INFO - zombiecheck | Checking for orphan process with PID: 2068
[task 2019-09-18T23:52:27.175Z] 23:52:27 INFO - zombiecheck | Checking for orphan process with PID: 2069
[task 2019-09-18T23:52:27.175Z] 23:52:27 INFO - zombiecheck | Checking for orphan process with PID: 2070
[task 2019-09-18T23:52:27.175Z] 23:52:27 INFO - zombiecheck | Checking for orphan process with PID: 2071
[task 2019-09-18T23:52:27.175Z] 23:52:27 INFO - mozcrash Copy/paste: /Users/cltbld/tasks/task_1568849388/build/macosx64-minidump_stackwalk /var/folders/4z/gmjb5mfn7m15rdy406rr641h000017/T/tmp7n4CGX.mozrunner/minidumps/26570C0C-38D2-4712-AA4B-02E707302944.dmp /Users/cltbld/tasks/task_1568849388/build/symbols
[task 2019-09-18T23:52:27.180Z] 23:52:27 INFO - mozcrash Saved minidump as /Users/cltbld/tasks/task_1568849388/build/blobber_upload_dir/26570C0C-38D2-4712-AA4B-02E707302944.dmp
[task 2019-09-18T23:52:27.181Z] 23:52:27 INFO - PROCESS-CRASH | Main app process exited normally | application crashed [None]

Sure, but it seems that the test itself may be unstable. It's also disabled if webrender is enabled or debug build on Windows...

Flags: needinfo?(masayuki)

It starts from part 10 of bug 1540029. It stops allocating TextEditRules and HTMLEditRules. Some methods check whether they were allocated, but the patch makes them check whether the initialization which they did instead. If we hit the difference (whether initialization succeeded or not) is, it should be in the log as warning message. However, it's not recorded so that I'm thinking that the patch changes timing of something since the test looks like really complicated async test. I'll try to investigate which await causes the timeout.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=7062585c0840ac10cba880ce6d0a924f6ffe40f3
Log is here:

[task 2019-09-20T06:34:45.800Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | startTestWithBrowser(content)... 
[task 2019-09-20T06:34:45.800Z] 06:34:45     INFO - Starting test with browser 'content'
[task 2019-09-20T06:34:45.800Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | BrowserTestUtils.browserLoaded(gBrowser)... 
[task 2019-09-20T06:34:45.801Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | Got BrowserTestUtils.browserLoaded(gBrowser) 
[task 2019-09-20T06:34:45.801Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | onDocumentLoaded... 
[task 2019-09-20T06:34:45.801Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | promiseEnterStringIntoFindField("test")... 
[task 2019-09-20T06:34:45.801Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | Got promiseEnterStringIntoFindField("test") 
[task 2019-09-20T06:34:45.801Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | promiseEnterStringIntoFindField("l")... 
[task 2019-09-20T06:34:45.801Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | Got promiseEnterStringIntoFindField("l") 
[task 2019-09-20T06:34:45.801Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | Findfield status attribute should have been 'notfound' after entering test 
[task 2019-09-20T06:34:45.801Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | promiseEnterStringIntoFindField("a")... 
[task 2019-09-20T06:34:45.802Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | Got promiseEnterStringIntoFindField("a") 
[task 2019-09-20T06:34:45.802Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | Findfield status attribute should not have been 'notfound' after entering latest 
[task 2019-09-20T06:34:45.802Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | Got onDocumentLoaded 
[task 2019-09-20T06:34:45.802Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | Got startTestWithBrowser(content) 
[task 2019-09-20T06:34:45.802Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | startTestWithBrowser(content-remote)... 
[task 2019-09-20T06:34:45.802Z] 06:34:45     INFO - Starting test with browser 'content-remote'
[task 2019-09-20T06:34:45.803Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | BrowserTestUtils.browserLoaded(gBrowser)... 
[task 2019-09-20T06:34:45.803Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | Got BrowserTestUtils.browserLoaded(gBrowser) 
[task 2019-09-20T06:34:45.803Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | onDocumentLoaded... 
[task 2019-09-20T06:34:45.803Z] 06:34:45     INFO - TEST-PASS | toolkit/content/tests/chrome/test_bug331215.xul | promiseEnterStringIntoFindField("test")... 
[task 2019-09-20T06:34:45.803Z] 06:34:45     INFO - Buffered messages finished
[task 2019-09-20T06:34:45.803Z] 06:34:45    ERROR - TEST-UNEXPECTED-TIMEOUT | toolkit/content/tests/chrome/test_bug331215.xul | application timed out after 370 seconds with no output
[task 2019-09-20T06:34:45.803Z] 06:34:45    ERROR - Force-terminating active process(es).

So, when startTestWithBrowser() is called with "content-remote", promiseEnterStringIntoFindField("test") may not receive expected onFindResult from the findbar.

mikedeboer: You struggled with similar timeout of this test in bug 1261233, do you have some ideas?

Flags: needinfo?(mdeboer)
Whiteboard: [stockwell needswork:owner]
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/content/tests/chrome/test_bug331215.xul | application timed out after 370 seconds with no output → Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/content/tests/chrome/test_bug331215.xhtml,test_bug331215.xul | application timed out after 370 seconds with no output
Pushed by csabou@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ab2e160e1e1d
Disable test_bug331215 on mac debug for frequent failures. r=egao
Keywords: leave-open
Whiteboard: [stockwell needswork:owner] → [stockwell disabled]
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/content/tests/chrome/test_bug331215.xhtml,test_bug331215.xul | application timed out after 370 seconds with no output → Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/content/tests/chrome/test_bug331215.xhtml | application timed out after 370 seconds with no output
Has Regression Range: --- → yes
Severity: normal → S3

Clear a needinfo that is pending on an inactive user.

Inactive users most likely will not respond; if the missing information is essential and cannot be collected another way, the bug maybe should be closed as INCOMPLETE.

For more information, please visit BugBot documentation.

Flags: needinfo?(mdeboer)

It seems that this is not reproducible in this 2 years. So, I guess that we can enable this test on macOS and close this bug.

Looks like it would still fail on mac debug - try push.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: