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 task that might be 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@[email protected] (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@[email protected] (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)

Answer 1

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().