eclipse / paho.mqtt.android

MQTT Android
Other
2.92k stars 882 forks source link

Ping alarm sender causing ANRs (Application Not Responding) #176

Open miketran78727 opened 7 years ago

miketran78727 commented 7 years ago

Please fill out the form below before submitting, thank you!

Android Version Bug Seen on: Kitkat 4.4 – 4.4.4

Description of Bug:

Users of applications see a lot of ANRs (Application Not Responding).

The user is currently using some snapshot build.

The ping alarm sender called checkForActivity() method of the Java client to send ping request. For some reason (perhaps network was down), the ping was not sent and connection was being shutdown. However, the Java client send thread was still holding the synchronized lock for a long period of time (> 10 seconds). As a result, Android displayed ANR because the Ping alarm sender was running in the main UI thread.

I will submit a pull request to prevent ANRs. The fix is to move the call to checkForActivity() into a AsyncTask.

Java trace dump when this happened:


Cmd line: com.canadapost.ngmc.daa

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

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

"main" prio=5 tid=1 MONITOR | group="main" sCount=1 dsCount=0 obj=0x41573cb0 self=0x414ae4d0 | sysTid=1689 nice=0 sched=0/0 cgrp=apps handle=1073906004 | state=S schedstat=( 1013898804035 274663543480 788978 ) utm=93619 stm=7770 core=1 at org.eclipse.paho.client.mqttv3.internal.ClientState.resolveOldTokens(ClientState.java:~1194)

"Timer-50" prio=5 tid=23 TIMED_WAIT | group="main" sCount=1 dsCount=0 obj=0x41d44538 self=0x62ba8540 | sysTid=12346 nice=0 sched=0/0 cgrp=apps handle=1647349032 | state=S schedstat=( 83679195 77117922 81 ) utm=6 stm=2 core=1 at java.lang.Object.wait(Native Method)

"MQTT Snd: 16133521404774" prio=5 tid=44 NATIVE | group="main" sCount=1 dsCount=0 obj=0x41df9290 self=0x62bda2a0 | sysTid=12344 nice=0 sched=0/0 cgrp=apps handle=1642915896 | state=S schedstat=( 13397217 65734864 30 ) utm=1 stm=0 core=1

00 pc 000207a0 /system/lib/libc.so (select+20)

01 pc 00008941 /system/lib/libjavacrypto.so

02 pc 000097c1 /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 00000214 /dev/ashmem/dalvik-jit-code-cache (deleted)

at com.android.org.conscrypt.NativeCrypto.SSL_write(Native Method) at com.android.org.conscrypt.OpenSSLSocketImpl$SSLOutputStream.write(OpenSSLSocketImpl.java:972) at com.crittercism.internal.i.write((null):84) at java.io.BufferedOutputStream.flushInternal(BufferedOutputStream.java:185) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:85) at org.eclipse.paho.client.mqttv3.internal.wire.MqttOutputStream.flush(MqttOutputStream.java:49) at org.eclipse.paho.client.mqttv3.internal.CommsSender.run(CommsSender.java:117) at java.lang.Thread.run(Thread.java:841)

oleshkevych commented 6 years ago

The same on sdk 23 (Android 6.0)

gradle: compile 'org.eclipse.paho:org.eclipse.paho.client.mqttv3:1.1.0' compile 'org.eclipse.paho:org.eclipse.paho.android.service:1.1.1'

D/AlarmPingSender: Sending Ping at:1,523,608,902,173 04-13 08:41:42.176 29941-29941/... E/ClientState: dd395abbe920af8|...|paho2268019988039: Timed out as no activity, keepAlive=60,000 lastOutboundActivity=1,523,608,842,170 lastInboundActivity=1,523,608,782,285 time=1,523,608,902,174 lastPing=1,523,608,842,170 04-13 08:42:12.754 29941-29949/.... E/PowerManager: WakeLock finalized while still held: MqttService.client.dd395abbe920af8|.....|paho2268019988039