Skip to content
This repository has been archived by the owner on Jan 14, 2018. It is now read-only.

Reliable ANR related to SpiceServiceListener when SpiceManager is Starting #270

Closed
colintheshots opened this issue Feb 28, 2014 · 19 comments

Comments

@colintheshots
Copy link

I have noticed that I can reliably produce an Application Not Responding error which seems to be an infinite deadlock using Robospice 1.4.11 with robospice-retrofit if I attempt to install and run the app via ADB while the screen is off on the physical device. The device used is a Nexus 7 (2012) running the most recent version of KitKat 4.4.2. It looks like the SpiceManager is attempting to start and stop at the same time, resulting in a deadlock. I'm attaching the ANR traces.txt.

Although the method used to reproduce this bug is hardly a normal use case, I fear that this ANR may appear in other usage patterns which are more typical. For example, I would expect this problem to trigger when the app gets updated while the device screen is off.

----- pid 22497 at 2014-02-28 10:12:30 -----
Cmd line: com.ourcompany.ourproduct

JNI: CheckJNI is off; workarounds are off; pins=1; globals=269

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

"main" prio=5 tid=1 MONITOR
  | group="main" sCount=1 dsCount=0 obj=0x41881ca8 self=0x414c5468
  | sysTid=22497 nice=0 sched=0/0 cgrp=apps handle=1074319700
  | state=S schedstat=( 323099000 97607000 705 ) utm=21 stm=11 core=0
  at com.octo.android.robospice.SpiceManager.isStarted(SpiceManager.java:~221)
  - waiting to lock <0x41ffdae0> (a com.ourcompany.ourproduct.network.ourcompanySpiceManager) held by tid=28 (Thread-649)
  at com.ourcompany.ourproduct.ui.BaseActivity.onStop(BaseActivity.java:59)
  at com.ourcompany.ourproduct.ui.MainActivity.onStop(MainActivity.java:264)
  at android.app.Instrumentation.callActivityOnStop(Instrumentation.java:1212)
  at android.app.Activity.performStop(Activity.java:5376)
  at android.app.ActivityThread.handleSleeping(ActivityThread.java:3302)
  at android.app.ActivityThread.access$2900(ActivityThread.java:135)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1375)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:136)
  at android.app.ActivityThread.main(ActivityThread.java:5017)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:515)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:779)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:595)
  at dalvik.system.NativeStart.main(Native Method)

"DataRequestDispatcher" prio=5 tid=14 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x42015298 self=0x64ff7660
  | sysTid=22563 nice=0 sched=0/0 cgrp=apps handle=1697400424
  | state=S schedstat=( 7190000 3582000 6 ) utm=0 stm=0 core=1
  #00  pc 00020790  /system/lib/libc.so (select+20)
  #01  pc 0000893d  /system/lib/libjavacrypto.so
  #02  pc 00009955  /system/lib/libjavacrypto.so
  #03  pc 0001dbcc  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #04  pc 0004e123  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
  #05  pc 00026fe0  /system/lib/libdvm.so
  #06  pc 0002dfa0  /system/lib/libdvm.so (dvmMterpStd(Thread*)+76)
  #07  pc 0002b638  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #08  pc 00060581  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+336)
  #09  pc 000605a5  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
  #10  pc 0005528b  /system/lib/libdvm.so
  #11  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #12  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
  at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:689)
  at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:103)
  at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:191)
  at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:82)
  at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:174)
  at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:180)
  at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:235)
  at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:259)
  at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:279)
  at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:121)
  at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:428)
  at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:555)
  at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:487)
  at android.net.http.AndroidHttpClient.execute(AndroidHttpClient.java:257)
  at maps.a.a.a((null):-1)
  at maps.a.a.execute((null):-1)
  at maps.a.a.execute((null):-1)
  at maps.bu.b.g((null):-1)
  at maps.bu.b.b((null):-1)
  at maps.bn.h.run((null):-1)
  at java.lang.Thread.run(Thread.java:841)

"Thread-651" prio=1 tid=29 MONITOR
  | group="main" sCount=1 dsCount=0 obj=0x420d98e0 self=0x652c4008
  | sysTid=22536 nice=19 sched=0/0 cgrp=apps/bg_non_interactive handle=1697403632
  | state=S schedstat=( 17989000 82312000 203 ) utm=0 stm=1 core=0
  at com.octo.android.robospice.SpiceManager$SpiceManagerCommand.call(SpiceManager.java:~1320)
  - waiting to lock <0x41ffdae0> (a com.ourcompany.ourproduct.network.ourcompanySpiceManager) held by tid=28 (Thread-649)
  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
  at java.lang.Thread.run(Thread.java:841)

"Thread-649" prio=1 tid=28 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x420f6b50 self=0x6861eb10
  | sysTid=22534 nice=19 sched=0/0 cgrp=apps/bg_non_interactive handle=1697394224
  | state=S schedstat=( 1372000 1286000 2 ) utm=0 stm=0 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x420bfb60> (a java.lang.VMThread) held by tid=28 (Thread-649)
  at java.lang.Thread.parkFor(Thread.java:1205)
  at sun.misc.Unsafe.park(Unsafe.java:325)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2017)
  at com.octo.android.robospice.SpiceManager.waitForServiceToBeBound(SpiceManager.java:1241)
  at com.octo.android.robospice.SpiceManager$SpiceManagerCommand.call(SpiceManager.java:1325)
  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
  at java.lang.Thread.run(Thread.java:841)

"SpiceManagerThread 0" prio=1 tid=27 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x41ffc0e0 self=0x64f8a628
  | sysTid=22533 nice=19 sched=0/0 cgrp=apps/bg_non_interactive handle=1694810120
  | state=S schedstat=( 3175000 3019000 10 ) utm=0 stm=0 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x41ffc1e0> (a java.lang.VMThread) held by tid=27 (SpiceManagerThread 0)
  at java.lang.Thread.parkFor(Thread.java:1205)
  at sun.misc.Unsafe.park(Unsafe.java:325)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2017)
  at com.octo.android.robospice.SpiceManager.waitForServiceToBeBound(SpiceManager.java:1241)
  at com.octo.android.robospice.SpiceManager.run(SpiceManager.java:252)
  at java.lang.Thread.run(Thread.java:841)

"Thread-646" prio=5 tid=26 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x420176b0 self=0x652873b8
  | sysTid=22530 nice=0 sched=0/0 cgrp=apps handle=1697150992
  | state=S schedstat=( 908000 11463000 11 ) utm=0 stm=0 core=0
  #00  pc 000217f4  /system/lib/libc.so (epoll_wait+12)
  #01  pc 0001063f  /system/lib/libutils.so (android::Looper::pollInner(int)+98)
  #02  pc 00010869  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
  #03  pc 0006a121  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04  pc 0001dbcc  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05  pc 0004e123  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
  #06  pc 00026fe0  /system/lib/libdvm.so
  #07  pc 0002dfa0  /system/lib/libdvm.so (dvmMterpStd(Thread*)+76)
  #08  pc 0002b638  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #09  pc 00060581  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+336)
  #10  pc 000605a5  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
  #11  pc 0005528b  /system/lib/libdvm.so
  #12  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #13  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:138)
  at android.os.Looper.loop(Looper.java:123)
  at maps.j.e.run((null):-1)

"[email protected]@420ce4d0" daemon prio=5 tid=25 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x4204ad20 self=0x6527f948
  | sysTid=22529 nice=0 sched=0/0 cgrp=apps handle=1697119648
  | state=S schedstat=( 222000 1126000 3 ) utm=0 stm=0 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x4200b028> (a java.lang.ref.ReferenceQueue)
  at java.lang.Object.wait(Object.java:401)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:102)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:73)
  at org.apache.http.impl.conn.tsccm.RefQueueWorker.run(RefQueueWorker.java:102)
  at java.lang.Thread.run(Thread.java:841)

"GLThread 644" prio=5 tid=22 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x420c5178 self=0x6527c008
  | sysTid=22528 nice=0 sched=0/0 cgrp=apps handle=1697115216
  | state=S schedstat=( 408000 833000 10 ) utm=0 stm=0 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x420a1288> (a maps.aj.z)
  at java.lang.Object.wait(Object.java:364)
  at maps.aj.y.l((null):-1)
  at maps.aj.y.run((null):-1)

"Thread-642" prio=1 tid=23 TIMED_WAIT
  | group="main" sCount=1 dsCount=0 obj=0x420581b0 self=0x6527c988
  | sysTid=22526 nice=19 sched=0/0 cgrp=apps/bg_non_interactive handle=1697107424
  | state=S schedstat=( 10180000 48718000 149 ) utm=1 stm=0 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x4205ff68> (a java.lang.Object)
  at java.lang.Object.wait(Object.java:401)
  at maps.by.c.c((null):-1)
  at maps.by.c.run((null):-1)
  at maps.bx.b.run((null):-1)

"ibs" prio=5 tid=21 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x42005eb0 self=0x6504ecf0
  | sysTid=22524 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1694822728
  | state=S schedstat=( 1846000 4017000 20 ) utm=0 stm=0 core=0
  #00  pc 000217f4  /system/lib/libc.so (epoll_wait+12)
  #01  pc 0001063f  /system/lib/libutils.so (android::Looper::pollInner(int)+98)
  #02  pc 00010869  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
  #03  pc 0006a121  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04  pc 0001dbcc  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05  pc 0004e123  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
  #06  pc 00026fe0  /system/lib/libdvm.so
  #07  pc 0002dfa0  /system/lib/libdvm.so (dvmMterpStd(Thread*)+76)
  #08  pc 0002b638  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #09  pc 00060581  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+336)
  #10  pc 000605a5  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
  #11  pc 0005528b  /system/lib/libdvm.so
  #12  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #13  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:138)
  at android.os.Looper.loop(Looper.java:123)
  at maps.ae.n.e((null):-1)
  at maps.ax.b.run((null):-1)

"vts_inaka_com.ourcompany.ourproduct" prio=5 tid=20 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x420006f8 self=0x6504e008
  | sysTid=22523 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1694819424
  | state=S schedstat=( 1353000 853000 6 ) utm=0 stm=0 core=1
  #00  pc 000217f4  /system/lib/libc.so (epoll_wait+12)
  #01  pc 0001063f  /system/lib/libutils.so (android::Looper::pollInner(int)+98)
  #02  pc 00010869  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
  #03  pc 0006a121  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04  pc 0001dbcc  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05  pc 0004e123  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
  #06  pc 00026fe0  /system/lib/libdvm.so
  #07  pc 0002dfa0  /system/lib/libdvm.so (dvmMterpStd(Thread*)+76)
  #08  pc 0002b638  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #09  pc 00060581  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+336)
  #10  pc 000605a5  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
  #11  pc 0005528b  /system/lib/libdvm.so
  #12  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #13  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:138)
  at android.os.Looper.loop(Looper.java:123)
  at maps.ae.d.e((null):-1)
  at maps.ae.ae.e((null):-1)
  at maps.ax.b.run((null):-1)

"vts_labl_com.ourcompany.ourproduct" prio=5 tid=19 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x42054a38 self=0x650098b8
  | sysTid=22522 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1694539024
  | state=S schedstat=( 1330000 1124000 8 ) utm=0 stm=0 core=1
  #00  pc 000217f4  /system/lib/libc.so (epoll_wait+12)
  #01  pc 0001063f  /system/lib/libutils.so (android::Looper::pollInner(int)+98)
  #02  pc 00010869  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
  #03  pc 0006a121  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04  pc 0001dbcc  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05  pc 0004e123  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
  #06  pc 00026fe0  /system/lib/libdvm.so
  #07  pc 0002dfa0  /system/lib/libdvm.so (dvmMterpStd(Thread*)+76)
  #08  pc 0002b638  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #09  pc 00060581  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+336)
  #10  pc 000605a5  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
  #11  pc 0005528b  /system/lib/libdvm.so
  #12  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #13  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:138)
  at android.os.Looper.loop(Looper.java:123)
  at maps.ae.d.e((null):-1)
  at maps.ae.ae.e((null):-1)
  at maps.ax.b.run((null):-1)

"its_ter" prio=5 tid=18 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x42002478 self=0x6504d8a8
  | sysTid=22521 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1694817536
  | state=S schedstat=( 1389000 3767000 25 ) utm=0 stm=0 core=0
  #00  pc 000217f4  /system/lib/libc.so (epoll_wait+12)
  #01  pc 0001063f  /system/lib/libutils.so (android::Looper::pollInner(int)+98)
  #02  pc 00010869  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
  #03  pc 0006a121  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04  pc 0001dbcc  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05  pc 0004e123  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
  #06  pc 00026fe0  /system/lib/libdvm.so
  #07  pc 0002dfa0  /system/lib/libdvm.so (dvmMterpStd(Thread*)+76)
  #08  pc 0002b638  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #09  pc 00060581  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+336)
  #10  pc 000605a5  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
  #11  pc 0005528b  /system/lib/libdvm.so
  #12  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #13  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:138)
  at android.os.Looper.loop(Looper.java:123)
  at maps.ae.d.e((null):-1)
  at maps.ax.b.run((null):-1)

"vts_traf_com.ourcompany.ourproduct" prio=5 tid=17 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x4200f718 self=0x6504d038
  | sysTid=22520 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1694657624
  | state=S schedstat=( 296000 329000 2 ) utm=0 stm=0 core=1
  #00  pc 000217f4  /system/lib/libc.so (epoll_wait+12)
  #01  pc 0001063f  /system/lib/libutils.so (android::Looper::pollInner(int)+98)
  #02  pc 00010869  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
  #03  pc 0006a121  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04  pc 0001dbcc  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05  pc 0004e123  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
  #06  pc 00026fe0  /system/lib/libdvm.so
  #07  pc 0002dfa0  /system/lib/libdvm.so (dvmMterpStd(Thread*)+76)
  #08  pc 0002b638  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #09  pc 00060581  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+336)
  #10  pc 000605a5  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
  #11  pc 0005528b  /system/lib/libdvm.so
  #12  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #13  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:138)
  at android.os.Looper.loop(Looper.java:123)
  at maps.ae.d.e((null):-1)
  at maps.ae.ae.e((null):-1)
  at maps.ax.b.run((null):-1)

"its" prio=5 tid=16 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x42037360 self=0x650263b0
  | sysTid=22519 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1694656520
  | state=S schedstat=( 1425000 3125000 10 ) utm=0 stm=0 core=1
  #00  pc 000217f4  /system/lib/libc.so (epoll_wait+12)
  #01  pc 0001063f  /system/lib/libutils.so (android::Looper::pollInner(int)+98)
  #02  pc 00010869  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
  #03  pc 0006a121  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04  pc 0001dbcc  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05  pc 0004e123  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
  #06  pc 00026fe0  /system/lib/libdvm.so
  #07  pc 0002dfa0  /system/lib/libdvm.so (dvmMterpStd(Thread*)+76)
  #08  pc 0002b638  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #09  pc 00060581  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+336)
  #10  pc 000605a5  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
  #11  pc 0005528b  /system/lib/libdvm.so
  #12  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #13  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:138)
  at android.os.Looper.loop(Looper.java:123)
  at maps.ae.d.e((null):-1)
  at maps.ax.b.run((null):-1)

"vts_com.ourcompany.ourproduct" prio=5 tid=15 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x42069618 self=0x40071008
  | sysTid=22518 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1074162712
  | state=S schedstat=( 2662000 4925000 13 ) utm=0 stm=0 core=1
  #00  pc 000217f4  /system/lib/libc.so (epoll_wait+12)
  #01  pc 0001063f  /system/lib/libutils.so (android::Looper::pollInner(int)+98)
  #02  pc 00010869  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
  #03  pc 0006a121  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04  pc 0001dbcc  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05  pc 0004e123  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
  #06  pc 00026fe0  /system/lib/libdvm.so
  #07  pc 0002dfa0  /system/lib/libdvm.so (dvmMterpStd(Thread*)+76)
  #08  pc 0002b638  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #09  pc 00060581  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+336)
  #10  pc 000605a5  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
  #11  pc 0005528b  /system/lib/libdvm.so
  #12  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #13  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:138)
  at android.os.Looper.loop(Looper.java:123)
  at maps.ae.d.e((null):-1)
  at maps.ae.ae.e((null):-1)
  at maps.ax.b.run((null):-1)

"pool-3-thread-1" prio=5 tid=11 TIMED_WAIT
  | group="main" sCount=1 dsCount=0 obj=0x4208d450 self=0x64feaa28
  | sysTid=22517 nice=0 sched=0/0 cgrp=apps handle=1694443600
  | state=S schedstat=( 239000 9347000 3 ) utm=0 stm=0 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x4208d598> (a java.lang.VMThread) held by tid=11 (pool-3-thread-1)
  at java.lang.Thread.parkFor(Thread.java:1205)
  at sun.misc.Unsafe.park(Unsafe.java:325)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:197)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2056)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1062)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:778)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1035)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1097)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
  at java.lang.Thread.run(Thread.java:841)

"Crashlytics Trace Manager" prio=5 tid=13 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x420300b0 self=0x400665c8
  | sysTid=22515 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1694444656
  | state=S schedstat=( 827000 865000 3 ) utm=0 stm=0 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x4200a280> (a java.lang.VMThread) held by tid=13 (Crashlytics Trace Manager)
  at java.lang.Thread.parkFor(Thread.java:1205)
  at sun.misc.Unsafe.park(Unsafe.java:325)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2017)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1050)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:778)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1035)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1097)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
  at com.crashlytics.android.internal.ak.a(SourceFile:44)
  at com.crashlytics.android.internal.Y.run(SourceFile:13)
  at java.lang.Thread.run(Thread.java:841)

"Crashlytics Exception Handler" prio=5 tid=12 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x42021e20 self=0x64e8f748
  | sysTid=22512 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1692990368
  | state=S schedstat=( 14581000 19280000 27 ) utm=0 stm=1 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x42022250> (a java.lang.VMThread) held by tid=12 (Crashlytics Exception Handler)
  at java.lang.Thread.parkFor(Thread.java:1205)
  at sun.misc.Unsafe.park(Unsafe.java:325)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2017)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:410)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1035)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1097)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
  at com.crashlytics.android.internal.ak.a(SourceFile:44)
  at com.crashlytics.android.internal.Y.run(SourceFile:13)
  at java.lang.Thread.run(Thread.java:841)

"Binder_2" prio=5 tid=10 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x41ff33e0 self=0x40013008
  | sysTid=22509 nice=0 sched=0/0 cgrp=apps handle=1073741832
  | state=S schedstat=( 593000 8063000 7 ) utm=0 stm=0 core=1
  #00  pc 00020640  /system/lib/libc.so (__ioctl+8)
  #01  pc 0002cedf  /system/lib/libc.so (ioctl+14)
  #02  pc 0001d375  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
  #03  pc 0001da7f  /system/lib/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+6)
  #04  pc 0001db15  /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+48)
  #05  pc 00021921  /system/lib/libbinder.so
  #06  pc 0000ea5d  /system/lib/libutils.so (android::Thread::_threadLoop(void*)+216)
  #07  pc 0004cd81  /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
  #08  pc 0000e58f  /system/lib/libutils.so
  #09  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #10  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at dalvik.system.NativeStart.run(Native Method)

"Binder_1" prio=5 tid=9 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x41fefa00 self=0x40035498
  | sysTid=22508 nice=0 sched=0/0 cgrp=apps handle=1073959504
  | state=S schedstat=( 2875000 2554000 15 ) utm=0 stm=0 core=0
  #00  pc 00020640  /system/lib/libc.so (__ioctl+8)
  #01  pc 0002cedf  /system/lib/libc.so (ioctl+14)
  #02  pc 0001d375  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
  #03  pc 0001da7f  /system/lib/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+6)
  #04  pc 0001db15  /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+48)
  #05  pc 00021921  /system/lib/libbinder.so
  #06  pc 0000ea5d  /system/lib/libutils.so (android::Thread::_threadLoop(void*)+216)
  #07  pc 0004cd81  /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
  #08  pc 0000e58f  /system/lib/libutils.so
  #09  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #10  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at dalvik.system.NativeStart.run(Native Method)

"FinalizerWatchdogDaemon" daemon prio=5 tid=8 TIMED_WAIT
  | group="system" sCount=1 dsCount=0 obj=0x41fec750 self=0x4160fa40
  | sysTid=22507 nice=0 sched=0/0 cgrp=apps handle=1096875672
  | state=S schedstat=( 270000 2605000 5 ) utm=0 stm=0 core=0
  at java.lang.VMThread.sleep(Native Method)
  at java.lang.Thread.sleep(Thread.java:1013)
  at java.lang.Thread.sleep(Thread.java:995)
  at java.lang.Daemons$FinalizerWatchdogDaemon.sleepFor(Daemons.java:248)
  at java.lang.Daemons$FinalizerWatchdogDaemon.waitForFinalization(Daemons.java:258)
  at java.lang.Daemons$FinalizerWatchdogDaemon.run(Daemons.java:212)
  at java.lang.Thread.run(Thread.java:841)

"FinalizerDaemon" daemon prio=5 tid=7 WAIT
  | group="system" sCount=1 dsCount=0 obj=0x41fec5a0 self=0x4160f318
  | sysTid=22506 nice=0 sched=0/0 cgrp=apps handle=1096873840
  | state=S schedstat=( 16410000 7324000 39 ) utm=1 stm=0 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x41876718> (a java.lang.ref.ReferenceQueue)
  at java.lang.Object.wait(Object.java:401)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:102)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:73)
  at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:170)
  at java.lang.Thread.run(Thread.java:841)

"ReferenceQueueDaemon" daemon prio=5 tid=6 WAIT
  | group="system" sCount=1 dsCount=0 obj=0x41fec438 self=0x64f7a460
  | sysTid=22505 nice=0 sched=0/0 cgrp=apps handle=1693952184
  | state=S schedstat=( 2305000 913000 30 ) utm=0 stm=0 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x41876640> 
  at java.lang.Object.wait(Object.java:364)
  at java.lang.Daemons$ReferenceQueueDaemon.run(Daemons.java:130)
  at java.lang.Thread.run(Thread.java:841)

"Compiler" daemon prio=5 tid=5 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x41fec348 self=0x64f7a008
  | sysTid=22504 nice=0 sched=0/0 cgrp=apps handle=1095861376
  | state=S schedstat=( 99333000 34411000 345 ) utm=4 stm=5 core=0
  #00  pc 000219bc  /system/lib/libc.so (__futex_syscall3+8)
  #01  pc 0000ef7c  /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
  #02  pc 0000efdc  /system/lib/libc.so (__pthread_cond_timedwait+64)
  #03  pc 00073cff  /system/lib/libdvm.so
  #04  pc 0005496d  /system/lib/libdvm.so
  #05  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #06  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at dalvik.system.NativeStart.run(Native Method)

"JDWP" daemon prio=5 tid=4 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x41fec260 self=0x41518028
  | sysTid=22503 nice=0 sched=0/0 cgrp=apps handle=1074183272
  | state=S schedstat=( 3731000 3154000 19 ) utm=0 stm=0 core=0
  #00  pc 00020790  /system/lib/libc.so (select+20)
  #01  pc 0006148f  /system/lib/libdvm.so
  #02  pc 00063fe1  /system/lib/libdvm.so
  #03  pc 0005496d  /system/lib/libdvm.so
  #04  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #05  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at dalvik.system.NativeStart.run(Native Method)

"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
  | group="system" sCount=0 dsCount=0 obj=0x41fec168 self=0x4006b810
  | sysTid=22502 nice=0 sched=0/0 cgrp=apps handle=1096879032
  | state=R schedstat=( 43220000 12993000 44 ) utm=2 stm=2 core=0
  at dalvik.system.NativeStart.run(Native Method)

"GC" daemon prio=5 tid=2 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x41fec088 self=0x41611688
  | sysTid=22501 nice=0 sched=0/0 cgrp=apps handle=1096883784
  | state=S schedstat=( 153973000 35837000 1985 ) utm=9 stm=6 core=0
  #00  pc 000219c0  /system/lib/libc.so (__futex_syscall3+12)
  #01  pc 0000ef7c  /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
  #02  pc 0000efdc  /system/lib/libc.so (__pthread_cond_timedwait+64)
  #03  pc 000528dd  /system/lib/libdvm.so (dvmRelativeCondWait(pthread_cond_t*, pthread_mutex_t*, long long, int)+24)
  #04  pc 00072773  /system/lib/libdvm.so
  #05  pc 0005496d  /system/lib/libdvm.so
  #06  pc 0000d228  /system/lib/libc.so (__thread_entry+72)
  #07  pc 0000d3c0  /system/lib/libc.so (pthread_create+240)
  at dalvik.system.NativeStart.run(Native Method)

----- end 22497 -----
@k0dek0mmand0
Copy link

👍 Seems to be related to #203 and comes in various flavors.

In our case an activity causes the manager to be started and stopped in a quick succession, which results in one thread being at waitForServiceToBeBound (synchronized) while also holding an explicit lock (lockAcquireService), and the other waiting at shouldStopAndJoin.

@colintheshots
Copy link
Author

I tried to reproduce this simply using the Robospice-Retrofit example and could not. After more testing, I can only reproduce this ANR when I have added any SpiceServiceListener to the current SpiceManager. I'll update the issue title to reflect this.

@colintheshots colintheshots changed the title Reliable ANR when SpiceManager is Preparing to Stop Reliable ANR related to SpiceServiceListener when SpiceManager is Starting Mar 24, 2014
@colintheshots
Copy link
Author

@stephanenicolas Any idea what might cause an ANR when using a SpiceServiceListener? Having the screen off seems to reproduce this reliably, but it can also happen in other ways. Thanks!

@stephanenicolas
Copy link
Owner

@colintheshots Sorry for the very long delay. Can you still reproduce that bug with 1.4.12 or current 1.4.13 snapshots ?

@stephanenicolas stephanenicolas added this to the 1.4.13 milestone Jun 11, 2014
@stephanenicolas
Copy link
Owner

I am really struggling to reproduce this error. Do you have a small snippet of activity showing the bug. Can you also check it is still present with 1.4.13 ?

@stephanenicolas
Copy link
Owner

@colintheshots and @k0dek0mmand0 , I am trying a new approach, blindly as I can't reproduce the bug.

Please try the latest 1.4.13 snapshot and report back. Thanks in advance and sorry for the delay to answer.

stephanenicolas added a commit that referenced this issue Jun 11, 2014
@colintheshots
Copy link
Author

Using 1.4.12, I just added getSpiceManager().addSpiceServiceListener(new MySpiceServiceListener()) to onResume in some existing sample code and ran it while the screen was off on my Nexus 4. The result was an ANR when I switched on the screen.

MySpiceServiceListener, in this case, simply implements the interface with no code added to any functions.

I'll try your 1.4.13 snapshot.

@stephanenicolas
Copy link
Owner

I tried that but couldn't get an ANR. You just add the spice service
listener in onResume and launch the app with screen off ?

2014-06-11 10:48 GMT-04:00 Colin Lee [email protected]:

Using 1.4.12, I just added getSpiceManager().addSpiceServiceListener(new
MySpiceServiceListener()) to onResume in some existing sample code and ran
it while the screen was off on my Nexus 4. The result was an ANR when I
switched on the screen.

MySpiceServiceListener, in this case, simply implements the interface with
no code added to any functions.

I'll try your 1.4.13 snapshot.


Reply to this email directly or view it on GitHub
#270 (comment)
.

@colintheshots
Copy link
Author

Yes, I simply added the SpiceServiceListener to this sample code in SampleSpiceActivity and it reproduced the bug: https://github.com/colintheshots/robospice-minnebar-example

@stephanenicolas
Copy link
Owner

@colintheshots Okay, let me try this, cloning your repo.

@colintheshots
Copy link
Author

I believe it works with the Robospice Retrofit sample app. You just need to make sure the code goes in the onResume() of the first activity that loads.

@stephanenicolas
Copy link
Owner

Thx @colintheshots , I got it :)
Oh, charming bug.

It looks like the latest SNAPSHOT of 1.4.13 resolved the problem. On my phone, the bug is gone with the snapshot, and present with 1.4.12. (Nexus 4, latest kitkat)

Can you confirm the issue is closed ?

@colintheshots
Copy link
Author

I was working from source and having issues getting my compilation environment right. Where are the SNAPSHOTS?

@stephanenicolas
Copy link
Owner

https://github.com/stephanenicolas/robospice/wiki/Using-RoboSpice-snapshots

2014-06-11 12:24 GMT-04:00 Colin Lee [email protected]:

I was working from source and having issues getting my compilation
environment right. Where are the SNAPSHOTS?


Reply to this email directly or view it on GitHub
#270 (comment)
.

@colintheshots
Copy link
Author

I verified that this ANR bug appears to be fixed.

@stephanenicolas
Copy link
Owner

Thank you very much for the follow-up though there was a very long time you reported the bug.

stephanenicolas added a commit that referenced this issue Jun 11, 2014
seva-ask pushed a commit to seva-ask/robospice that referenced this issue Jun 11, 2014
seva-ask pushed a commit to seva-ask/robospice that referenced this issue Jun 11, 2014
@Proper-Job
Copy link

I get this in some of my apps using 1.4.12.
I'd like to give those 1.4.13 snapshot jars a try.
I don't use maven or gradle (good old ant), is there a way to download the 1.4.13-SNAPSHOT jars somehwere?
Thanks
Moritz

@Proper-Job
Copy link

Never mind, I managed to build the snapshot myself.
Thanks anyways
Moritz

@stephanenicolas
Copy link
Owner

In case you want to do it again, look at the wiki, you will find the maven
snapshot repo of RS.

S.

2014-07-26 10:12 GMT+02:00 Moritz Pfeiffer [email protected]:

Never mind, I managed to build the snapshot myself.
Thanks anyways
Moritz


Reply to this email directly or view it on GitHub
#270 (comment)
.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

4 participants