Weird ANR in ForegroundService
<p>I have the following code:</p>

<pre class="lang-java prettyprint-override"><code>BasicHttpResponse send(String message) throws KeyStoreException, IOException, NoSuchAlgorithmException, UnsupportedEncodingException, AuthenticationException, CertificateException, KeyManagementException, UnrecoverableKeyException {
    Log.d(context.getString(R.string.app_name), "SOAP: " + message);

    //SSL
    final KeyStore keyStore = KeyStore.getInstance("BKS");
    keyStore.load(context.getResources().openRawResource(R.raw.ipex), "xxx".toCharArray());
    final SSLSocketFactory ssl = new SSLSocketFactory(keyStore);
    ssl.setHostnameVerifier(SSLSocketFactory.ALLOW_ALL_HOSTNAME_VERIFIER);
    http.getConnectionManager().getSchemeRegistry().register(new Scheme("https", ssl, 443));

    //SOAP POST
    post.setHeader("Content-Type", "application/soap+xml; charset=utf-8");
    http.modifyRequestToAcceptGzipResponse(post);
    final StringEntity entity = new StringEntity(message.toString(), HTTP.UTF_8);
    entity.setContentType("text/xml");
    post.setEntity(entity);

    //Basic HTTP authentication
    post.setHeader(new BasicScheme().authenticate(credentials, post));

    //Send request
    BasicHttpResponse response = null;
    final byte max = 5;
    for (byte i = 1; response == null || (i &lt;= max &amp;&amp; response.getStatusLine().getStatusCode() != HttpStatus.SC_OK); i++) {
        Log.d(context.getString(R.string.app_name), String.format("SOAP: %d/%d", i, max));
        response = (BasicHttpResponse) http.execute(post);
        Log.d(context.getString(R.string.app_name), response.getStatusLine().toString());
    }

    //Unpack response
    final BasicHttpEntity ungzipped = new BasicHttpEntity();
    ungzipped.setContent(http.getUngzippedContent(response.getEntity()));
    response.setEntity(ungzipped);

    Log.v(context.getString(R.string.app_name), "SOAP: return");
    return response;
}
</code></pre>

<p>It always ends in the 3. loop, and puts this in the logcat:</p>

<pre class="lang-none prettyprint-override"><code>D/ipexcti ( 5432): SOAP: &lt;?xml version="1.0"?&gt;&lt;soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:ipex="http://ipbx/binding" xmlns:xmpp="http://ipbx.namespace"&gt;&lt;soap:Body&gt;&lt;ipex:setJabberStatus&gt;&lt;type&gt;mobile&lt;/type&gt;&lt;number&gt;123456789&lt;/number&gt;&lt;param&gt;&lt;xmpp:status&gt;offline&lt;/xmpp:status&gt;&lt;xmpp:status_msg&gt;hovor na mobilním telefonu&lt;/xmpp:status_msg&gt;&lt;xmpp:resource&gt;ipexcti&lt;/xmpp:resource&gt;&lt;/param&gt;&lt;/ipex:setJabberStatus&gt;&lt;/soap:Body&gt;&lt;/soap:Envelope&gt;
D/ipexcti ( 5432): SOAP: 1/5
D/ipexcti ( 5432): HTTP/1.1 500 Internal Service Error
D/ipexcti ( 5432): SOAP: 2/5
D/dalvikvm( 5432): GC_CONCURRENT freed 326K, 51% free 2799K/5639K, external 0K/0K, paused 3ms+1ms
D/ipexcti ( 5432): HTTP/1.1 500 Internal Service Error
D/ipexcti ( 5432): SOAP: 3/5
D/dalvikvm( 5278): GC_EXPLICIT freed 316K, 45% free 3616K/6471K, external 0K/0K, paused 39ms
I/Process (  186): Sending signal. PID: 5432 SIG: 3
I/dalvikvm( 5432): threadid=4: reacting to signal 3
W/ActivityManager(  186): Timeout executing service: ServiceRecord{40b34138 cz.ipex.ipexcti/.ipexctiService}
I/dalvikvm( 5432): Wrote stack traces to '/data/anr/traces.txt'
I/Process (  186): Sending signal. PID: 186 SIG: 3
I/dalvikvm(  186): threadid=4: reacting to signal 3
I/dalvikvm(  186): Wrote stack traces to '/data/anr/traces.txt'
I/Process (  186): Sending signal. PID: 272 SIG: 3
I/dalvikvm(  272): threadid=4: reacting to signal 3
I/dalvikvm(  272): Wrote stack traces to '/data/anr/traces.txt'
I/Process (  186): Sending signal. PID: 273 SIG: 3
I/dalvikvm(  273): threadid=4: reacting to signal 3
I/dalvikvm(  273): Wrote stack traces to '/data/anr/traces.txt'
I/Process (  186): Sending signal. PID: 250 SIG: 3
I/dalvikvm(  250): threadid=4: reacting to signal 3
I/dalvikvm(  250): Wrote stack traces to '/data/anr/traces.txt'
D/dalvikvm(  186): GC_EXPLICIT freed 1005K, 43% free 7750K/13447K, external 2052K/2310K, paused 63ms
I/Process (  186): Sending signal. PID: 5432 SIG: 9
E/ActivityManager(  186): ANR in cz.ipex.ipexcti:service
E/ActivityManager(  186): Reason: Executing service cz.ipex.ipexcti/.ipexctiService
E/ActivityManager(  186): Load: 2.14 / 2.18 / 2.22
E/ActivityManager(  186): CPU usage from 24393ms to 846ms ago:
E/ActivityManager(  186):   2.4% 186/system_server: 0.6% user + 1.7% kernel / faults: 12 minor
E/ActivityManager(  186):   0.2% 250/com.android.systemui: 0.1% user + 0% kernel / faults: 360 minor
E/ActivityManager(  186):   0.3% 33/vsync_workqueue: 0% user + 0.3% kernel
E/ActivityManager(  186):   0.1% 54/gp2a_wq: 0% user + 0.1% kernel
E/ActivityManager(  186):   0.1% 2870/com.google.android.apps.maps:NetworkLocationService: 0.1% user + 0% kernel / faults: 66 minor
E/ActivityManager(  186):   0.1% 5278/com.google.android.apps.maps:LocationFriendService: 0.1% user + 0% kernel / faults: 62 minor
E/ActivityManager(  186):   0% 51/file-storage: 0% user + 0% kernel
E/ActivityManager(  186):   0% 1889/dhd_dpc: 0% user + 0% kernel
E/ActivityManager(  186):   0% 1891/wpa_supplicant: 0% user + 0% kernel
E/ActivityManager(  186):   0% 5/events/0: 0% user + 0% kernel
E/ActivityManager(  186):   0% 71/mmcqd: 0% user + 0% kernel
E/ActivityManager(  186):   0% 138/rild: 0% user + 0% kernel
E/ActivityManager(  186):   0% 139/zygote: 0% user + 0% kernel / faults: 8 minor
E/ActivityManager(  186):   0% 164/flush-179:0: 0% user + 0% kernel
E/ActivityManager(  186):   0% 272/com.android.phone: 0% user + 0% kernel
E/ActivityManager(  186):   0% 313/com.google.process.gapps: 0% user + 0% kernel
E/ActivityManager(  186):  +0% 5432/cz.ipex.ipexcti:service: 0% user + 0% kernel
E/ActivityManager(  186): 4.6% TOTAL: 2.3% user + 2.3% kernel + 0% iowait
E/ActivityManager(  186): CPU usage from 183ms to 696ms later:
E/ActivityManager(  186):   3.8% 186/system_server: 3.8% user + 0% kernel
E/ActivityManager(  186):     3.8% 203/ActivityManager: 1.9% user + 1.9% kernel
E/ActivityManager(  186):   1.4% 54/gp2a_wq: 0% user + 1.4% kernel
E/ActivityManager(  186): 3.8% TOTAL: 1.9% user + 1.9% kernel
I/ActivityManager(  186): Process cz.ipex.ipexcti:service (pid 5432) has died.
W/ActivityManager(  186): Scheduling restart of crashed service cz.ipex.ipexcti/.ipexctiService in 166048ms
</code></pre>

<p>The <code>traces.txt</code> says this about my process:</p>

<pre class="lang-none prettyprint-override"><code>----- pid 5812 at 2011-12-13 16:39:02 -----
Cmd line: cz.ipex.ipexcti:service

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)
"main" prio=5 tid=1 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x4001f1b0 self=0xce60
  | sysTid=5812 nice=0 sched=0/0 cgrp=default handle=-1345002432
  at java.lang.Object.wait(Native Method)
  - waiting on &lt;0x4001f248&gt; (a java.lang.VMThread)
  at java.lang.Thread.parkFor(Thread.java:1424)
  at java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
  at sun.misc.Unsafe.park(Unsafe.java:337)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:808)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:968)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1274)
  at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:220)
  at java.util.concurrent.FutureTask.get(FutureTask.java:83)
  at android.os.AsyncTask.get(AsyncTask.java:340)
  at cz.ipex.ipexcti.Presence.set(Presence.java:65)
  at cz.ipex.ipexcti.ipexctiService.onStartCommand(ipexctiService.java:30)
  at android.app.ActivityThread.handleServiceArgs(ActivityThread.java:2160)
  at android.app.ActivityThread.access$2800(ActivityThread.java:123)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1002)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:130)
  at android.app.ActivityThread.main(ActivityThread.java:3835)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:507)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:847)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:605)
  at dalvik.system.NativeStart.main(Native Method)

"RefQueueWorker@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@40525a88" daemon prio=5 tid=10 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x405289d8 self=0x13c1b0
  | sysTid=5821 nice=0 sched=0/0 cgrp=default handle=1295080
  at java.lang.Object.wait(Native Method)
  - waiting on &lt;0x405279d0&gt; (a java.lang.ref.ReferenceQueue)
  at java.lang.Object.wait(Object.java:395)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:107)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:80)
  at org.apache.http.impl.conn.tsccm.RefQueueWorker.run(RefQueueWorker.java:102)
  at java.lang.Thread.run(Thread.java:1019)

"AsyncTask #1" prio=5 tid=9 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x40523bc8 self=0x13b758
  | sysTid=5820 nice=10 sched=0/0 cgrp=bg_non_interactive handle=1292432
  at java.lang.Object.wait(Native Method)
  - waiting on &lt;0x40523da0&gt; (a java.lang.VMThread)
  at java.lang.Thread.parkFor(Thread.java:1424)
  at java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
  at sun.misc.Unsafe.park(Unsafe.java:337)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2016)
  at org.apache.http.impl.conn.tsccm.WaitingThread.await(WaitingThread.java:159)
  at org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking(ConnPoolByRoute.java:339)
  at org.apache.http.impl.conn.tsccm.ConnPoolByRoute$1.getPoolEntry(ConnPoolByRoute.java:238)
  at org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager$1.getConnection(ThreadSafeClientConnManager.java:175)
  at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:325)
  at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:555)
  at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:487)
  at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:465)
  at android.net.http.AndroidHttpClient.execute(AndroidHttpClient.java:246)
  at cz.ipex.ipexcti.SOAP.send(SOAP.java:66)
  at cz.ipex.ipexcti.Presence$SoapTask.doInBackground(Presence.java:92)
  at cz.ipex.ipexcti.Presence$SoapTask.doInBackground(Presence.java:86)
  at android.os.AsyncTask$2.call(AsyncTask.java:185)
  at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:306)
  at java.util.concurrent.FutureTask.run(FutureTask.java:138)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1088)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:581)
  at java.lang.Thread.run(Thread.java:1019)

"Binder Thread #2" prio=5 tid=8 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x4051a928 self=0x12a118
  | sysTid=5819 nice=0 sched=0/0 cgrp=default handle=610768
  at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #1" prio=5 tid=7 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x40513978 self=0x944b8
  | sysTid=5818 nice=0 sched=0/0 cgrp=default handle=972000
  at dalvik.system.NativeStart.run(Native Method)

"Compiler" daemon prio=5 tid=6 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x4050f888 self=0x93388
  | sysTid=5817 nice=0 sched=0/0 cgrp=default handle=976016
  at dalvik.system.NativeStart.run(Native Method)

"JDWP" daemon prio=5 tid=5 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x4050f7d8 self=0x92a48
  | sysTid=5816 nice=0 sched=0/0 cgrp=default handle=542000
  at dalvik.system.NativeStart.run(Native Method)

"Signal Catcher" daemon prio=5 tid=4 RUNNABLE
  | group="system" sCount=0 dsCount=0 obj=0x4050f718 self=0xee1d0
  | sysTid=5815 nice=0 sched=0/0 cgrp=default handle=979816
  at dalvik.system.NativeStart.run(Native Method)

"GC" daemon prio=5 tid=3 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x4050f670 self=0xedfd8
  | sysTid=5814 nice=0 sched=0/0 cgrp=default handle=967136
  at dalvik.system.NativeStart.run(Native Method)

"HeapWorker" daemon prio=5 tid=2 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x4050f5b8 self=0xed5f0
  | sysTid=5813 nice=0 sched=0/0 cgrp=default handle=971784
  at dalvik.system.NativeStart.run(Native Method)

----- end 5812 -----
</code></pre>

<p>I don't fully understand what's going on.</p>

<p>I am aware of what ANR is, and how to try to avoid it, and I guess I'm doing it, but... Android doesn't think so.</p>

<p>The app consist of <code>Activity</code> with buttons. The buttons sends messages to my <code>ForegroundService</code> (using <code>StartService()</code> with <code>Intent</code>). The <code>ForegroundService</code> then creates the class which prepares the SOAP message, instantiates the SOAP class and starts <code>AsyncTask</code> to actually perform the <code>send()</code> (as seen in <code>traces.txt</code>).</p>

<p>So, the HTTP part of the code is running in <code>AsyncTask</code>, so why the ANR???</p>

<p>P. S. Why 5 attempts? The PHP SOAP server is sometimes returning HTTP 500 with SOAP response saying <code>Bad Request</code> and we don't know why. Any idea about that?</p>
