Closed Bug 1116036 Opened 11 years ago Closed 9 years ago

Intermittent testHistoryService | testHistoryService.js - Simple 301 redirect makes 1 history item

Categories

(Firefox for Android Graveyard :: Testing, defect)

Product:
Firefox for Android Graveyard
Component:
Testing
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox45 affected, firefox46 affected, firefox48 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 48
Tracking Flags:
Tracking Status
firefox45 --- affected
firefox46 --- affected
firefox48 --- fixed

People

(Reporter: philor, Assigned: mfinkle)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

history-bumptimeout v0.1
971 bytes, patch
Margaret
: review+
Details | Diff | Splinter Review
use longer sleep after first load
3.08 KB, patch
mfinkle
: review+
Details | Diff | Splinter Review
No description provided.
This happens intermittently on the Android 4.3 emulator also. http://ftp.mozilla.org/pub/mozilla.org/mobile/try-builds/gbrown@mozilla.com-8215e218bc55/try-android-api-9/try_ubuntu64_vm_mobile_test-robocop-3-bm54-tests1-linux64-build31.txt.gz 19:46:21 INFO - testHistoryService.js | sleep start 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"\nTEST-INFO | testHistoryService.js | Observer: http:\/\/example.org\/tests\/robocop\/robocop_blank_02.html\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - testHistoryService.js | Observer: http://example.org/tests/robocop/robocop_blank_02.html 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"\nTEST-INFO | testHistoryService.js | sleep end\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - testHistoryService.js | sleep end 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"\nTEST-INFO | testHistoryService.js | visit counts: 2\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - testHistoryService.js | visit counts: 2 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"\nTEST-UNEXPECTED-FAIL | testHistoryService.js | Simple 301 redirect makes 1 history item - See following stack:\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 WARNING - TEST-UNEXPECTED-FAIL | testHistoryService | testHistoryService.js - Simple 301 redirect makes 1 history item - See following stack: 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"JS frame :: robocop_head.js :: do_throw :: line 471\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - testHistoryService.js | JS frame :: robocop_head.js :: do_throw :: line 471 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"JS frame :: robocop_head.js :: do_report_result :: line 573\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - testHistoryService.js | JS frame :: robocop_head.js :: do_report_result :: line 573 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"JS frame :: testHistoryService.js :: ok :: line 14\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - testHistoryService.js | JS frame :: testHistoryService.js :: ok :: line 14 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"JS frame :: testHistoryService.js :: <TOP_LEVEL> :: line 110\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - testHistoryService.js | JS frame :: testHistoryService.js :: <TOP_LEVEL> :: line 110 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"JS frame :: self-hosted :: next :: line 620\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - testHistoryService.js | JS frame :: self-hosted :: next :: line 620 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"JS frame :: resource:\/\/gre\/modules\/Task.jsm :: TaskImpl_run :: line 314\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - testHistoryService.js | JS frame :: resource://gre/modules/Task.jsm :: TaskImpl_run :: line 314 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - testHistoryService.js | native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0 19:46:21 INFO - TEST-PASS | testHistoryService | Given message occurred for registered event: {"message":"\nTEST-INFO | (xpcshell\/head.js) | exiting test\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS 19:46:21 INFO - (xpcshell/head.js) | exiting test 19:46:21 INFO - EventExpecter: no longer listening for Robocop:JS 19:46:21 INFO - Unregistered listener for Robocop:JS 19:46:21 INFO - TEST-OK | testHistoryService | took 120972ms 19:46:21 INFO - TEST-START | Shutdown 19:46:21 INFO - Passed: 40 19:46:21 INFO - Failed: 1
Whiteboard: [test disabled on android 4.3]
As part of bug 1184186, I tried re-writing testHistoryService as a mochitest; it intermittently fails the same way: https://treeherder.mozilla.org/#/jobs?repo=try&revision=1af11a37537f http://ftp.mozilla.org/pub/mozilla.org/mobile/try-builds/gbrown@mozilla.com-1af11a37537f/try-android-api-11/try_ubuntu64_vm_armv7_mobile_test-mochitest-chrome-bm118-tests1-linux64-build3.txt.gz 20:59:33 INFO - 193 INFO TEST-START | mobile/android/tests/browser/chrome/test_history_service.html 21:00:06 INFO - 194 INFO Error: Unable to restore focus, expect failures and timeouts. 21:00:06 INFO - 195 INFO Error: Unable to restore focus, expect failures and timeouts. 21:00:06 INFO - 196 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_history_service.html | Simple visit makes 1 history item 21:00:06 INFO - 197 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_history_service.html | Simple visit makes final history item 21:00:06 INFO - 198 INFO TEST-UNEXPECTED-FAIL | mobile/android/tests/browser/chrome/test_history_service.html | Simple 301 redirect makes 1 history item 21:00:06 INFO - run_test/<@chrome://mochitests/content/chrome/mobile/android/tests/browser/chrome/test_history_service.html:121:7 21:00:06 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:330:41 21:00:06 INFO - 199 INFO TEST-UNEXPECTED-FAIL | mobile/android/tests/browser/chrome/test_history_service.html | Simple 301 redirect makes final history item 21:00:06 INFO - run_test/<@chrome://mochitests/content/chrome/mobile/android/tests/browser/chrome/test_history_service.html:124:7 21:00:06 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:330:41 21:00:22 INFO - 200 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_history_service.html | JavaScript redirect makes 2 history items 21:00:22 INFO - 201 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_history_service.html | JavaScript redirect makes intermediate history item 21:00:22 INFO - 202 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_history_service.html | JavaScript redirect makes final history item 21:00:34 INFO - 203 INFO TEST-OK | mobile/android/tests/browser/chrome/test_history_service.html | took 64606ms
This seems to be spiking in frequency today.
I was hoping to be able to re-enable this test on 4.3, but I can't yet. Bumping the "wait for pages to load" timeout does make 2.3 very happy. 13 green rc3 triggers.
Assignee: nobody → mark.finkle
Attachment #8707876 - Flags: review?(margaret.leibovic)
Attachment #8707876 - Flags: review?(margaret.leibovic) → review+
2.3 failures are much improved - thank you! - but a few remain. Would an even larger timeout resolve those?
Flags: needinfo?(mark.finkle)
(In reply to Geoff Brown [:gbrown] from comment #134) > 2.3 failures are much improved - thank you! - but a few remain. Would an > even larger timeout resolve those? You could try going to 8 seconds.
Flags: needinfo?(mark.finkle)
Blocks: 1252961
As-is, testHistoryService fails frequently on Android 4.3 and infrequently on 2.3. Significant increases to the wait time result in significant improvement on 4.3. 20 seconds: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f2a31350f81f 10 seconds: https://treeherder.mozilla.org/#/jobs?repo=try&revision=fd694244fc0a
At 20 seconds, there is no sign of this intermittent failure. At 10 seconds, there are some (low frequency) failures on 4.3. There are 4 sleeps, so increasing the wait time by +14 seconds adds about 1 minute to the test time: possible, but undesirable. I noticed that it is always the "Simple 301 redirect" case that fails, so tried increasing just the sleep immediately before that check: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c495a2670c89. This continued to fail on 4.3, fairly frequently -- as though it made no difference. I tried increasing the sleep time immediately before the "Simple 301 redirect" *and* the sleep before that: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ca52c93329f8. That is effective -- no failures. Just one more attempt at optimization, increasing only the first of the 2 sleeps in ca52c93329f8: https://treeherder.mozilla.org/#/jobs?repo=try&revision=47d3af5b37e8, running now.
(In reply to Geoff Brown [:gbrown] from comment #143) > Just one more attempt at optimization, increasing only the first of the 2 > sleeps in ca52c93329f8: > https://treeherder.mozilla.org/#/jobs?repo=try&revision=47d3af5b37e8, > running now. And that works: no failures.
I don't claim to understand why this is needed, but it allows us to run reliably on 4.3: https://treeherder.mozilla.org/#/jobs?repo=try&revision=47d3af5b37e8
Attachment #8728673 - Flags: review?(mark.finkle)
Comment on attachment 8728673 [details] [diff] [review] use longer sleep after first load Doesn't need to be pretty, just needs to work. Thanks, Geoff
Attachment #8728673 - Flags: review?(mark.finkle) → review+
https://hg.mozilla.org/mozilla-central/rev/663c40336889
Status: NEW → RESOLVED
Closed: 9 years ago
status-firefox48: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 48
Whiteboard: [test disabled on android 4.3]
See Also: → 1281335
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: