Closed Bug 971093 Opened 10 years ago Closed 10 years ago

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

Categories

(Firefox for Android Graveyard :: Testing, defect)

x86
Android
defect
Not set
normal

Tracking

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

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

People

(Reporter: RyanVM, Assigned: liuche)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

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: 10 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

Created:
Updated:
Size: