975155 - Frequent Android 2.3 testFindInPage | Automation Error: Missing end of test marker (process crashed?)

Status: RESOLVED WONTFIX

(Firefox for Android Graveyard :: Testing, defect, P5)

Description

[Geoff Brown [:gbrown]]

Robocop's testFindInPage usually fails on the Android 2.3 emulator. The test ends suddenly, leaving no crash dump.

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

16:00:20     INFO -  1 INFO TEST-START | testFindInPage
16:00:20     INFO -  2 INFO TEST-PASS | testFindInPage | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready
16:00:20     INFO -  EventExpecter: no longer listening for Gecko:Ready
16:00:20     INFO -  3 INFO TEST-PASS | testFindInPage | waiting for urlbar text to gain focus - urlbar text gained focus
16:00:20     INFO -  4 INFO TEST-PASS | testFindInPage | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_text_page.html should equal http://mochi.test:8888/tests/robocop/robocop_text_page.html
16:00:20     INFO -  5 INFO TEST-PASS | testFindInPage | Given message occurred for registered event: {"errorType":"","bgColor":"transparent","type":"DOMContentLoaded","tabID":0} - DOMContentLoaded should equal DOMContentLoaded
16:00:20     INFO -  EventExpecter: no longer listening for DOMContentLoaded
16:00:20     INFO -  PaintExpecter: no longer listening for events
16:00:20     INFO -  waitForText timeout on ^Find in Page$
16:00:20     INFO -  6 INFO TEST-PASS | testFindInPage | Looking for the next search match button in the Find in Page UI - Found the next match button
16:00:20     INFO -  INFO | automation.py | Application ran for: 0:02:59.888737
16:00:20     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpLlyMgjpidlog
16:00:20     INFO -  /data/anr/traces.txt not found
16:00:20     INFO -  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
16:00:20     INFO -  runtests.py | Running tests: end.
16:00:20     INFO -  Mochi-Remote ERROR | Automation Error: Missing end of test marker (process crashed?)

Logcat provides some explanation:

16:00:20     INFO -  02-11 15:48:08.422 I/Robocop ( 2517): 6 INFO TEST-PASS | testFindInPage | Looking for the next search match button in the Find in Page UI - Found the next match button

...all is well so far. "Find in Page" has just been selected, and Robocop can see views in the Find in Page dialog.

16:00:20     INFO -  02-11 15:48:08.883 W/GeckoGLController( 2517): GLController::serverSurfaceChanged(1024, 695)
16:00:20     INFO -  02-11 15:48:08.883 D/GeckoLayerClient( 2517): Window-size changed to (1024,695)
16:00:20     INFO -  02-11 15:48:08.883 W/GeckoGLController( 2517): GLController::resumeCompositor(1024, 695) and mCompositorCreated=true
16:00:20     INFO -  02-11 15:48:09.581 W/GeckoGLController( 2517): done GLController::resumeCompositor
16:00:20     INFO -  02-11 15:48:09.583 W/GeckoGLController( 2517): GLController::serverSurfaceChanged(1024, 695)

We see the window size has been adjusted for "Find in Page", and now things go downhilll...

16:00:20     INFO -  02-11 15:48:09.634 D/Robocop ( 2517): Received drawFinished notification
16:00:20     INFO -  02-11 15:48:10.052 I/InputQueue-JNI( 2517): Sending finished signal for input channel '406219f0 AtchDlg:org.mozilla.fennec/org.mozilla.fennec.App (client)' since it is being unregistered while an input message is still in progress.
16:00:20     INFO -  02-11 15:48:10.182 W/GeckoGLController( 2517): GLController::updateCompositor with mCompositorCreated=true
16:00:20     INFO -  02-11 15:48:10.182 W/GeckoGLController( 2517): GLController::resumeCompositor(1024, 695) and mCompositorCreated=true
16:00:20     INFO -  02-11 15:48:10.610 D/Robocop ( 2517): Received drawFinished notification
16:00:20     INFO -  02-11 15:48:12.012 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:15.227 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:16.222 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:19.232 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:21.233 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:22.232 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:23.246 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:27.242 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:29.283 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:30.292 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:31.297 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:35.297 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:39.298 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:40.113 W/WindowManager(   65): Input event injection timed out.
16:00:20     INFO -  02-11 15:48:43.296 W/SharedBufferStack( 2517): waitForCondition(LockCondition) timed out (identity=114, status=0). CPU may be pegged. trying again.
16:00:20     INFO -  02-11 15:48:45.122 I/InputDispatcher(   65): Application is not responding: AppWindowToken{40821170 token=HistoryRecord{406224b0 org.mozilla.fennec/.App}} - Window{4072f098 org.mozilla.fennec/org.mozilla.fennec.App paused=false}.  36183.4ms since event, 5000.6ms since wait started
16:00:20     INFO -  02-11 15:48:45.122 I/WindowManager(   65): Input event dispatching timed out sending to org.mozilla.fennec/org.mozilla.fennec.App
16:00:20     INFO -  02-11 15:48:45.132 D/AndroidRuntime( 2508): Shutting down VM
16:00:20     INFO -  02-11 15:48:45.161 I/ActivityManager(   65): Force stopping package org.mozilla.fennec uid=10017
16:00:20     INFO -  02-11 15:48:45.162 I/Process (   65): Sending signal. PID: 2563 SIG: 9
16:00:20     INFO -  02-11 15:48:45.225 I/Process (   65): Sending signal. PID: 2517 SIG: 9
16:00:20     INFO -  02-11 15:48:45.242 I/AndroidRuntime( 2508): NOTE: attach of thread 'Binder Thread #3' failed
16:00:20     INFO -  02-11 15:48:45.384 D/jdwp    ( 2508): adbd disconnected
16:00:20     INFO -  02-11 15:48:45.513 W/WindowManager(   65): Input event injection timed out.
16:00:20     INFO -  02-11 15:48:46.194 W/WindowManager(   65): Rebuild removed 4 windows but added 2
16:00:20     INFO -  02-11 15:48:46.478 E/InputDispatcher(   65): channel '4072f098 org.mozilla.fennec/org.mozilla.fennec.App (server)' ~ Consumer closed input channel or an error occurred.  events=0x8
16:00:20     INFO -  02-11 15:48:46.478 E/InputDispatcher(   65): channel '4072f098 org.mozilla.fennec/org.mozilla.fennec.App (server)' ~ Channel is unrecoverably broken and will be disposed!
16:00:20     INFO -  02-11 15:48:46.595 I/WindowManager(   65): WIN DEATH: Window{4072f098 org.mozilla.fennec/org.mozilla.fennec.App paused=false}
16:00:20     INFO -  02-11 15:48:46.636 I/WindowManager(   65): WIN DEATH: Window{4073bc20 SurfaceView paused=false}

I have reproduced "CPU may be pegged" locally on an emulator with the same AVD/images, even with a much-simplified test -- it seems to happen as soon as Robocop brings up the Find in Page dialog.

These seem relevant, but I don't see a known solution:

http://stackoverflow.com/questions/10199231/android-freeze-in-opengles-cpu-may-be-pegged-trying-again
http://stackoverflow.com/questions/8458404/android-cpu-may-be-pegged-bug

Comment 1

[Geoff Brown [:gbrown]]

:snorp -- any ideas?

Comment 2

[Geoff Brown [:gbrown]]

I reproduced this problem locally on an emulator with the same AVD, without Robocop or any test infra -- just opened Fennec, opened a page, selected MENU > More > Find in Page -- Fennec became unresponsive within 5 seconds. 

I cannot reproduce on any of my devices.

Comment 3

[Geoff Brown [:gbrown]]

Disabled on Android 2.3 only: https://hg.mozilla.org/integration/mozilla-inbound/rev/011b9055dfec

Comment 4

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/011b9055dfec

Comment 5

[James Willcox (:snorp) ([e-mail]) (he/him)]

Looks like we frequently get stuck in eglSwapBuffers(), presumably when the surface gets resized/recreated.

#0  0xafd0c738 in __futex_syscall3 () from /Users/snorp/source/jimdb-arm/lib/emulator-5554/system/lib/libc.so
#1  0xafd11374 in __pthread_cond_timedwait_relative () from /Users/snorp/source/jimdb-arm/lib/emulator-5554/system/lib/libc.so
#2  0xac7116b6 in android::SharedBufferBase::waitForCondition(android::SharedBufferBase::ConditionBase const&) ()
   from /Users/snorp/source/jimdb-arm/lib/emulator-5554/system/lib/libsurfaceflinger_client.so
#3  0xac71172e in android::SharedBufferClient::lock(int) () from /Users/snorp/source/jimdb-arm/lib/emulator-5554/system/lib/libsurfaceflinger_client.so
#4  0xac7126e8 in android::Surface::lockBuffer(android_native_buffer_t*) () from /Users/snorp/source/jimdb-arm/lib/emulator-5554/system/lib/libsurfaceflinger_client.so
#5  0xac71272e in android::Surface::lockBuffer(ANativeWindow*, android_native_buffer_t*) () from /Users/snorp/source/jimdb-arm/lib/emulator-5554/system/lib/libsurfaceflinger_client.so
#6  0x80406dd2 in egl_window_surface_t::swapBuffers() () from /Users/snorp/source/jimdb-arm/lib/emulator-5554/system/lib/libEGL_emulation.so
#7  0x804071fa in eglSwapBuffers () from /Users/snorp/source/jimdb-arm/lib/emulator-5554/system/lib/libEGL_emulation.so
#8  0xabe037b8 in eglSwapBuffers () from /Users/snorp/source/jimdb-arm/lib/emulator-5554/system/lib/libEGL.so
#9  0x4dd3e550 in fSwapBuffers (surface=<optimized out>, dpy=<optimized out>, this=0x4f416d48 <mozilla::gl::sEGLLibrary>) at /Users/snorp/source/gecko-dev/gfx/gl/GLLibraryEGL.h:283
#10 mozilla::gl::GLContextEGL::SwapBuffers (this=<optimized out>) at /Users/snorp/source/gecko-dev/gfx/gl/GLContextProviderEGL.cpp:467
#11 0x4ddacd8a in mozilla::layers::CompositorOGL::EndFrame (this=0x555f4f80) at /Users/snorp/source/gecko-dev/gfx/layers/opengl/CompositorOGL.cpp:1189
#12 0x4dda2c40 in mozilla::layers::LayerManagerComposite::Render (this=0x555e7a60) at /Users/snorp/source/gecko-dev/gfx/layers/composite/LayerManagerComposite.cpp:519
#13 0x4dda2db6 in EndTransaction (aFlags=<optimized out>, this=0x555e7a60, aCallback=<optimized out>, aCallbackData=<optimized out>)
    at /Users/snorp/source/gecko-dev/gfx/layers/composite/LayerManagerComposite.cpp:244
#14 mozilla::layers::LayerManagerComposite::EndTransaction (this=0x555e7a60, aCallback=<optimized out>, aCallbackData=<optimized out>, aFlags=<optimized out>)
    at /Users/snorp/source/gecko-dev/gfx/layers/composite/LayerManagerComposite.cpp:200
#15 0x4dd9ad2e in mozilla::layers::LayerManagerComposite::EndEmptyTransaction (this=<optimized out>, aFlags=<optimized out>)
    at /Users/snorp/source/gecko-dev/gfx/layers/composite/LayerManagerComposite.cpp:195
#16 0x4dda35ac in mozilla::layers::CompositorParent::CompositeToTarget (this=0x555caa00, aTarget=0x0) at /Users/snorp/source/gecko-dev/gfx/layers/ipc/CompositorParent.cpp:666
#17 0x4dda4ade in DispatchToMethod<mozilla::layers::CompositorParent, void (mozilla::layers::CompositorParent::*)()> (method=
    (void (mozilla::layers::CompositorParent::*)(mozilla::layers::CompositorParent * const)) 0x4dda36bb <mozilla::layers::CompositorParent::Composite()>, obj=<optimized out>, arg=...)

Comment 6

[Geoff Brown [:gbrown]]

There are other problems with testFindInPage on other Android platforms, so we're disabling it everywhere. Bug 1015395 may make significant changes to the test.

Comment 7

[(inactive) Jim Chen [:jchen] [:darchons]]

Might be related to bug 971355 comment 24, which is an Android bug that should have been fixed around 2.3.3. (The test image is 2.3.7 AFAICT)

Comment 8

[(inactive) Jim Chen [:jchen] [:darchons]]

Looking at libsurfaceflinger_client.so from the 2.3 image, the Android bug is fixed so that can't be it.

Comment 9

[Brad Lassey [:blassey] (use needinfo?)]

filter on [mass-p5]

Comment 10

[Geoff Brown [:gbrown]]

Android 2.3 is no longer supported in Firefox 48+.

Test manifests were updated in bug 1251013.