ANR caused by Input dispatching timed out - while trying to get my public IP address

Question

I get the following complete error message: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 2. Wait queue head age: 9379.7ms.)

See below the code + traces. It seems that the lock happens at GetIP_WAN.java:32 which is the line:

            BufferedReader br = new BufferedReader(
                    new InputStreamReader(conn.getInputStream()));

I call this function whenever I detect a network change wifi-3g/4g-no internet. and in a few other places. it happens on every occasion but much more from the network change detection obviously.

I verify if the public IP has changed this way:

ipwan = giw.getWanIpAddress();

and in getWanIpAddress:

ipwan = new GetIP_WAN().execute().get();

ipwan being a String pointing to the public IP.

I am not able to reproduce this ANR.

My app uses several async tasks that might be an intensive async task for several seconds. If I test it with a strong load and I switch off wifi I don't have problems.

Input would be much appreciated!!!

public class GetIP_WAN extends AsyncTask<Void, Integer, String> {

    @Override
    protected  String doInBackground(Void... params) {
        URL url;

        String ipwan = null;
        try {
            // get URL content
            url = new URL("http://ipv4bot.whatismyipaddress.com/");
            URLConnection conn = url.openConnection();

            conn.setConnectTimeout(3000);

            // open the stream and put it into BufferedReader
            BufferedReader br = new BufferedReader(
                    new InputStreamReader(conn.getInputStream()));

            String inputLine;
            ipwan = br.readLine();

            br.close();
        } catch (java.net.SocketTimeoutException e) {
            return ("timeout");
        } catch (MalformedURLException e) {
            e.printStackTrace();
            return ("malformed");
        } catch (IOException e) {
            e.printStackTrace();
            return ("exception");
        }
        return (ipwan);
    }

}

and here is the trace (my code where the lock happens is identified by >>>):

"main" tid=1 Waiting 
"main" prio=5 tid=1 Waiting
  | group="main" sCount=1 dsCount=0 obj=0x7331b000 self=0xb81bb2c0
  | sysTid=23053 nice=-4 cgrp=default sched=0/0 handle=0xb6f5cbec
  | state=S schedstat=( 26983505120 16031385654 42843 ) utm=2225 stm=473 core=0 HZ=100
  | stack=0xbe5d4000-0xbe5d6000 stackSize=8MB
  | held mutexes=
  at java.lang.Object.wait! (Native method)
- waiting on <0x0448108a> (a java.lang.Object)
  at java.lang.Thread.parkFor (Thread.java:1220)
- locked <0x0448108a> (a java.lang.Object)
  at sun.misc.Unsafe.park (Unsafe.java:299)
  at java.util.concurrent.locks.LockSupport.park (LockSupport.java:157)
  at java.util.concurrent.FutureTask.awaitDone (FutureTask.java:400)
  at java.util.concurrent.FutureTask.get (FutureTask.java:162)
  at android.os.AsyncTask.get (AsyncTask.java:487)
  >>>   at com.bernard_zelmans.checksecurity.Connectivity.GetInfoWan.getWanIpAddress (GetInfoWan.java:168)
  >>>   at com.bernard_zelmans.checksecurity.Connectivity.ConnectivityFragment$2.onClick (ConnectivityFragment.java:155)
  at android.view.View.performClick (View.java:4781)
  at android.view.View$PerformClick.run (View.java:19874)
  at android.os.Handler.handleCallback (Handler.java:739)
  at android.os.Handler.dispatchMessage (Handler.java:95)
  at android.os.Looper.loop (Looper.java:135)
  at android.app.ActivityThread.main (ActivityThread.java:5254)
  at java.lang.reflect.Method.invoke! (Native method)
  at java.lang.reflect.Method.invoke (Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run (ZygoteInit.java:902)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:697)
"AsyncTask #5" tid=21 Native Performing network I/O
"AsyncTask #5" prio=5 tid=21 Native
  | group="main" sCount=1 dsCount=0 obj=0x1372b0a0 self=0xb8537190
  | sysTid=23175 nice=10 cgrp=bg_non_interactive sched=0/0 handle=0xb8536ee0
  | state=S schedstat=( 9854319 53209536 49 ) utm=0 stm=0 core=0 HZ=100
  | stack=0xa413d000-0xa413f000 stackSize=1036KB
  | held mutexes=
  native: pc 000000000003a180  /system/lib/libc.so (recvfrom+16)
  native: pc 0000000000020165  /system/lib/libjavacore.so (???)
  native: pc 00000000002d557d  /data/dalvik-cache/arm/system@framework@boot.oat (Java_libcore_io_Posix_recvfromBytes__Ljava_io_FileDescriptor_2Ljava_lang_Object_2IIILjava_net_InetSocketAddress_2+176)
  at libcore.io.Posix.recvfromBytes (Native method)
  at libcore.io.Posix.recvfrom (Posix.java:185)
  at libcore.io.BlockGuardOs.recvfrom (BlockGuardOs.java:250)
  at libcore.io.IoBridge.recvfrom (IoBridge.java:553)
  at java.net.PlainSocketImpl.read (PlainSocketImpl.java:485)
  at java.net.PlainSocketImpl.access$000 (PlainSocketImpl.java:37)
  at java.net.PlainSocketImpl$PlainSocketInputStream.read (PlainSocketImpl.java:237)
  at com.android.okio.Okio$2.read (Okio.java:113)
  at com.android.okio.RealBufferedSource.indexOf (RealBufferedSource.java:147)
  at com.android.okio.RealBufferedSource.readUtf8LineStrict (RealBufferedSource.java:94)
  at com.android.okhttp.internal.http.HttpConnection.readResponse (HttpConnection.java:179)
  at com.android.okhttp.internal.http.HttpTransport.readResponseHeaders (HttpTransport.java:101)
  at com.android.okhttp.internal.http.HttpEngine.readResponse (HttpEngine.java:628)
  at com.android.okhttp.internal.http.HttpURLConnectionImpl.execute (HttpURLConnectionImpl.java:388)
  at com.android.okhttp.internal.http.HttpURLConnectionImpl.getResponse (HttpURLConnectionImpl.java:332)
  at com.android.okhttp.internal.http.HttpURLConnectionImpl.getInputStream (HttpURLConnectionImpl.java:199)
  >>>  at com.bernard_zelmans.checksecurity.Connectivity.GetIP_WAN.doInBackground (GetIP_WAN.java:32)
  >>>  at com.bernard_zelmans.checksecurity.Connectivity.GetIP_WAN.doInBackground (GetIP_WAN.java:16)
  at android.os.AsyncTask$2.call (AsyncTask.java:292)
  at java.util.concurrent.FutureTask.run (FutureTask.java:237)
  at android.os.AsyncTask$SerialExecutor$1.run (AsyncTask.java:231)
  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:818)
"WifiManager" tid=22 Native 
"WifiManager" prio=5 tid=22 Native
  | group="main" sCount=1 dsCount=0 obj=0x137192e0 self=0xb85369a0
  | sysTid=23176 nice=0 cgrp=default sched=0/0 handle=0xb84af978
  | state=S schedstat=( 2818438 6808230 23 ) utm=0 stm=0 core=1 HZ=100
  | stack=0xa4035000-0xa4037000 stackSize=1036KB
  | held mutexes=
  native: pc 000000000003a0ac  /system/lib/libc.so (__epoll_pwait+20)
  native: pc 0000000000011483  /system/lib/libc.so (epoll_pwait+26)
  native: pc 0000000000011491  /system/lib/libc.so (epoll_wait+6)
  native: pc 0000000000010edf  /system/lib/libutils.so (_ZN7android6Looper9pollInnerEi+98)
  native: pc 0000000000011109  /system/lib/libutils.so (_ZN7android6Looper8pollOnceEiPiS1_PPv+92)
  native: pc 000000000007e371  /system/lib/libandroid_runtime.so (_ZN7android18NativeMessageQueue8pollOnceEP7_JNIEnvi+22)
  native: pc 000000000010e76b  /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+102)
  at android.os.MessageQueue.nativePollOnce (Native method)
  at android.os.MessageQueue.next (MessageQueue.java:143)
  at android.os.Looper.loop (Looper.java:122)
  at android.os.HandlerThread.run (HandlerThread.java:61)
"Heap thread pool worker thread 1" tid=2 Native 
"Heap thread pool worker thread 1" prio=5 tid=2 Native (still starting up)
  | group="" sCount=1 dsCount=0 obj=0x0 self=0xb8337008
  | sysTid=23060 nice=0 cgrp=default sched=0/0 handle=0xb81c1910
  | state=S schedstat=( 2796719 5468959 19 ) utm=0 stm=0 core=0 HZ=100
  | stack=0xb49ce000-0xb49d0000 stackSize=1020KB
  | held mutexes=
  native: pc 000000000000f9b0  /system/lib/libc.so (syscall+28)
  native: pc 00000000000a8c4b  /system/lib/libart.so (_ZN3art17ConditionVariable4WaitEPNS_6ThreadE+82)
  native: pc 000000000022f877  /system/lib/libart.so (_ZN3art10ThreadPool7GetTaskEPNS_6ThreadE+50)
  native: pc 000000000022f81f  /system/lib/libart.so (_ZN3art16ThreadPoolWorker3RunEv+54)
  native: pc 000000000023005d  /system/lib/libart.so (_ZN3art16ThreadPoolWorker8CallbackEPv+52)
  native: pc 00000000000132bb  /system/lib/libc.so (_ZL15__pthread_startPv+30)
  native: pc 00000000000111e7  /system/lib/libc.so (__start_thread+6)
"Heap thread pool worker thread 2" tid=3 Native 
"Heap thread pool worker thread 2" prio=5 tid=3 Native (still starting up)
  | group="" sCount=1 dsCount=0 obj=0x0 self=0xb81c0ea0
  | sysTid=23061 nice=0 cgrp=default sched=0/0 handle=0xb833a0b0
  | state=S schedstat=( 5997967 2723698 18 ) utm=0 stm=0 core=0 HZ=100
  | stack=0xb48ce000-0xb48d0000 stackSize=1020KB
  | held mutexes=
  native: pc 000000000000f9b0  /system/lib/libc.so (syscall+28)
  native: pc 00000000000a8c4b  /system/lib/libart.so (_ZN3art17ConditionVariable4WaitEPNS_6ThreadE+82)
  native: pc 000000000022f877  /system/lib/libart.so (_ZN3art10ThreadPool7GetTaskEPNS_6ThreadE+50)
  native: pc 000000000022f81f  /system/lib/libart.so (_ZN3art16ThreadPoolWorker3RunEv+54)
  native: pc 000000000023005d  /system/lib/libart.so (_ZN3art16ThreadPoolWorker8CallbackEPv+52)
  native: pc 00000000000132bb  /system/lib/libc.so (_ZL15__pthread_startPv+30)
  native: pc 00000000000111e7  /system/lib/libc.so (__start_thread+6)
"Heap thread pool worker thread 0" tid=4 Native 
"Heap thread pool worker thread 0" prio=5 tid=4 Native (still starting up)
  | group="" sCount=1 dsCount=0 obj=0x0 self=0xb83390c0
  | sysTid=23059 nice=0 cgrp=default sched=0/0 handle=0xb82a4b58
  | state=S schedstat=( 3379426 4137085 15 ) utm=0 stm=0 core=1 HZ=100
  | stack=0xb4ace000-0xb4ad0000 stackSize=1020KB
  | held mutexes=
  native: pc 000000000000f9b0  /system/lib/libc.so (syscall+28)
  native: pc 00000000000a8c4b  /system/lib/libart.so (_ZN3art17ConditionVariable4WaitEPNS_6ThreadE+82)
  native: pc 000000000022f877  /system/lib/libart.so (_ZN3art10ThreadPool7GetTaskEPNS_6ThreadE+50)
  native: pc 000000000022f81f  /system/lib/libart.so (_ZN3art16ThreadPoolWorker3RunEv+54)
  native: pc 000000000023005d  /system/lib/libart.so (_ZN3art16ThreadPoolWorker8CallbackEPv+52)
  native: pc 00000000000132bb  /system/lib/libc.so (_ZL15__pthread_startPv+30)
  native: pc 00000000000111e7  /system/lib/libc.so (__start_thread+6)
"HeapTrimmerDaemon" tid=6 Waiting 
"HeapTrimmerDaemon" daemon prio=5 tid=6 Waiting
  | group="system" sCount=1 dsCount=0 obj=0x12c061c0 self=0xb833c230
  | sysTid=23066 nice=0 cgrp=default sched=0/0 handle=0xb833ca20
  | state=S schedstat=( 16039218 18453438 23 ) utm=1 stm=0 core=3 HZ=100
  | stack=0xa6f4e000-0xa6f50000 stackSize=1036KB
  | held mutexes=
  at java.lang.Object.wait! (Native method)
- waiting on <0x1c7546fb> (a java.lang.Daemons$HeapTrimmerDaemon)
  at java.lang.Daemons$HeapTrimmerDaemon.run (Daemons.java:311)
- locked <0x1c7546fb> (a java.lang.Daemons$HeapTrimmerDaemon)
  at java.lang.Thread.run (Thread.java:818)
"GCDaemon" tid=7 Waiting 
"FinalizerWatchdogDaemon" tid=8 Waiting 
"Binder_1" tid=9 Native 
"FinalizerDaemon" tid=10 Waiting 
"ReferenceQueueDaemon" tid=11 Waiting 
"Binder_2" tid=12 Native 
"AsyncTask #1" tid=13 Waiting 
"Timer-0" tid=14 Waiting 
"RenderThread" tid=15 Native 
"AsyncTask #2" tid=18 Waiting 
"AsyncTask #3" tid=19 Waiting 
"AsyncTask #4" tid=20 Waiting 
"Binder_3" tid=23 Native 
"AdWorker(Default) #1" tid=24 TimedWaiting 
"java.lang.ProcessManager" tid=25 Waiting 
"AdWorker(Default) #2" tid=26 TimedWaiting 
"AdWorker(Default) #3" tid=27 TimedWaiting 
"AdWorker(Default) #4" tid=28 TimedWaiting 
"AdWorker(Default) #5" tid=29 TimedWaiting 
"Binder_6" tid=30 Native 
"Binder_4" tid=40 Native 
"Binder_7" tid=45 Native 
"Binder_5" tid=49 Native 
"Signal Catcher" tid=5 Runnable 
"Signal Catcher" daemon prio=5 tid=5 Runnable
  | group="system" sCount=0 dsCount=0 obj=0x12c000a0 self=0xb833abf8
  | sysTid=23062 nice=0 cgrp=default sched=0/0 handle=0xb8339498
  | state=R schedstat=( 166092660 21972502 124 ) utm=8 stm=8 core=0 HZ=100
  | stack=0xb47c4000-0xb47c6000 stackSize=1012KB
  | held mutexes= "thread list lock" "mutator lock"(exclusive held)
  native: pc 0000000000004758  /system/lib/libbacktrace_libc++.so (_ZN13UnwindCurrent6UnwindEjP8ucontext+23)
  native: pc 0000000000002f8d  /system/lib/libbacktrace_libc++.so (_ZN9Backtrace6UnwindEjP8ucontext+8)
  native: pc 00000000002411c9  /system/lib/libart.so (_ZN3art15DumpNativeStackERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEEiPKcPNS_6mirror9ArtMethodE+68)
  native: pc 0000000000225591  /system/lib/libart.so (_ZNK3art6Thread4DumpERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+148)
  native: pc 000000000022e8bb  /system/lib/libart.so (_ZN3art10ThreadList14DumpForSigQuitERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+142)
  native: pc 0000000000215ca5  /system/lib/libart.so (_ZN3art7Runtime14DumpForSigQuitERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+68)
  native: pc 000000000021a431  /system/lib/libart.so (_ZN3art13SignalCatcher13HandleSigQuitEv+752)
  native: pc 000000000021aadb  /system/lib/libart.so (_ZN3art13SignalCatcher3RunEPv+318)
  native: pc 00000000000132bb  /system/lib/libc.so (_ZL15__pthread_startPv+30)
  native: pc 00000000000111e7  /system/lib/libc.so (__start_thread+6)

great input. I see my error. I did not think it was not safe to return directly from doinbackground a data to use in the UI. Let me rephrase what you said because. I'm not sure I've understood the terminology handler and weakref. frag calls async task which calls http (in doinbackgroud), when it gets the ip it waits for onpostexecute to send the ip @ through a method? — narb, Nov 06 '17 at 16:18
Well even though onPostExecute(...) is fired on the UI thread, it should not touch any Views directly because it can easily cause memory leaks. What you should do is indicate to the owner of the View, such as a Fragment or a Activity, that some work has completed and it should update it's view using the AsyncTask data. I recommended using a Handler to pass data between the AsyncTask and wrapping it inside of an WeakReference that way if the Fragment or Activity where to get destroyed you wouldn't have a strong reference to it preventing it from getting GC'd thus leaking an Activity. — cincy_anddeveloper, Nov 06 '17 at 16:26
I assume the reason you are not able to reproduce the ANR is because doInBackground happens to be completing to fast. Try placing a sleep call inside of the method. Or even just place the downloading code in a for loop and execute the code a few times. Just for sanities sake, log how long it takes to execute doInBackground... I assume for your users in the field, they have much worse network conditions and the download times increase significantly. — cincy_anddeveloper, Nov 06 '17 at 16:47
AsyncTask are fantastic ways to perform some long running work on a background thread and periodically update an apps UI with information about the data. The interesting part is, it can easily cause a memory leak if you don't pay special attention, but you can say that about many things in Android/Java and C++ for that matter. :) Takes a bit of thinking to get right. Good Luck! — cincy_anddeveloper, Nov 06 '17 at 16:58
it smells good. no more crash despite that in the same routine I was doing an async task that was again returning directly a string from doinbackground and it crashed yesterday :):) one more time: thanks a lot! — narb, Nov 08 '17 at 20:24

cincy_anddeveloper · Accepted Answer · 2018-12-11T16:19:51.710

I think your problem is that you're calling AsyncTask.get() right after you call GetIP_WAN().execute(). I assume that you're calling GetIP_WAN().execute() on the UI thread. If it's in an onClick callback or a BroadcastReceiver it most certainly is. So what I believe is happening is your GetIP_WAN task is correctly executing on a background thread completing but the get() call is attempting to retrieve the data that will get returned from doInBackground(). But that call (get()) will NEVER return before doInBackground and maybe onPostExecute(...) returns, thus causing blocking on the UI thread. If you read the documentation for get inside of the AsyncTask class it says

/** * Waits if necessary for the computation to complete, and then * retrieves its result. * * @return The computed result. * * @throws CancellationException If the computation was cancelled. * @throws ExecutionException If the computation threw an exception. * @throws InterruptedException If the current thread was interrupted * while waiting. */

Ironically, you are negating the purpose of you AsnycTask. Even though the work is taking place on the background thread, you are forcing the UI thread to wait for the work to complete before any additional processing on the UI thread can complete. The Android OS handles creating a ANR dialog when it detects the UI/Main thread has been blocking for 5 seconds.

I assume you are calling get so you can get your data from GetIP_WAN, so you can manipulate/display it on the UI thread. What I recommend is you pass some form of reference to the owning activity or fragment into the GetIP_WAN and when the task completes and fires onPostExecute(...) which will be fired on the UI/Main thread, you act upon the activity or fragment to update it's UI with the data you downloaded in doInBackground(...). One pattern I'd recommend is passing a Handler reference that's wrapped inside of a WeakReference into GetIP_WAN and in onPostExecute(...), send an empty message indicating that the work was completed and it's safe to call GetIP_WAN.get().

ANR caused by Input dispatching timed out - while trying to get my public IP address

1 Answers1

Linked