Closed Bug 975155 Opened 11 years ago Closed 9 years ago

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

Categories

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

x86_64
Android
defect

Tracking

(fennec+)

RESOLVED WONTFIX
Tracking Status
fennec + ---

People

(Reporter: gbrown, Assigned: snorp)

References

Details

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
Blocks: 967704
:snorp -- any ideas?
Flags: needinfo?(snorp)
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.
Blocks: 975187
No longer blocks: 975187
Assignee: nobody → snorp
Flags: needinfo?(snorp)
Whiteboard: [leave open] [test disabled on Android 2.3]
Blocks: 979921
No longer blocks: 967704
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=...)
tracking-fennec: --- → ?
tracking-fennec: ? → 31+
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.
Depends on: 1015395
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)
Looking at libsurfaceflinger_client.so from the 2.3 image, the Android bug is fixed so that can't be it.
tracking-fennec: 31+ → +
filter on [mass-p5]
Priority: -- → P5
Android 2.3 is no longer supported in Firefox 48+. Test manifests were updated in bug 1251013.
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → WONTFIX
Whiteboard: [leave open] [test disabled on Android 2.3]
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.