Closed Bug 1116036 Opened 7 years ago Closed 6 years ago

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

Categories

(Firefox for Android Graveyard :: Testing, defect)

ARM
Android
defect
Not set
normal

Tracking

(firefox45 affected, firefox46 affected, firefox48 fixed)

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

People

(Reporter: philor, Assigned: mfinkle)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

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: 6 years ago
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.