Sync fails with "The target server failed to respond"

---

With version 0.5.10.2 (installed via F-Droid) under Android 4.1, I now get this error:

I/davdroid.SyncManager(23379): Fetching 460 new remote resource(s)
I/davdroid.RemoteCollection(23379): Multi-getting 35 remote resource(s)
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "REPORT /calendars/__uids__/2faeac7a-0279-583d-8282-ce4c6cd37a6e/calendar/ HTTP/1.1[\r][\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "Content-Type: text/xml; charset=UTF-8[\r][\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "Depth: 0[\r][\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "Content-Length: 4465[\r][\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "Host: servername:8008[\r][\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "Connection: Keep-Alive[\r][\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "User-Agent: DAVdroid/0.5.10.2-alpha[\r][\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "Accept-Encoding: gzip,deflate[\r][\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "Authorization: Basic b2xpdmVyOnBhc3M=[\r][\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "[\r][\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "<C:calendar-multiget xmlns:C="urn:ietf:params:xml:ns:caldav" xmlns="DAV:">[\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "   <prop>[\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "      <C:calendar-data/>[\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "      <getetag/>[\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "   </prop>[\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "   <href>/calendars/__uids__/2faeac7a-0279-583d-8282-ce4c6cd37a6e/calendar/03081c1c-060b-41e6-848e-8552eec6a86b.ics</href>[\n]"

…

D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "   <href>/calendars/__uids__/2faeac7a-0279-583d-8282-ce4c6cd37a6e/calendar/cc08285a-2b75-47c0-9c9d-8010d7e404b3.ics</href>[\n]"
D/ch.boye.httpclientandroidlib.wire(23379): http-outgoing-7 >> "</C:calendar-multiget>"
D/class ch.boye.httpclientandroidlib.impl.conn.DefaultManagedHttpClientConnection(23379): http-outgoing-7: Close connection
D/class ch.boye.httpclientandroidlib.impl.conn.DefaultManagedHttpClientConnection(23379): http-outgoing-7: Shutdown connection
D/class ch.boye.httpclientandroidlib.impl.conn.DefaultManagedHttpClientConnection(23379): http-outgoing-7: Close connection
E/davdroid.DavSyncAdapter(23379): I/O error
E/davdroid.DavSyncAdapter(23379): ch.boye.httpclientandroidlib.NoHttpResponseException: The target server failed to respond
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:143)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:260)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:161)
E/davdroid.DavSyncAdapter(23379): 	at java.lang.reflect.Method.invokeNative(Native Method)
E/davdroid.DavSyncAdapter(23379): 	at java.lang.reflect.Method.invoke(Method.java:511)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.conn.CPoolProxy.invoke(CPoolProxy.java:138)
E/davdroid.DavSyncAdapter(23379): 	at $Proxy5.receiveResponseHeader(Native Method)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:271)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:123)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.execchain.MainClientExec.execute(MainClientExec.java:254)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.execchain.RetryExec.execute(RetryExec.java:85)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.execchain.RedirectExec.execute(RedirectExec.java:108)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:186)
E/davdroid.DavSyncAdapter(23379): 	at ch.boye.httpclientandroidlib.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
E/davdroid.DavSyncAdapter(23379): 	at at.bitfire.davdroid.webdav.WebDavResource.multiGet(WebDavResource.java:298)
E/davdroid.DavSyncAdapter(23379): 	at at.bitfire.davdroid.resource.RemoteCollection.multiGet(RemoteCollection.java:88)
E/davdroid.DavSyncAdapter(23379): 	at at.bitfire.davdroid.syncadapter.SyncManager.pullNew(SyncManager.java:187)
E/davdroid.DavSyncAdapter(23379): 	at at.bitfire.davdroid.syncadapter.SyncManager.synchronize(SyncManager.java:87)
E/davdroid.DavSyncAdapter(23379): 	at at.bitfire.davdroid.syncadapter.DavSyncAdapter.onPerformSync(DavSyncAdapter.java:93)
E/davdroid.DavSyncAdapter(23379): 	at android.content.AbstractThreadedSyncAdapter$SyncThread.run(AbstractThreadedSyncAdapter.java:254)
D/SyncManager(  572): failed sync operation rb2 (bitfire.at.davdroid), com.android.calendar, USER, earliestRunTime 158299076, SyncResult: stats [ numIoExceptions: 1]

This is for a big calendar (460 items apparently); with a smaller calendar (~10-20 items) it works fine. With older versions (0.5.6 maybe?) this error didn’t occur.

The calendar is served by Darwin CalendarServer 2.4 running on Debian. It can be used fine with Thunderbird+Lightning.

Not sure yet whether the problem is on server or client side… Does the backtrace ring any bells?

Not sure yet whether the problem is on server or client side… Does the backtrace ring any bells?

Looks like a server problem. DAVdroid as sent a REPORT multi-get request, but the server didn’t send anything back (apparently not even headers).

So I think this is caused by the server closing the (HTTP keep-alive) connection, but the client doesn’t notice this (or notices too late). IIUC this is what happens:

• client opens HTTP connection (HTTP 1.1, so keep-alive is implicitly enabled)
• client sends PROPFIND request
• server sends huge HTTP 1.1 response (Content-Length: 224076)
• client has to a) receive and b) parse response, and c) create the REPORT request for first 35 items
• a+b+c takes maybe 20-40 seconds; but the server closes the HTTP connection 15 seconds after it has finished sending its response (server calls shutdown() and close() on the socket) - this is due to the default “idle timeout” in Calendarserver being set to 15 seconds
• client doesn’t notice that server has closed connection, tries to send REPORT request over socket that is already closed on server side
• server replies with TCP Reset packets, and client finally closes connection on his side, and raises error because it didn’t get a response

I have now worked around this problem by increasing the HTTP Keep-Alive timeout on server to 120 seconds, by adding these lines to /etc/caldavd/caldavd.plist:

    <key>IdleConnectionTimeOut</key>
    <integer>120</integer>

(this is probably a good idea anyway, performance-wise).

So the problem is aggravated by a large calendar, low-end phone (600 MHz) and low Keep-Alive timeout on server side.

It would be nice if there was a way to make the client notice that the Keep-Alive connection is closed before it sends the next request. No idea at the moment how to do that.

Sounds reasonable, thanks for the debugging work. I will have a look at the Keep-Alive settings.

I have tried this out by setting the Keep-Alive time on our server to 2 secs and adding a Thread.sleep(5000) between two operations so that the stale connection problem can be reproduced: In DAVroid/0.5.11, the NoHttpResponseException (which is a soft I/O error) occurs because the HttpClient stale connection check is disabled AND there’s not appropriate retry strategy.

With the new DavHttpRequestRetryHandler, the request is retried on a new connection when the old connection has got stale (closed). The stale connection check is not required because at the moment, all used HTTP verbs are idempotent.