Sync fails with "The target server failed to respond"

[AutoImport-oliver]

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?

[rfc2822]

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

[AutoImport-oliver]

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.

[rfc2822]

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

[rfc2822]

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.