Open Bug 1366505 Opened 7 years ago Updated 2 years ago

Intermittent dom/base/test/chrome/test_nsITextInputProcessor.xhtml,test_nsITextInputProcessor.xul | Test timed out.

Categories

(Core :: DOM: Core & HTML, defect, P2)

defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

(In reply to OrangeFactor Robot from comment #3)
> 30 failures in 820 pushes (0.037 failures/push) were associated with this
> bug in the last 7 days. 
> 
> This is the #47 most frequent failure this week.  
> 
> ** This failure happened more than 30 times this week! Resolving this bug is
> a high priority. **
> 
> ** Try to resolve this bug as soon as possible. If unresolved for 2 weeks,
> the affected test(s) may be disabled. ** 

This is just a symptom of bug 1366686 and the test is very important for keeping trusting automated tests which synthesize keyboard events and/or composition events.
:masayuki, thanks for the info here- this bug has poppped up on our radar, we will see if it remains.
Whiteboard: [stockwell needswork]
Priority: -- → P5
Whiteboard: [stockwell needswork] → [stockwell unknown]
Comment 23 says there were 33 failures in the last week, but if I click on the link it doesn't show any. I'm not sure what that means. The failures were all on esr52, so it seems unlikely that there was a real regression.
Priority: -- → P2
yeah, esr52 seems odd to start a failure up, as this is not on beta or trunk, I wouldn't worry about this.
Whiteboard: [stockwell needswork:owner] → [stockwell unknown]
Component: DOM → DOM: Core & HTML
Summary: Intermittent dom/base/test/chrome/test_nsITextInputProcessor.xul | Test timed out. → Intermittent dom/base/test/chrome/test_nsITextInputProcessor.xhtml,test_nsITextInputProcessor.xul | Test timed out.

Failure has been observed on the Debian 10 test image that I am working to migrate to from the current Ubuntu 16.04 test image.

There are multiple other failures in mochitest-chrome under Debian 10, and I wonder if a bunch (if not all) of them are related.

Try: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=13513111a9183259074f1cfeaf773f37146be166&selectedJob=271937762
Log: https://taskcluster-artifacts.net/cp-PL4qBRkKTbhp2kw98RA/0/public/logs/live_backing.log

Excerpt:

[task 2019-10-18T17:28:29.982Z] 17:28:29     INFO - TEST-START | dom/base/test/chrome/test_nsITextInputProcessor.xul
[task 2019-10-18T17:28:30.063Z] 17:28:30     INFO - GECKO(3717) | JavaScript error: resource://specialpowers/SpecialPowersParent.jsm, line 605: TypeError: this.manager.rootFrameLoader is null
[task 2019-10-18T17:28:30.064Z] 17:28:30     INFO - GECKO(3717) | JavaScript error: , line 0: NS_ERROR_UNEXPECTED:
[task 2019-10-18T17:33:51.774Z] 17:33:51     INFO - TEST-INFO | started process screentopng
[task 2019-10-18T17:33:51.877Z] 17:33:51     INFO - TEST-INFO | screentopng: exit 0
[task 2019-10-18T17:33:51.878Z] 17:33:51     INFO - Buffered messages logged at 17:28:30
[task 2019-10-18T17:33:51.878Z] 17:33:51     INFO - must wait for load
[task 2019-10-18T17:33:51.879Z] 17:33:51     INFO - must wait for focus
[task 2019-10-18T17:33:51.880Z] 17:33:51     INFO - Buffered messages finished
[task 2019-10-18T17:33:51.882Z] 17:33:51     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/chrome/test_nsITextInputProcessor.xul | Test timed out. 
[task 2019-10-18T17:33:51.882Z] 17:33:51     INFO - SimpleTest.ok@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:277:18
[task 2019-10-18T17:33:51.883Z] 17:33:51     INFO - reportError@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:121:22
[task 2019-10-18T17:33:51.883Z] 17:33:51     INFO - TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:142:18
[task 2019-10-18T17:33:51.884Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.884Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.885Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.885Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.886Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.886Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.887Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.887Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.887Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.887Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - TestRunner.runTests/<@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:388:20
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - promise callback*TestRunner.runTests@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:375:50
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - RunSet.runtests@chrome://mochikit/content/tests/SimpleTest/setup.js:201:14
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - RunSet.runall@chrome://mochikit/content/tests/SimpleTest/setup.js:180:12
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - hookupTests@chrome://mochikit/content/tests/SimpleTest/setup.js:273:12
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:50:13
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:61:28
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:57:3
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - hookup@chrome://mochikit/content/tests/SimpleTest/setup.js:253:20
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - linkAndHookup@chrome://mochikit/content/harness.xul:45:3
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:50:13
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:61:28
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:57:3
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - getTestList@chrome://mochikit/content/chrome-harness.js:258:18
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - loadTests@chrome://mochikit/content/harness.xul:24:14
[task 2019-10-18T17:33:51.888Z] 17:33:51     INFO - EventListener.handleEvent*@chrome://mochikit/content/harness.xul:48:12
[task 2019-10-18T17:33:52.779Z] 17:33:52     INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/chrome/test_nsITextInputProcessor.xul | [SimpleTest.finish()] waitForFocus() was called a different number of times from the number of callbacks run.  Maybe the test terminated prematurely -- be sure to use SimpleTest.waitForExplicitFinish(). - got 1, expected +0
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - SimpleTest.is@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:322:16
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - afterCleanup@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1169:24
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - executeCleanupFunction@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1232:13
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - SimpleTest.finish@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1251:5
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - killTest@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:130:22
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - async*delayedKillTest@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:159:17
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:157:17
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.780Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - TestRunner.runTests/<@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:388:20
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - promise callback*TestRunner.runTests@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:375:50
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - RunSet.runtests@chrome://mochikit/content/tests/SimpleTest/setup.js:201:14
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - RunSet.runall@chrome://mochikit/content/tests/SimpleTest/setup.js:180:12
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - hookupTests@chrome://mochikit/content/tests/SimpleTest/setup.js:273:12
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:50:13
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:61:28
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:57:3
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - hookup@chrome://mochikit/content/tests/SimpleTest/setup.js:253:20
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - linkAndHookup@chrome://mochikit/content/harness.xul:45:3
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:50:13
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:61:28
[task 2019-10-18T17:33:52.781Z] 17:33:52     INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:57:3
[task 2019-10-18T17:33:52.782Z] 17:33:52     INFO - getTestList@chrome://mochikit/content/chrome-harness.js:258:18
[task 2019-10-18T17:33:52.782Z] 17:33:52     INFO - loadTests@chrome://mochikit/content/harness.xul:24:14
[task 2019-10-18T17:33:52.782Z] 17:33:52     INFO - EventListener.handleEvent*@chrome://mochikit/content/harness.xul:48:12
[task 2019-10-18T17:33:52.783Z] 17:33:52     INFO - GECKO(3717) | MEMORY STAT | vsize 2815MB | residentFast 317MB | heapAllocated 122MB
[task 2019-10-18T17:33:52.785Z] 17:33:52     INFO - TEST-OK | dom/base/test/chrome/test_nsITextInputProcessor.xul | took 322795ms
[task 2019-10-18T17:33:52.786Z] 17:33:52    ERROR - chrome://mochitests/content/chrome/dom/base/test/chrome/test_nsITextInputProcessor.xul logged result after SimpleTest.finish(): [SimpleTest.finish()] waitForFocus() was called a different number of times from the number of callbacks run.  Maybe the test terminated prematurely -- be sure to use SimpleTest.waitForExplicitFinish().
[task 2019-10-18T17:33:52.807Z] 17:33:52     INFO - TEST-START | dom/base/test/chrome/test_permission_isHandlingUserInput.xul
[task 2019-10-18T17:33:52.869Z] 17:33:52     INFO - GECKO(3717) | MEMORY STAT | vsize 2831MB | residentFast 321MB | heapAllocated 125MB
[task 2019-10-18T17:33:52.871Z] 17:33:52     INFO - TEST-OK | dom/base/test/chrome/test_permission_isHandlingUserInput.xul | took 66ms
[task 2019-10-18T17:33:52.893Z] 17:33:52     INFO - TEST-START | dom/base/test/chrome/test_range_getClientRectsAndTexts.html
[task 2019-10-18T17:33:52.941Z] 17:33:52     INFO - GECKO(3717) | MEMORY STAT | vsize 2831MB | residentFast 317MB | heapAllocated 119MB
[task 2019-10-18T17:33:52.941Z] 17:33:52     INFO - TEST-OK | dom/base/test/chrome/test_range_getClientRectsAndTexts.html | took 44ms
[task 2019-10-18T17:33:52.961Z] 17:33:52     INFO - TEST-START | dom/base/test/chrome/test_swapFrameLoaders.xul
[task 2019-10-18T17:33:55.635Z] 17:33:55     INFO - GECKO(3717) | MEMORY STAT | vsize 2834MB | residentFast 336MB | heapAllocated 131MB
[task 2019-10-18T17:33:55.650Z] 17:33:55     INFO - TEST-OK | dom/base/test/chrome/test_swapFrameLoaders.xul | took 2682ms
[task 2019-10-18T17:33:55.671Z] 17:33:55     INFO - TEST-START | dom/base/test/chrome/test_title.xul
[task 2019-10-18T17:33:55.928Z] 17:33:55     INFO - GECKO(3717) | MEMORY STAT | vsize 2835MB | residentFast 346MB | heapAllocated 135MB
[task 2019-10-18T17:33:55.944Z] 17:33:55     INFO - TEST-OK | dom/base/test/chrome/test_title.xul | took 265ms
[task 2019-10-18T17:33:55.972Z] 17:33:55     INFO - TEST-START | dom/base/test/chrome/test_windowroot.xul
[task 2019-10-18T17:33:56.000Z] 17:33:55     INFO - GECKO(3717) | MEMORY STAT | vsize 2834MB | residentFast 347MB | heapAllocated 137MB
[task 2019-10-18T17:33:56.007Z] 17:33:56     INFO - TEST-OK | dom/base/test/chrome/test_windowroot.xul | took 36ms
[task 2019-10-18T17:33:56.031Z] 17:33:56     INFO - TEST-START | Shutdown
[task 2019-10-18T17:33:56.032Z] 17:33:56     INFO - Passed:  868
[task 2019-10-18T17:33:56.032Z] 17:33:56     INFO - Failed:  3
[task 2019-10-18T17:33:56.032Z] 17:33:56     INFO - Todo:    3
[task 2019-10-18T17:33:56.033Z] 17:33:56     INFO - Mode:    non-e10s
[task 2019-10-18T17:33:56.034Z] 17:33:56     INFO - Slowest: 322795ms - chrome://mochitests/content/chrome/dom/base/test/chrome/test_nsITextInputProcessor.xul

:kmag - I see that you last modified test_nsITextInputProcessor.xul; could you shed some light into what the possible cause of the timeout may be? Thanks!

Flags: needinfo?(kmaglione+bmo)

Removing the debian10/ubuntu1804 blocker due to the issue being resolved by building the docker image differently.

No longer blocks: 1572247
Flags: needinfo?(kmaglione+bmo)
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.