979552 - Frequent Android 2.3 testAddSearchEngine, testBookmarkFolders | Automation Error: Missing end of test marker (process crashed?)

Status: RESOLVED WONTFIX

(Firefox for Android Graveyard :: Testing, defect)

Description

[Geoff Brown [:gbrown]]

Very much like bug 975155...

https://tbpl.mozilla.org/php/getParsedLog.php?id=35600530&tree=Ash&full=1#error7

09:07:59     INFO -  0 INFO SimpleTest START
09:07:59     INFO -  1 INFO TEST-START | testSettingsMenuItems
09:07:59     INFO -  2 INFO TEST-PASS | testSettingsMenuItems | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready
09:07:59     INFO -  EventExpecter: no longer listening for Gecko:Ready
09:07:59     INFO -  waitForText timeout on ^Settings$
09:07:59     INFO -  waitForText timeout on Enter Search
09:07:59     INFO -  3 INFO TEST-PASS | testSettingsMenuItems | Browser toolbar URL stayed the same - about:home should equal about:home
09:07:59     INFO -  INFO | automation.py | Application ran for: 0:02:05.432812
09:07:59     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmplLfBh5pidlog
09:07:59     INFO -  /data/anr/traces.txt not found
09:07:59     INFO -  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
09:07:59     INFO -  runtests.py | Running tests: end.
09:07:59     INFO -  Mochi-Remote ERROR | Automation Error: Missing end of test marker (process crashed?)

09:07:59     INFO -  03-04 08:59:43.263 W/GeckoGLController( 1551): GLController::serverSurfaceChanged(1024, 743)
09:07:59     INFO -  03-04 08:59:43.287 W/GeckoGLController( 1551): GLController::resumeCompositor(1024, 743) and mCompositorCreated=true
09:07:59     INFO -  03-04 08:59:43.373 W/GeckoGLController( 1551): done GLController::resumeCompositor
09:07:59     INFO -  03-04 08:59:43.443 W/GeckoGLController( 1551): GLController::updateCompositor with mCompositorCreated=true
09:07:59     INFO -  03-04 08:59:43.443 W/GeckoGLController( 1551): GLController::resumeCompositor(1024, 743) and mCompositorCreated=true
09:07:59     INFO -  03-04 08:59:44.993 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 08:59:46.114 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 08:59:47.223 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 08:59:49.303 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 08:59:49.723 W/ActivityManager(   65): Launch timeout has expired, giving up wake lock!
09:07:59     INFO -  03-04 08:59:50.113 W/ActivityManager(   65): Activity idle timeout for HistoryRecord{40649c40 org.mozilla.fennec/org.mozilla.gecko.preferences.GeckoPreferences}
09:07:59     INFO -  03-04 08:59:52.243 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 08:59:53.033 W/ActivityManager(   65): Activity idle timeout for HistoryRecord{40721998 org.mozilla.fennec/.App}
09:07:59     INFO -  03-04 08:59:53.263 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 08:59:54.263 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 08:59:55.263 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 08:59:57.273 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:01.293 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:02.293 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:03.383 I/Robocop ( 1551): waitForText timeout on Enter Search
09:07:59     INFO -  03-04 09:00:03.903 I/Robocop ( 1551): 3 INFO TEST-PASS | testSettingsMenuItems | Browser toolbar URL stayed the same - about:home should equal about:home
09:07:59     INFO -  03-04 09:00:05.293 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:05.533 E/GeckoConsole( 1551): 1393952405532	addons.updates	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
09:07:59     INFO -  03-04 09:00:05.533 I/Gecko   ( 1551): 1393952405532	addons.updates	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
09:07:59     INFO -  03-04 09:00:05.573 E/GeckoConsole( 1551): 1393952405574	addons.updates	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
09:07:59     INFO -  03-04 09:00:05.573 I/Gecko   ( 1551): 1393952405574	addons.updates	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
09:07:59     INFO -  03-04 09:00:05.605 E/GeckoConsole( 1551): 1393952405608	addons.updates	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
09:07:59     INFO -  03-04 09:00:05.605 I/Gecko   ( 1551): 1393952405608	addons.updates	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
09:07:59     INFO -  03-04 09:00:09.300 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:12.293 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:13.303 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:16.293 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:17.314 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:21.310 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:23.303 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:25.321 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:29.324 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:30.323 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:33.324 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:33.915 W/WindowManager(   65): Input event injection timed out.
09:07:59     INFO -  03-04 09:00:34.323 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:37.333 W/SharedBufferStack( 1551): waitForCondition(LockCondition) timed out (identity=55, status=0). CPU may be pegged. trying again.
09:07:59     INFO -  03-04 09:00:38.923 I/InputDispatcher(   65): Application is not responding: AppWindowToken{40725cd0 token=HistoryRecord{40721998 org.mozilla.fennec/.App}} - Window{40616d90 org.mozilla.fennec/org.mozilla.fennec.App paused=false}.  5005.7ms since event, 5002.8ms since wait started
09:07:59     INFO -  03-04 09:00:38.923 I/WindowManager(   65): Input event dispatching timed out sending to org.mozilla.fennec/org.mozilla.fennec.App
09:07:59     INFO -  03-04 09:00:38.933 D/AndroidRuntime( 1542): Shutting down VM
09:07:59     INFO -  03-04 09:00:38.953 I/ActivityManager(   65): Force stopping package org.mozilla.fennec uid=10017
09:07:59     INFO -  03-04 09:00:38.953 I/Process (   65): Sending signal. PID: 1598 SIG: 9

Comment 1

[Geoff Brown [:gbrown]]

All of these look similar and fail with "CPU may be pegged".

Comment 2

[Geoff Brown [:gbrown]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/8bcac46ba183

Comment 3

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/8bcac46ba183

Comment 4

[Geoff Brown [:gbrown]]

Verified that this still happens, if skipped tests are enabled:

https://tbpl.mozilla.org/php/getParsedLog.php?id=41585120&tree=Ash&full=1#error4

00:57:33     INFO -  1 INFO TEST-START | testBookmarkFolders
00:57:33     INFO -  2 INFO TEST-PASS | testBookmarkFolders | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready
00:57:33     INFO -  EventExpecter: no longer listening for Gecko:Ready
00:57:33     INFO -  3 INFO TEST-PASS | testBookmarkFolders | Generating a random Guid for the bookmark - We could not generate a Guid for the bookmark
00:57:33     INFO -  4 INFO TEST-PASS | testBookmarkFolders | Inserted at:  - content://org.mozilla.fennec.db.browser/bookmarks/10?profile=default&sync=true
00:57:33     INFO -  5 INFO TEST-PASS | testBookmarkFolders | waiting for urlbar text to gain focus - urlbar text gained focus
00:57:33     INFO -  6 INFO TEST-PASS | testBookmarkFolders | Checking that the correct tab is displayed - The BOOKMARKS tab is displayed
00:57:33     INFO -  7 INFO TEST-PASS | testBookmarkFolders | waiting for urlbar text to gain focus - urlbar text gained focus
00:57:33     INFO -  8 INFO TEST-PASS | testBookmarkFolders | Checking that the correct tab is displayed - The BOOKMARKS tab is displayed
00:57:33     INFO -  
00:57:33  WARNING -  TEST-UNEXPECTED-FAIL | testBookmarkFolders | application timed out after 330 seconds with no output
00:57:33     INFO -  INFO | automation.py | Application ran for: 0:10:45.986804
00:57:33     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpDVIZ7Cpidlog
00:57:33     INFO -  /data/anr/traces.txt not found
00:57:33     INFO -  Stopping web server
00:57:33     INFO -  Stopping web socket server
00:57:33     INFO -  Stopping ssltunnel
00:57:33     INFO -  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
00:57:33     INFO -  runtests.py | Running tests: end.
00:57:33     INFO -  Mochi-Remote ERROR | runTests() exited with code 2
00:57:33     INFO -  Mochi-Remote ERROR | Automation Error: Missing end of test marker (process crashed?)
00:57:33     INFO -  Mochi-Remote INFO  | 
00:57:33     INFO -  06-12 00:30:03.264 I/Gecko   ( 1776): 1402533003271	addons.update-checker	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
00:57:33     INFO -  06-12 00:30:04.773 W/SharedBufferStack( 1776): waitForCondition(LockCondition) timed out (identity=75, status=0). CPU may be pegged. trying again.
00:57:33     INFO -  06-12 00:30:06.782 W/SharedBufferStack( 1776): waitForCondition(LockCondition) timed out (identity=75, status=0). CPU may be pegged. trying again.
00:57:33     INFO -  06-12 00:30:07.784 W/SharedBufferStack( 1776): waitForCondition(LockCondition) timed out (identity=75, status=0). CPU may be pegged. trying again.
00:57:33     INFO -  06-12 00:30:08.783 W/SharedBufferStack( 1776): waitForCondition(LockCondition) timed out (identity=75, status=0). CPU may be pegged. trying again.

Comment 5

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

testBookmarkFolders calls getInstrumentation.waitForIdleSync() around the time the application crashes - related?

Comment 6

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/testBookmarkFolders.java?rev=523e67cf4b9e#99

Comment 7

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

Attachment: Remove getInstrumentation().waitForIdleSync calls and re-enable tests.

I removed the `getInstrumentation().waitForIdleSync()` calls, as per comment 5,
and all tests besides testImportFromAndroid appear to work now. These calls did
not seem necessary, but I don't entirely know their intended purpose.

try: https://tbpl.mozilla.org/?tree=Try&rev=8d8f7a6e2c40

Comment 8

[Geoff Brown [:gbrown]]

Comment on attachment 8441766 [details] [diff] [review]
Remove getInstrumentation().waitForIdleSync calls and re-enable tests.

Review of attachment 8441766 [details] [diff] [review]:
-----------------------------------------------------------------

I do not like those waitForIdleSync calls and don't know what they are for either. They may be sleep() calls in disguise! I don't mind removing them.

Unfortunately, the tests are still crashing in your try run -- silently. In the first Android 2.3 rc1, https://tbpl.mozilla.org/php/getParsedLog.php?id=41844309&tree=Try&full=1, both testAddSearchEngine and testBookmarkFolders crashed, even though rc1 is green on tbpl. :(

Comment 9

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

Some interesting lines in testAddSearchEngine:

22:23:39     INFO -  06-16 22:02:32.036 W/SharedBufferStack(  645): waitForCondition(LockCondition) timed out (identity=24, status=0). CPU may be pegged. trying again.

22:23:39     INFO -  06-16 22:02:55.165 E/GeckoConsole(  645): 1402956175174	addons.update-checker	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found

22:23:39     INFO -  06-16 22:02:59.967 W/WindowManager(   64): Input event injection timed out.

22:23:39     INFO -  06-16 22:03:04.986 I/InputDispatcher(   64): Application is not responding: Window{406c15d0 org.mozilla.fennec/org.mozilla.fennec.App paused=false}.  35021.9ms since event, 5008.8ms since wait started

22:23:39     INFO -  06-16 22:03:04.986 I/WindowManager(   64): Input event dispatching timed out sending to org.mozilla.fennec/org.mozilla.fennec.App

The failure appears to be here: https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/testAddSearchEngine.java?rev=523e67cf4b9e#72

Comment 10

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

testBookmarkFolders appears to die in the same location as before, with waitForIdleSync.

testTitleBar appears not to have run, and the other tests also failed. :\

Comment 11

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

Not actively working on this.

Comment 12

[Geoff Brown [:gbrown]]

Bug 1058027 sounds like it deals with similar issues in real 2.3 devices but the fix did not resolve any test failures.

Comment 13

[Geoff Brown [:gbrown]]

Some of these tests have been deleted.

Comment 14

[Geoff Brown [:gbrown]]

Android 2.3 is no longer supported in Firefox 48+.

Test manifests were updated in bug 1251013.