Closed Bug 971093 Opened 12 years ago Closed 12 years ago

Intermittent testSettingsMenuItems | Exception caught - junit.framework.AssertionFailedError: Text string: '^Customize$' is not found!

Categories

(Firefox for Android Graveyard :: Testing, defect)

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

Tracking

(firefox29 unaffected, firefox30 fixed, firefox31 fixed, firefox-esr24 unaffected)

Status:
RESOLVED FIXED
Milestone:
Firefox 31
Tracking Flags:
Tracking Status
firefox29 --- unaffected
firefox30 --- fixed
firefox31 --- fixed
firefox-esr24 --- unaffected

People

(Reporter: RyanVM, Assigned: liuche)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Patch: Increase sleep for navigation
1.29 KB, patch
gbrown
: review+
Details | Diff | Splinter Review
https://tbpl.mozilla.org/php/getParsedLog.php?id=34495135&tree=Mozilla-Inbound Android 4.2 x86 Emulator mozilla-inbound opt test androidx86-set-4 on 2014-02-11 08:17:28 PST for push b5be94737a83 slave: talos-linux64-ix-063 08:48:03 INFO - 0 INFO SimpleTest START 08:48:03 INFO - 1 INFO TEST-START | testSettingsMenuItems 08:48:03 INFO - EventExpecter: no longer listening for Gecko:Ready 08:48:03 INFO - 2 INFO TEST-PASS | testSettingsMenuItems | Browser toolbar URL stayed the same - about:home should equal about:home 08:48:03 INFO - waitForText timeout on Settings 08:48:03 INFO - waitForCondition timeout after 10000 ms. 08:48:03 INFO - waitForEnabledText timeout on ^Customize$ 08:48:03 INFO - Exception caught during test! 08:48:03 INFO - junit.framework.AssertionFailedError: Text string: '^Customize$' is not found! 08:48:03 INFO - at junit.framework.Assert.fail(Assert.java:50) 08:48:03 INFO - at junit.framework.Assert.assertTrue(Assert.java:20) 08:48:03 INFO - at com.jayway.android.robotium.solo.Clicker.clickOnText(Clicker.java:383) 08:48:03 INFO - at com.jayway.android.robotium.solo.Solo.clickOnText(Solo.java:1028) 08:48:03 INFO - at org.mozilla.gecko.tests.testSettingsMenuItems.checkForSync(testSettingsMenuItems.java:131) 08:48:03 INFO - at org.mozilla.gecko.tests.testSettingsMenuItems.testSettingsMenuItems(testSettingsMenuItems.java:115) 08:48:03 INFO - at java.lang.reflect.Method.invokeNative(Native Method) 08:48:03 INFO - at java.lang.reflect.Method.invoke(Method.java:511) 08:48:03 INFO - at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:214) 08:48:03 INFO - at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:199) 08:48:03 INFO - at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:192) 08:48:03 INFO - at org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:150) 08:48:03 INFO - at junit.framework.TestCase.runBare(TestCase.java:134) 08:48:03 INFO - at junit.framework.TestResult$1.protect(TestResult.java:115) 08:48:03 INFO - at junit.framework.TestResult.runProtected(TestResult.java:133) 08:48:03 INFO - at junit.framework.TestResult.run(TestResult.java:118) 08:48:03 INFO - at junit.framework.TestCase.run(TestCase.java:124) 08:48:03 INFO - at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:190) 08:48:03 INFO - at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:175) 08:48:03 INFO - at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:555) 08:48:03 INFO - at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1661) 08:48:03 INFO - 3 INFO TEST-UNEXPECTED-FAIL | testSettingsMenuItems | Exception caught - junit.framework.AssertionFailedError: Text string: '^Customize$' is not found! 08:48:03 INFO - 4 INFO TEST-END | testSettingsMenuItems | finished in 91213ms 08:48:03 INFO - 5 INFO TEST-START | Shutdown 08:48:03 INFO - 6 INFO Passed: 1 08:48:03 WARNING - 7 INFO Failed: 1 08:48:03 WARNING - One or more unittests failed. 08:48:03 INFO - 8 INFO Todo: 0 08:48:03 INFO - 9 INFO SimpleTest FINISHED
08:48:03 INFO - 02-11 16:30:18.896 I/Robocop ( 2245): waitForText timeout on Settings 08:48:03 INFO - 02-11 16:30:29.097 I/Robocop ( 2245): waitForCondition timeout after 10000 ms. 08:48:03 INFO - 02-11 16:30:29.107 I/Robocop ( 2245): waitForEnabledText timeout on ^Customize$ 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'TOP SITES' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'BOOKMARKS' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'READING LIST' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'HISTORY' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Firefox: Support' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Firefox: Customize with add-ons' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Firefox Marketplace' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Add a site' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Add a site' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Add a site' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Add a site' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Add a site' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Add a site' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Most recent' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: 'Tabs from last time' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: '1' 08:48:03 INFO - 02-11 16:30:39.407 D/Robotium( 2245): '^Customize$' not found. Have found: '' Screenshot available. It verifies that the Settings menu is not displayed. Top Sites is selected.
Thankfully, there is a complete logcat at http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/4b90ba3c369ed602662d57b2afe24634249994ccffeda7515845330d66c878cbfb7a8ff34c1e160aac5dc65b0403e7a7cc9c25d1bb05dfd36617e450b4a293cb. It contains: 02-11 16:29:19.755 D/Robocop ( 2245): waiting for Gecko:Ready 02-11 16:29:19.755 I/Robocop ( 2245): EventExpecter: no longer listening for Gecko:Ready 02-11 16:29:19.785 D/InputEventConsistencyVerifier( 2245): KeyEvent: ACTION_UP but key was not down. 02-11 16:29:19.785 D/InputEventConsistencyVerifier( 2245): in android.view.ViewRootImpl@b32fc338 02-11 16:29:19.785 D/InputEventConsistencyVerifier( 2245): 0: sent at 423789000000, KeyEvent { action=ACTION_UP, keyCode=KEYCODE_MENU, scanCode=0, metaState=0, flags=0x8, repeatCount=0, eventTime=423789, downTime=423789, deviceId=-1, source=0x101 } 02-11 16:29:20.486 E/SurfaceFlinger( 809): ro.sf.lcd_density must be defined as a build property 02-11 16:29:22.726 W/EGL_emulation( 2245): eglSurfaceAttrib not implemented 02-11 16:29:22.745 I/InputDispatcher( 1218): Window 'Window{b336d1b8 u0 org.mozilla.fennec/org.mozilla.fennec.App}' spent 2963.9ms processing the last input event: KeyEvent(action=1, deviceId=-1, source=0x00000101) 02-11 16:29:22.745 I/Choreographer( 2245): Skipped 136 frames! The application may be doing too much work on its main thread. 02-11 16:29:24.005 I/Choreographer( 2245): Skipped 46 frames! The application may be doing too much work on its main thread. 02-11 16:29:25.096 I/ActivityManager( 1218): START u0 {cmp=org.mozilla.fennec/org.mozilla.gecko.preferences.GeckoPreferences} from pid 2245 02-11 16:29:28.835 I/IdleService( 2245): Get idle time: time since reset 13123 msec 02-11 16:29:28.835 I/IdleService( 2245): Idle timer callback: current idle time 13123 msec 02-11 16:29:28.835 I/IdleService( 2245): next timeout 1876 msec from now 02-11 16:29:28.835 I/IdleService( 2245): SetTimerExpiryIfBefore: next timeout 1876 msec from now 02-11 16:29:28.835 I/IdleService( 2245): reset timer expiry to 1886 msec from now 02-11 16:29:29.425 I/Choreographer( 2245): Skipped 259 frames! The application may be doing too much work on its main thread. 02-11 16:29:30.216 D/dalvikvm( 2245): GC_CONCURRENT freed 357K, 7% free 5500K/5884K, paused 12ms+2ms, total 20ms 02-11 16:29:30.725 I/IdleService( 2245): Get idle time: time since reset 15013 msec 02-11 16:29:30.725 I/IdleService( 2245): Idle timer callback: current idle time 15013 msec 02-11 16:29:30.725 I/IdleService( 2245): next timeout 164985 msec from now 02-11 16:29:30.725 I/IdleService( 2245): SetTimerExpiryIfBefore: next timeout 164985 msec from now 02-11 16:29:30.725 I/IdleService( 2245): reset timer expiry to 164995 msec from now 02-11 16:29:30.725 I/IdleService( 2245): Idle timer callback: tell observer 9b9ed2a0 user is idle 02-11 16:29:31.885 D/GeckoHealthRec( 2245): Recording session end: P 02-11 16:29:31.885 V/GeckoHealthRec( 2245): Recorded session entry for env 1, current is 1 02-11 16:29:31.885 D/GeckoSessInfo( 2245): Recording session done: 1392136150493 02-11 16:29:31.905 W/GeckoProfile( 2245): Requested profile directory missing. 02-11 16:29:32.556 E/SurfaceFlinger( 809): ro.sf.lcd_density must be defined as a build property 02-11 16:29:33.536 W/EGL_emulation( 2245): eglSurfaceAttrib not implemented 02-11 16:29:33.556 I/Choreographer( 2245): Skipped 98 frames! The application may be doing too much work on its main thread. 02-11 16:29:33.785 I/ActivityManager( 1218): Displayed org.mozilla.fennec/org.mozilla.gecko.preferences.GeckoPreferences: +1s900ms 02-11 16:29:33.785 I/GeckoHealth( 2245): fennec :: HealthReportBroadcastService :: Registering HealthReportPruneService. 02-11 16:29:33.785 I/GeckoHealth( 2245): fennec :: BackgroundService :: Setting inexact repeating alarm for interval 86400000 02-11 16:29:34.026 W/GeckoGLController( 2245): GLController::serverSurfaceDestroyed() with mCompositorCreated=true 02-11 16:29:34.026 W/GeckoGLController( 2245): done GLController::serverSurfaceDestroyed() 02-11 16:29:34.266 D/GeckoSessInfo( 2245): Recording start of session: 1392136174267 02-11 16:29:35.576 E/SurfaceFlinger( 809): ro.sf.lcd_density must be defined as a build property 02-11 16:29:35.576 W/GeckoGLController( 2245): GLController::serverSurfaceChanged(1024, 687) 02-11 16:29:35.576 W/GeckoGLController( 2245): GLController::resumeCompositor(1024, 687) and mCompositorCreated=true 02-11 16:29:37.517 W/GeckoGLController( 2245): done GLController::resumeCompositor 02-11 16:29:37.546 E/SurfaceFlinger( 809): ro.sf.lcd_density must be defined as a build property 02-11 16:29:39.436 W/ActivityManager( 1218): Launch timeout has expired, giving up wake lock! 02-11 16:29:41.896 W/ActivityManager( 1218): Activity idle timeout for ActivityRecord{b35589b8 u0 org.mozilla.fennec/org.mozilla.gecko.preferences.GeckoPreferences} 02-11 16:29:44.266 W/ActivityManager( 1218): Activity idle timeout for ActivityRecord{b33d5778 u0 org.mozilla.fennec/.App} 02-11 16:29:44.436 W/EGL_emulation( 2245): eglSurfaceAttrib not implemented 02-11 16:29:44.446 W/GeckoGLController( 2245): GLController::updateCompositor with mCompositorCreated=true 02-11 16:29:44.446 W/GeckoGLController( 2245): GLController::resumeCompositor(1024, 687) and mCompositorCreated=true 02-11 16:29:47.986 W/GeckoGLController( 2245): done GLController::resumeCompositor 02-11 16:29:47.986 W/GeckoGLController( 2245): done GLController::updateCompositor with compositor resume 02-11 16:29:47.986 I/Choreographer( 2245): Skipped 626 frames! The application may be doing too much work on its main thread. 02-11 16:29:49.436 I/Choreographer( 1218): Skipped 53 frames! The application may be doing too much work on its main thread. 02-11 16:29:50.046 I/Robocop ( 2245): 2 INFO TEST-PASS | testSettingsMenuItems | Browser toolbar URL stayed the same - about:home should equal about:home 02-11 16:29:50.626 I/Choreographer( 2245): Skipped 69 frames! The application may be doing too much work on its main thread. 02-11 16:29:55.336 I/InputDispatcher( 1218): Window 'Window{b336d1b8 u0 org.mozilla.fennec/org.mozilla.fennec.App}' spent 5294.8ms processing the last input event: KeyEvent(action=0, deviceId=-1, source=0x00000101) 02-11 16:29:55.336 D/InputEventConsistencyVerifier( 2245): KeyEvent: ACTION_UP but key was not down. 02-11 16:29:55.336 D/InputEventConsistencyVerifier( 2245): in android.view.ViewRootImpl@b334d350 02-11 16:29:55.336 D/InputEventConsistencyVerifier( 2245): 0: sent at 459342000000, KeyEvent { action=ACTION_UP, keyCode=KEYCODE_MENU, scanCode=0, metaState=0, flags=0x8, repeatCount=0, eventTime=459342, downTime=459342, deviceId=-1, source=0x101 } 02-11 16:29:55.336 I/Choreographer( 2245): Skipped 281 frames! The application may be doing too much work on its main thread. 02-11 16:29:56.136 E/SurfaceFlinger( 809): ro.sf.lcd_density must be defined as a build property 02-11 16:29:58.507 W/EGL_emulation( 2245): eglSurfaceAttrib not implemented 02-11 16:29:58.516 W/InputDispatcher( 1218): Permission denied: injecting event from pid 2245 uid 10046 02-11 16:29:58.516 W/InputManager( 1218): Input event injection from pid 2245 failed. 02-11 16:29:58.516 W/InputEventReceiver( 2245): Attempted to finish an input event but the input event receiver has already been disposed. 02-11 16:29:58.516 I/InputDispatcher( 1218): Window 'Window{b336d1b8 u0 org.mozilla.fennec/org.mozilla.fennec.App}' spent 3182.2ms processing the last input event: KeyEvent(action=1, deviceId=-1, source=0x00000101) 02-11 16:29:58.516 I/Choreographer( 2245): Skipped 143 frames! The application may be doing too much work on its main thread. 02-11 16:30:00.806 W/InputMethodManagerService( 1218): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@b34ec5d8 attribute=null, token = android.os.BinderProxy@b32ff770 ... 02-11 16:30:18.896 I/Robocop ( 2245): waitForText timeout on Settings
(In reply to TBPL Robot from comment #9) > Tomcat > https://tbpl.mozilla.org/php/getParsedLog.php?id=36725926&tree=Mozilla- > Inbound > Android 2.2 Tegra mozilla-inbound opt test robocop-2 on 2014-03-26 04:17:26 > revision: bc2e311097d4 > slave: tegra-096 03-26 04:36:17.174 I/Robocop ( 4309): 60 INFO TEST-PASS | testSettingsMenuItems | Waiting for settings item choice ^Only over Wi-Fi$ in section ^Home$ - The ^Only over Wi-Fi$ choice is present in section ^Home$ 03-26 04:36:19.254 W/InputManagerService( 1020): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@48771bf8 03-26 04:36:19.324 W/KeyCharacterMap( 4309): No keyboard for id 0 03-26 04:36:19.324 W/KeyCharacterMap( 4309): Using default keymap: /system/usr/keychars/qwerty.kcm.bin 03-26 04:36:19.374 W/GeckoBatteryManager( 4309): Already started! 03-26 04:36:29.804 I/Robocop ( 4309): waitForCondition timeout after 10000 ms. 03-26 04:36:29.814 I/Robocop ( 4309): waitForEnabledText timeout on ^Mozilla$ 03-26 04:36:40.124 D/Robotium( 4309): '^Mozilla$' not found. Have found: 'Settings' 03-26 04:36:40.124 D/Robotium( 4309): '^Mozilla$' not found. Have found: 'Home' 03-26 04:36:40.124 D/Robotium( 4309): '^Mozilla$' not found. Have found: 'Customize your homepage' 03-26 04:36:40.124 D/Robotium( 4309): '^Mozilla$' not found. Have found: 'Search' 03-26 04:36:40.124 D/Robotium( 4309): '^Mozilla$' not found. Have found: 'Customize your search providers' 03-26 04:36:40.124 D/Robotium( 4309): '^Mozilla$' not found. Have found: 'Tabs' 03-26 04:36:40.124 D/Robotium( 4309): '^Mozilla$' not found. Have found: 'Don't restore after quitting Nightly' 03-26 04:36:40.124 D/Robotium( 4309): '^Mozilla$' not found. Have found: 'Import from Android' 03-26 04:36:40.124 D/Robotium( 4309): '^Mozilla$' not found. Have found: 'Download updates automatically' 03-26 04:36:40.124 D/Robotium( 4309): '^Mozilla$' not found. Have found: 'Only over Wi-Fi' 03-26 04:36:40.134 I/Robocop ( 4309): Exception caught during test! 03-26 04:36:40.134 I/Robocop ( 4309): junit.framework.AssertionFailedError: Text string: '^Mozilla$' is not found! 03-26 04:36:40.134 I/Robocop ( 4309): at junit.framework.Assert.fail(Assert.java:47) 03-26 04:36:40.134 I/Robocop ( 4309): at junit.framework.Assert.assertTrue(Assert.java:20) 03-26 04:36:40.134 I/Robocop ( 4309): at com.jayway.android.robotium.solo.Clicker.clickOnText(Clicker.java:383) 03-26 04:36:40.134 I/Robocop ( 4309): at com.jayway.android.robotium.solo.Solo.clickOnText(Solo.java:1028) 03-26 04:36:40.134 I/Robocop ( 4309): at org.mozilla.gecko.tests.testSettingsMenuItems.checkMenuHierarchy(testSettingsMenuItems.java:196) 03-26 04:36:40.134 I/Robocop ( 4309): at org.mozilla.gecko.tests.testSettingsMenuItems.testSettingsMenuItems(testSettingsMenuItems.java:131) There is also a valid screenshot here.
:liuche -- can you have a look?
Flags: needinfo?(liuche)
Will do! I wonder why we didn't catch this with broken tests on landing :/
Assignee: nobody → liuche
Flags: needinfo?(liuche)
This looks like it happens only on older devices - I wonder if the changing menus isn't registering because the devices are slow. Increasing the sleep timeout before navigating back. Try push: https://tbpl.mozilla.org/?tree=Try&rev=242b2164eb74
Looks like all the try runs are green (or unrelated oranges).
Attachment #8399854 - Flags: review?(gbrown)
Comment on attachment 8399854 [details] [diff] [review] Patch: Increase sleep for navigation Review of attachment 8399854 [details] [diff] [review]: ----------------------------------------------------------------- Consider using an even larger period - 150 ms? In UI terms, that's still not a lot of time, and our test devices exhibit a wide range of performance characteristics.
Attachment #8399854 - Flags: review?(gbrown) → review+
(In reply to Geoff Brown [:gbrown] from comment #35) > Comment on attachment 8399854 [details] [diff] [review] > Patch: Increase sleep for navigation > > Review of attachment 8399854 [details] [diff] [review]: > ----------------------------------------------------------------- > > Consider using an even larger period - 150 ms? In UI terms, that's still not > a lot of time, and our test devices exhibit a wide range of performance > characteristics. Done. https://hg.mozilla.org/integration/fx-team/rev/bbaf247e9637
Target Milestone: --- → Firefox 31
https://hg.mozilla.org/mozilla-central/rev/bbaf247e9637
Status: NEW → RESOLVED
Closed: 12 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
The following changeset is now in Firefox Nightly: > bbaf247e9637 Bug 971093 - Intermittent testSettingsMenuItems | Exception caught - junit.framework.AssertionFailedError: Text string: '^Customize$' is not found! r=gbrown Nightly Build Information: ID: 20140402030201 Changeset: 4941a2ac0786109b08856738019b016a6c5a66a6 Version: 31.0a1 TBPL: https://tbpl.mozilla.org/?rev=4941a2ac0786 URL: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central Download Links: > Linux x86: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.linux-i686.tar.bz2 > Linux x86_64: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.linux-x86_64.tar.bz2 > Linux x86_64 ASAN: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.linux-x86_64-asan.tar.bz2 > Mac: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.mac.dmg > Win32: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.win32.installer.exe > Win64: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-02-03-02-01-mozilla-central/firefox-31.0a1.en-US.win64-x86_64.installer.exe Previous Nightly Build Information: ID: 20140401030203 Changeset: 1417d180a1d8665b1a91b897d1cc4cc31e7980d4 Version: 31.0a1 TBPL: https://tbpl.mozilla.org/?rev=1417d180a1d8 URL: https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2014/04/2014-04-01-03-02-03-mozilla-central
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: