Closed Bug 979552 Opened 7 years ago Closed 4 years ago

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

Categories

(Firefox for Android :: Testing, defect)

x86_64
Linux
defect
Not set
normal

Tracking

()

RESOLVED WONTFIX

People

(Reporter: gbrown, Assigned: gbrown)

References

Details

Attachments

(1 file)

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
Blocks: 967704
All of these look similar and fail with "CPU may be pegged".
Summary: Frequent Android 2.3 testSettingsMenuItems | Automation Error: Missing end of test marker (process crashed?) → Frequent Android 2.3 testAddSearchEngine, testBookmarkFolders, testSettingsMenuItems, testTitleBox | Automation Error: Missing end of test marker (process crashed?)
Summary: Frequent Android 2.3 testAddSearchEngine, testBookmarkFolders, testSettingsMenuItems, testTitleBox | Automation Error: Missing end of test marker (process crashed?) → Frequent Android 2.3 testAddSearchEngine, testBookmarkFolders, testImportFromAndroid, testSettingsMenuItems, testTitleBar | Automation Error: Missing end of test marker (process crashed?)
https://hg.mozilla.org/integration/mozilla-inbound/rev/8bcac46ba183
Whiteboard: [leave open] [test disabled on Android 2.3]
Blocks: 979921
No longer blocks: 967704
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.
testBookmarkFolders calls getInstrumentation.waitForIdleSync() around the time the application crashes - related?
Assignee: snorp → michael.l.comella
Status: NEW → ASSIGNED
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
Attachment #8441766 - Flags: review?(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. :(
Attachment #8441766 - Flags: review?(gbrown) → feedback+
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
testBookmarkFolders appears to die in the same location as before, with waitForIdleSync.

testTitleBar appears not to have run, and the other tests also failed. :\
Not actively working on this.
Assignee: michael.l.comella → nobody
Status: ASSIGNED → NEW
Bug 1058027 sounds like it deals with similar issues in real 2.3 devices but the fix did not resolve any test failures.
Some of these tests have been deleted.
Summary: Frequent Android 2.3 testAddSearchEngine, testBookmarkFolders, testImportFromAndroid, testSettingsMenuItems, testTitleBar | Automation Error: Missing end of test marker (process crashed?) → Frequent Android 2.3 testAddSearchEngine, testBookmarkFolders | Automation Error: Missing end of test marker (process crashed?)
Whiteboard: [leave open] [test disabled on Android 2.3] → [test disabled on Android 2.3]
Android 2.3 is no longer supported in Firefox 48+.

Test manifests were updated in bug 1251013.
Assignee: nobody → gbrown
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → WONTFIX
Whiteboard: [test disabled on Android 2.3]
You need to log in before you can comment on or make changes to this bug.