Closed Bug 968951 Opened 12 years ago Closed 10 years ago

Intermittent testBrowserProvider | application timed out after 330 seconds with no output

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

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: RyanVM, Assigned: gbrown)

References

Details

(Keywords: crash, intermittent-failure)

Attachments

(1 file)

Add debug statements to testBrowserProvider.
5.03 KB, patch
nalexander
: review+
Details | Diff | Splinter Review
https://tbpl.mozilla.org/php/getParsedLog.php?id=34213393&tree=B2g-Inbound Android 2.2 Armv6 Tegra b2g-inbound opt test robocop-1 on 2014-02-06 06:07:13 PST for push af1358bae3e3 slave: tegra-237 316 INFO TEST-START | testBrowserProvider - TestExpireHistory 317 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | All non-special bookmarks and folders were deleted - 7 should equal 7 318 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | All history entries were deleted - 0 should equal 0 319 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | All favicons were deleted - 0 should equal 0 320 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | All thumbnails were deleted - 0 should equal 0 321 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | Expected number of inserts matches - 3000 should equal 3000 322 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | 3000 history entries found - 3000 should equal 3000 323 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | Expected number of inserts matches - 3000 should equal 3000 324 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | 3000 thumbnails entries found - 3000 should equal 3000 325 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | 3000 history entries found - 3000 should equal 3000 326 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | 15 thumbnails found - 15 should equal 15 327 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | All non-special bookmarks and folders were deleted - 7 should equal 7 328 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | All history entries were deleted - 0 should equal 0 329 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | All favicons were deleted - 0 should equal 0 330 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | All thumbnails were deleted - 0 should equal 0 331 INFO TEST-PASS | testBrowserProvider - TestExpireHistory | Expected number of inserts matches - 3000 should equal 3000 TEST-UNEXPECTED-FAIL | testBrowserProvider | application timed out after 330 seconds with no output INFO | automation.py | Application ran for: 0:10:44.872522 INFO | zombiecheck | Reading PID log: /tmp/tmpOCW_dApidlog /data/anr/traces.txt not found WARNING | leakcheck | refcount logging is off, so leaks can't be detected! runtests.py | Running tests: end. Mochi-Remote WARNING | cleaning up pidfile '/builds/tegra-237/test/../runtestsremote.pid' was unsuccessful from the test harness Mochi-Remote ERROR | runTests() exited with code 2 Mochi-Remote ERROR | Automation Error: Missing end of test marker (process crashed?)
Most of the logcats here show nothing but 03-18 21:37:48.376 W/GeckoProfile( 4274): Requested profile directory missing. 03-18 21:37:48.376 W/GeckoProfile( 4274): Requested profile directory missing. 03-18 21:37:48.386 W/GeckoProfile( 4274): Requested profile directory missing. 03-18 21:37:48.386 W/GeckoProfile( 4274): Requested profile directory missing. 03-18 21:37:48.386 W/GeckoProfile( 4274): Requested profile directory missing. 03-18 21:37:48.406 W/GeckoProfile( 4274): Requested profile directory missing. An exception is https://tbpl.mozilla.org/php/getParsedLog.php?id=36361426&tree=B2g-Inbound (Comment 7): 03-18 16:26:52.881 W/GeckoDBUtils( 4280): Tried to insert an empty or non-byte-array image. Ignoring. 03-18 16:26:52.881 W/GeckoProfile( 4280): Requested profile directory missing. 03-18 16:26:52.881 W/GeckoDBUtils( 4280): Tried to insert an empty or non-byte-array image. Ignoring. 03-18 16:26:52.881 W/GeckoProfile( 4280): Requested profile directory missing. 03-18 16:26:52.881 W/GeckoDBUtils( 4280): Tried to insert an empty or non-byte-array image. Ignoring. 03-18 16:26:52.881 W/GeckoProfile( 4280): Requested profile directory missing. ...
Component: Awesomescreen → Testing
Depends on: 896109
(In reply to Geoff Brown [:gbrown] from comment #11) > Most of the logcats here show nothing but > > 03-18 21:37:48.376 W/GeckoProfile( 4274): Requested profile directory > missing. That just means something's doing work. Bug 896109. > 03-18 16:26:52.881 W/GeckoDBUtils( 4280): Tried to insert an empty or > non-byte-array image. Ignoring. > 03-18 16:26:52.881 W/GeckoProfile( 4280): Requested profile directory > missing. I suspect that's an Android string/resource dependency issue: sometimes resources end up in the wrong place, with hilarious or tragic results. This is probably some label ending up where a favicon should be.
This is looking a lot like broken webapp updating on the slaves, which only happens some (long) time after start up, which is only tickled by long tests such as this one. I checked 5 recent logs; all looked like: 04-02 09:39:48.706 I/Robocop ( 4525): 88 INFO TEST-PASS | testBrowserProvider - TestPositionBookmarks | All history entries were deleted - 0 should equal 0 04-02 09:40:09.326 E/GeckoConsole( 4525): 1396431609335 addons.update-checker WARN Request failed: http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found 04-02 09:40:09.326 I/Gecko ( 4525): 1396431609335 addons.update-checker WARN Request failed: http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found 04-02 09:40:09.336 E/GeckoConsole( 4525): 1396431609339 addons.update-checker WARN Request failed: http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found 04-02 09:40:09.336 I/Gecko ( 4525): 1396431609339 addons.update-checker WARN Request failed: http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found 04-02 09:40:09.336 E/GeckoConsole( 4525): 1396431609345 addons.update-checker WARN Request failed: http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found 04-02 09:40:09.336 I/Gecko ( 4525): 1396431609345 addons.update-checker WARN Request failed: http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found 04-02 09:41:06.176 I/Gecko ( 4525): periodic check for webapp updates 04-02 09:42:27.066 I/IdleService( 4525): Get idle time: time since reset 179827 msec 04-02 09:42:27.066 I/IdleService( 4525): Idle timer callback: current idle time 179827 msec 04-02 09:42:27.066 I/IdleService( 4525): next timeout 173 msec from now 04-02 09:42:27.066 I/IdleService( 4525): SetTimerExpiryIfBefore: next timeout 173 msec from now 04-02 09:42:27.066 I/IdleService( 4525): reset timer expiry to 183 msec from now 04-02 09:42:27.246 I/IdleService( 4525): Get idle time: time since reset 180010 msec 04-02 09:42:27.246 I/IdleService( 4525): Idle timer callback: current idle time 180010 msec 04-02 09:42:27.246 I/IdleService( 4525): next timeout 4294967114990 msec from now 04-02 09:42:27.246 I/IdleService( 4525): SetTimerExpiryIfBefore: next timeout 4294967114989 msec from now 04-02 09:42:27.246 I/IdleService( 4525): reset timer expiry to 4294967114999 msec from now 04-02 09:42:27.246 I/IdleService( 4525): Idle timer callback: tell observer 5ab5e480 user is idle 04-02 09:42:27.246 I/IdleService( 4525): Notifying idle-daily observers 04-02 09:42:27.256 I/IdleService( 4525): Remove observer 5ab5e480 (180 seconds), 0 remain idle 04-02 09:42:33.406 I/IdleService( 4525): Storing last idle time as 1396431747 04-02 09:42:33.406 I/IdleService( 4525): Register idle observer 5cb851b0 for 300 seconds 04-02 09:42:33.406 I/IdleService( 4525): Register: adjusting next switch from -1 to 300 seconds 04-02 09:42:33.406 I/IdleService( 4525): next timeout 113825 msec from now 04-02 09:42:33.406 I/IdleService( 4525): SetTimerExpiryIfBefore: next timeout 113825 msec from now 04-02 09:42:33.406 I/IdleService( 4525): reset timer expiry to 113835 msec from now 04-02 09:43:11.816 I/SUTAgentAndroid( 1501): 10.26.84.6 : ps 04-02 09:43:11.886 I/SUTAgentAndroid( 1501): 10.26.84.6 : activity 04-02 09:43:11.926 I/SUTAgentAndroid( 1501): 10.26.84.6 : isdir /mnt/sdcard/tests/logs 04-02 09:43:11.946 I/SUTAgentAndroid( 1501): 10.26.84.6 : cd /mnt/sdcard/tests/logs 04-02 09:43:11.966 I/SUTAgentAndroid( 1501): 10.26.84.6 : ls 04-02 09:43:11.986 I/SUTAgentAndroid( 1501): 10.26.84.6 : pull /mnt/sdcard/tests/logs/mochitest.log 0 04-02 09:43:32.016 I/SUTAgentAndroid( 1501): 10.26.84.6 : activity 04-02 09:43:52.036 I/SUTAgentAndroid( 1501): 10.26.84.6 : activity 04-02 09:44:12.067 I/SUTAgentAndroid( 1501): 10.26.84.6 : activity 04-02 09:44:12.136 I/SUTAgentAndroid( 1501): 10.26.84.6 : isdir /mnt/sdcard/tests/logs 04-02 09:44:12.166 I/SUTAgentAndroid( 1501): 10.26.84.6 : cd /mnt/sdcard/tests/logs 04-02 09:44:12.186 I/SUTAgentAndroid( 1501): 10.26.84.6 : ls 04-02 09:44:12.206 I/SUTAgentAndroid( 1501): 10.26.84.6 : pull /mnt/sdcard/tests/logs/mochitest.log 11020 That is, business as usual (not always up to the 88th message, some further) until we start updating webapps, then nothing, then hard kill by the harness. myk, can you investigate or redirect?
Flags: needinfo?(myk)
(In reply to Nick Alexander :nalexander from comment #31) > This is looking a lot like broken webapp updating on the slaves, which only > happens some (long) time after start up, which is only tickled by long tests > such as this one. That seems unlikely, given that robocop isn't running any webapp tests, so the slaves shouldn't have any webapps installed, and the periodic webapp update timer should exit early without doing anything that could stall the test run (f.e. attempt to access an unavailable external resource like the update check service). > I checked 5 recent logs; all looked like: > > 04-02 09:39:48.706 I/Robocop ( 4525): 88 INFO TEST-PASS | > testBrowserProvider - TestPositionBookmarks | All history entries were > deleted - 0 should equal 0 > 04-02 09:40:09.326 E/GeckoConsole( 4525): 1396431609335 > addons.update-checker WARN Request failed: > http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found > 04-02 09:40:09.326 I/Gecko ( 4525): 1396431609335 addons.update-checker > WARN Request failed: > http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found > 04-02 09:40:09.336 E/GeckoConsole( 4525): 1396431609339 > addons.update-checker WARN Request failed: > http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found > 04-02 09:40:09.336 I/Gecko ( 4525): 1396431609339 addons.update-checker > WARN Request failed: > http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found > 04-02 09:40:09.336 E/GeckoConsole( 4525): 1396431609345 > addons.update-checker WARN Request failed: > http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found > 04-02 09:40:09.336 I/Gecko ( 4525): 1396431609345 addons.update-checker > WARN Request failed: > http://10.26.84.6:30286/extensions-dummy/updateBackgroundURL - 404: Not Found > 04-02 09:41:06.176 I/Gecko ( 4525): periodic check for webapp updates > 04-02 09:42:27.066 I/IdleService( 4525): Get idle time: time since reset > 179827 msec … > That is, business as usual (not always up to the 88th message, some further) > until we start updating webapps, then nothing, then hard kill by the > harness. myk, can you investigate or redirect? To me that looks like: business as usual until 09:39:48, then a bunch of warnings at 09:40:09, then nothing for about a minute, then "periodic check for webapp updates" at 09:41:06. The webapp updater uses an nsIUpdateCallback that it registers with the nsIUpdateTimerManager via the update-timer category: https://github.com/mozilla/gecko-dev/blob/b344638c9b6a5282288f12f143f05cbd72bc094f/mobile/android/components/MobileComponents.manifest#L111-L116 So it gets called at some arbitrary time within the first few minutes of startup. I think what we're seeing here is something else stalling the test run long enough for the updater to get called, after which the updater (silently) does nothing because there's nothing to do. As for what specifically is stalling the run, I'm not the expert on Fennec robocop tests; perhaps mcomella can provide insight!
Flags: needinfo?(myk) → needinfo?(michael.l.comella)
It seems this may be a known issue (without a known cause). Here's final output line in the code [1] and the next comment, pasted below for convenience: /** * There's no reason why the following two parts should fail. * But sometimes they do, and I'm not going to spend the time * to figure out why in an unrelated bug. */ --- Committed in bug 975792. What follows next is a delete, query, etc. - nothing suspicious as the comment mentions. rnewman is the author of the comment. Richard, considering what you mentioned in your comment, I'm assuming you don't have anything to add? Note that I'm a little suspicious that the web app code fires (on a timer) reliably every time this test is run, give or take a few seconds, but then again, maybe the platform timers are just that accurate and this test is just that predictable. [1]: https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/testBrowserProvider.java?rev=523e67cf4b9e#67
Flags: needinfo?(michael.l.comella) → needinfo?(rnewman)
Might be a relationship between whatever root cause results in deletions not working, might not. But nothing much more to add than what we just discussed IRL.
Flags: needinfo?(rnewman)
I noticed that the next time we log is about halfway through the test [1]. That means the test can start hanging in `ensureEmptyDatabase` (between test cases), or in the test itself. There's nothing that stands out as problematic - there are deletions and queries in `ensureEmptyDatabase` and a few insertions in `TestPositionBookmarks`. I think it'd be helpful to add some log statements as I cannot repro this locally. [1]: https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/testBrowserProvider.java?rev=523e67cf4b9e#886
Assignee: nobody → michael.l.comella
Status: NEW → ASSIGNED
Comment on attachment 8404994 [details] [diff] [review] Add debug statements to testBrowserProvider. lgtm.
Attachment #8404994 - Flags: review?(rnewman) → review+
Please change the reviewer to nalexander on the pushed patch.
Keywords: checkin-needed, leave-open
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #69) > https://hg.mozilla.org/mozilla-central/rev/24b062e8494e Probably not worth backing out for but note that the reviewer tag is incorrect on the patch - the reviewer is nalexander, not rnewman.
comment 71 is irrelevant because it's on aurora (where this patch isn't). comment 72 fails at a different location (oh, boy!). TestPositionBookmarks passes, and later, TestExpireHistory fails at some point after [1], but before the `assertCountIsAndClose` and next `ensureEmptyDatabase`. Notably, we're not failing in `ensureEmptyDatabase` (right now). Let's wait and see what happens next. [1]: https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/testBrowserProvider.java?rev=24b062e8494e#1730
comment 74 is irrelevant (Aurora). In comment 75, the failure is in `ensureEmptyDatabase`, but before the lines rnewman pointed out as troublesome. The final output was here [1], which is before the next `assertCountIsAndClose`, a few lines later. I'm not sure why this happens. [1]: https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/testBrowserProvider.java?rev=24b062e8494e#63
comment 77 is TestPositionBookmarks again: ensureEmptyDatabase: Favicon deletion completed. ensureEmptyDatabase: Thumbnail deletion completed. testBrowserProvider: Database empty - Starting TestPositionBookmarks. TestPositionBookmarks: Folder inserted TEST-UNEXPECTED-FAIL | testBrowserProvider | application timed out after 330 seconds with no output --- The folder is inserted [1], but sometime before the bookmarks insertion (create a content values, and insert into the provider 1000+ times), we hang. I wonder if the insertion actually takes long enough to cause a hang - we should probably be using ContentProvider.bulkInsert [2]. Alternatively, maybe the device screen turns off from disuse, causing the test to stop (it's Robocop after all). If we can insert faster, maybe we can avoid the issue. Alternatively, maybe we can make this use the ContentProvider test framework. [3] [1]: https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/testBrowserProvider.java?rev=24b062e8494e#868 [2]: https://developer.android.com/reference/android/content/ContentProvider.html#bulkInsert%28android.net.Uri,%20android.content.ContentValues[]%29 [3]: https://developer.android.com/reference/android/test/ProviderTestCase2.html
(In reply to Michael Comella (:mcomella) from comment #78) > Alternatively, maybe the device screen turns off from disuse, causing the > test to stop (it's Robocop after all). That should be avoided by http://mxr.mozilla.org/mozilla-central/source/build/mobile/sutagent/android/watcher/WatcherService.java#299. Anything is possible I suppose, but the watcher's attempt to keep the screen on has always been effective in my experience (unless the Watcher is killed on low memory, or something like that).
(In reply to Michael Comella (:mcomella) from comment #78) > we should probably be using ContentProvider.bulkInsert [2]. Or not! From the bulkInsert docs: "or the default implementation will iterate over the values and call insert(Uri, ContentValues) on each of them."
Worth noting that all of these intermittents are Android 2.2.
Not actively working on this.
Assignee: michael.l.comella → nobody
Status: ASSIGNED → NEW
Assignee: nobody → gbrown
Status: NEW → RESOLVED
Closed: 10 years ago
Keywords: leave-open
Resolution: --- → WORKSFORME
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: