DAVdroid loses or duplicates events on sync



  • Recently, I have some problems with DAVdroid losing or duplicating some events (& perhaps also tasks and contacts) when syncing. I use Baïkal 0.4.6 on Nginx. Syncing with KOrganizer (KDE) and infcloud works as it should. I tested with two different calendars Android-side, so I know it is not a specific problem of my calendar application.

    I saved the logs of a sync (for now without any server-side updates) and the only ‘error’-like thing I see (repeated, for each resource, it seems) is:

    <d:multistatus xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns" xmlns:cal="urn:ietf:params:xml:ns:caldav" xmlns:cs="http://calendarserver.org/ns/" xmlns:card="urn:ietf:params:xml:ns:carddav">
     ...
     <d:response>
      ...
      <d:propstat>
       <d:prop>
        <d:displayname/>
        <card:addressbook-description/>
        <card:supported-address-data/>
        <cal:calendar-description/>
        <x1:calendar-color xmlns:x1="http://apple.com/ns/ical/"/>
        <cal:supported-calendar-component-set/>
       </d:prop>
       <d:status>HTTP/1.1 404 Not Found</d:status>
      </d:propstat>
     </d:response>
    </d:multistatus>
    

    What I have observed is the following: when modifying an event in another client, sometimes after syncing through DAVdroid (1.3.1-gplay) that event disappears or is duplicated Android-side. (Then the duplicated event also disappeared. They do not return upon further syncs.)

    Many things have changed for me in the last two weeks: server, Baïkal version, DAVdroid version, so it is hard to know where to look. But the fact that I have no problems with the other clients makes me focus on DAVdroid for now. When looking at the SQLite database on my server, the events are there. I don't know where the Android side SQLite database is, so I haven't looked there yet.

    When doing a full sync, the specific etag value and resource (looks like <something>.ics) of an event that has disappeared does not appear in the logs; many (all non-disappeared?) others do.


  • developer

    Does this only happen for events more than 90 days in the past?

    Otherwise, we would required steps to reproduce because I can only have a look at the problem when I can reproduce it.



  • @rfc2822 said in DAVdroid loses or duplicates events on sync:

    Does this only happen for events more than 90 days in the past?

    No, this is about current events.

    Otherwise, we would required steps to reproduce because I can only have a look at the problem when I can reproduce it.

    I understand, I'll have a look at that.

    But in the mean time: the 404 error can already be ruled out as problematic?


  • developer

    But in the mean time: the 404 error can already be ruled out as problematic?

    It's not an error, it only a partial response meaning that the displayname etc. properties are not set for the requested resource.



  • @rfc2822 said in DAVdroid loses or duplicates events on sync:

    Otherwise, we would required steps to reproduce because I can only have a look at the problem when I can reproduce it.

    I already gave a description of what I did and what happened. As of yet, I cannot reliably reproduce the problem. I can, however, create a test account for you on my server if that would be useful. Let me know in that case how to provide you with the configuration details.

    N.B.: did you see my last edit of my original post (last paragraph)?


  • developer

    @equaeghe There was this similar report some time ago: https://forums.bitfire.at/topic/1186/duplicate-android-entries-on-read-only-calendars/

    Unfortunately, I was never able to reproduce the problem although I have tried several times. So I guess I won't be able to reproduce it with a test account, too, unless there were specific instructions.

    Maybe the best thing would be to enable verbose logs in DAVdroid and let them enabled until the problem has occured again. Then we can have a look at the logs.



  • @rfc2822 said in DAVdroid loses or duplicates events on sync:

    @equaeghe There was this similar report some time ago: https://forums.bitfire.at/topic/1186/duplicate-android-entries-on-read-only-calendars/

    I had a look. Although it seemed different, I also tried to sync my calendar with CalDAV Sync, and that worked without any problem, meaning that the events that disappeared with DAVdroid are present with CalDAV Sync. (BTW: I prefer DAVdroid because of its fully open source development process and Cal+Card combination, but I have a license to Gajda's apps from before DAVdroid's existence.)

    Maybe the best thing would be to enable verbose logs in DAVdroid and let them enabled until the problem has occured again. Then we can have a look at the logs.

    Ok, will do.



  • @rfc2822 said in DAVdroid loses or duplicates events on sync:

    Then we can have a look at the logs.

    It occurred again. There was a specific VEVENT I created titled ‘test4’ that disappeared. It had uri 1474447140.R225.ics and etag c181568b87831b825bcacce2e1794447 when last seen in the logs. I checked, and that event is still present in the database with the samen uri and etag.

    Preliminary excerpts of log files:

    Log file davdroid-14947-20160921-103248.txt:

    […]
    2016-09-21 10:39:15 12 [syncadapter.CalendarSyncManager] Adding 1474447140.R225.ics to local calendar
    […]
    

    Log file davdroid-29290-20160921-201304.txt:

    […]
    2016-09-21 20:42:46 8 [syncadapter.SyncManager] Found local resource: 1474447140.R225.ics
    [… 224 lines removed …]
    2016-09-21 20:42:46 8 [syncadapter.CalendarSyncManager] Found remote VEVENT: 1474447140.R225.ics
    […]
    

    Log file davdroid-7578-20160923-123541.txt:

    […]
    2016-09-23 14:35:50 7 [syncadapter.SyncManager] Found local resource: 1474447140.R225.ics
    [… 207 lines removed …]
    2016-09-23 14:35:50 7 [syncadapter.SyncManager] 1474447140.R225.ics is not on server anymore, deleting
    [… 21 lines removed …]
    2016-09-23 14:40:47 8 [syncadapter.SyncManager] I/O exception during sync, trying again later
    EXCEPTION javax.net.ssl.SSLHandshakeException: Handshake failed
    […]
    

    I do not know whether that exception afterwards may point to a problem before querying for the resource on the server. I did not spot any other strange things in the log. In any case, let me know how I should transfer a redacted copy of this last log file, as I assume it's the one you need.

    P.S.: In the log filename it would be more convenient for sorting purposes if the random(?) number came after the datetime instead of before it.


  • developer

    @equaeghe Please send all logs, most importantly the last one, to play@bitfire.at (OpenPGP key on our home page).


  • developer

    Thanks for the logs. Unfortunately, I can't see anything suspicious in them. Entries were removed because they weren't on the server anymore, and new entries have been added as expected …



  • @rfc2822 said in DAVdroid loses or duplicates events on sync:

    Thanks for the logs. Unfortunately, I can't see anything suspicious in them. Entries were removed because they weren't on the server anymore, and new entries have been added as expected …

    Well, as said three posts up, DAVdroid mistakenly assumes some entries where removed, while in reality they were not, as I verified by looking in the database (and by the fact that CalDAV Sync does not remove them). So something in the code used by DAVdroid to determine whether an entry is removed is triggering this. It may be a server bug or a DAVdroid bug. Given that CalDAV Sync does not exhibit this behavior may point to DAVdroid as the culprit.

    What about the exception I mentioned?


  • developer

    @equaeghe said in DAVdroid loses or duplicates events on sync:

    Well, as said three posts up, DAVdroid mistakenly assumes some entries where removed, while in reality they were not, as I verified by looking in the database

    DAVdroid doesn't query the whole database. It sends a REPORT calendar-query request with limited time range, for instance:

    <CAL:calendar-query xmlns="DAV:" xmlns:CAL="urn:ietf:params:xml:ns:caldav">
      <prop><getetag /></prop>
      <CAL:filter>
        <CAL:comp-filter name="VCALENDAR">
          <CAL:comp-filter name="VEVENT"><CAL:time-range start="20160923T143550Z" /></CAL:comp-filter>
        </CAL:comp-filter>
      </CAL:filter>
    </CAL:calendar-query>
    

    Let's have a look at one example of the removed events:

    2016-09-23 14:35:50 7 [syncadapter.SyncManager] 1474447140.R225.ics is not on server anymore, deleting
    

    So, what's the reason for DAVdroid assuming this:

    2016-09-23 14:35:50 7 [HttpClient$1] --> REPORT https://<domain name>/dav.php/calendars/<user name>/<calendar w>/ http/1.1
    2016-09-23 14:35:50 7 [HttpClient$1] Content-Type: application/xml; charset=utf-8
    2016-09-23 14:35:50 7 [HttpClient$1] Content-Length: 328
    2016-09-23 14:35:50 7 [HttpClient$1] Depth: 1
    2016-09-23 14:35:50 7 [HttpClient$1] 
    2016-09-23 14:35:50 7 [HttpClient$1] <?xml version='1.0' encoding='UTF-8' ?><CAL:calendar-query xmlns="DAV:" xmlns:CAL="urn:ietf:params:xml:ns:caldav"><prop><getetag /></prop><CAL:filter><CAL:comp-filter name="VCALENDAR"><CAL:comp-filter name="VEVENT"><CAL:time-range start="20160923T143550Z" /></CAL:comp-filter></CAL:comp-filter></CAL:filter></CAL:calendar-query>
    2016-09-23 14:35:50 7 [HttpClient$1] --> END REPORT (328-byte body)
    2016-09-23 14:35:50 7 [dav4android.BasicDigestAuthHandler] Adding Basic authorization header for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/
    2016-09-23 14:35:50 7 [HttpClient$1] <-- 207  https://<domain name>/dav.php/calendars/<user name>/<calendar w>/ (79ms)
    2016-09-23 14:35:50 7 [HttpClient$1] server: nginx/1.10.0 (Ubuntu)
    2016-09-23 14:35:50 7 [HttpClient$1] date: Fri, 23 Sep 2016 12:35:51 GMT
    2016-09-23 14:35:50 7 [HttpClient$1] content-type: application/xml; charset=utf-8
    2016-09-23 14:35:50 7 [HttpClient$1] expires: Thu, 19 Nov 1981 08:52:00 GMT
    2016-09-23 14:35:50 7 [HttpClient$1] cache-control: no-store, no-cache, must-revalidate
    2016-09-23 14:35:50 7 [HttpClient$1] pragma: no-cache
    2016-09-23 14:35:50 7 [HttpClient$1] x-sabre-version: 3.1.3
    2016-09-23 14:35:50 7 [HttpClient$1] vary: Brief,Prefer
    2016-09-23 14:35:50 7 [HttpClient$1] 
    2016-09-23 14:35:50 7 [HttpClient$1] <?xml version="1.0"?>
    <d:multistatus xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns" xmlns:cal="urn:ietf:params:xml:ns:caldav" xmlns:cs="http://calendarserver.org/ns/" xmlns:card="urn:ietf:params:xml:ns:carddav">
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/1462784390.R575.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;d62dd0b6fcbc5ece5123f69c57333ddc&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/1472217259.R754.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;e47664765463be92ed3cb71d2d95a8b3&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/1472217361.R13.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;a69a60e9c2712906466b474121a3eb12&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/1472217708.R617.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;3eec7f89ff5a90c65051e921a074d251&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/1472717349.R296.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;64de669e0ee844bd52f5653f9752116a&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/1473232121.R906.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;f3b695b57ce01fcbbfe93347b932277c&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/1474026589.R663.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;a9e54cdc04153090819ac28854496a7e&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/1474364111.R357.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;b66a1aebfd7dcfdff469e7d6bf761c71&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/3a85603870ec714885792150587de157dc0d34754b6f9b52feca71456569c8a2.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;1275051e858155acf5b848de90d886d5&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/3b39b53755eb037dde98d8ff6479bf95e52bd87c311ac382a91dad90c57d93f3.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;923beeb6903abebaef82c956e040d802&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/45475301cd2c0ab7e7364f89922d55443670edd7772459b37c40f68047f4bf17.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;af3b7eccec8fe4820abeec78a11a1638&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/55224e45e724a6ab824e943f6e3caa377881d39dd8d83d1a8ec0454abf9fbc4f.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;117eb934198e595c7102d63b53b383c3&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/600eecded1d8022b3e5095ec28f972fa8a9697bb6810473aead202597c107dfb.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;601ae760357e12b349bfd39a37bad450&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/dd3941c2b7a3a352300d1948cfd01362d68ad661f8d6c5b16408c7cb8ca04c1b.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;73a5c041c15a9e71d6cb6c3b537c96d7&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
     <d:response>
      <d:href>/dav.php/calendars/<user name>/<calendar w>/f82f8484df2f2dcd23b153cdff49288d406e181bd3702dc7f30a379c4254807c.ics</d:href>
      <d:propstat>
       <d:prop>
        <d:getetag>&quot;08de53da464fa99950e8903d470dfd77&quot;</d:getetag>
       </d:prop>
       <d:status>HTTP/1.1 200 OK</d:status>
      </d:propstat>
     </d:response>
    </d:multistatus>
    
    2016-09-23 14:35:50 7 [HttpClient$1] <-- END HTTP (4607-byte body)
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/1462784390.R575.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=d62dd0b6fcbc5ece5123f69c57333ddc)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/1472217259.R754.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=e47664765463be92ed3cb71d2d95a8b3)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/1472217361.R13.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=a69a60e9c2712906466b474121a3eb12)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/1472217708.R617.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=3eec7f89ff5a90c65051e921a074d251)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/1472717349.R296.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=64de669e0ee844bd52f5653f9752116a)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/1473232121.R906.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=f3b695b57ce01fcbbfe93347b932277c)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/1474026589.R663.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=a9e54cdc04153090819ac28854496a7e)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/1474364111.R357.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=b66a1aebfd7dcfdff469e7d6bf761c71)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/3a85603870ec714885792150587de157dc0d34754b6f9b52feca71456569c8a2.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=1275051e858155acf5b848de90d886d5)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/3b39b53755eb037dde98d8ff6479bf95e52bd87c311ac382a91dad90c57d93f3.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=923beeb6903abebaef82c956e040d802)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/45475301cd2c0ab7e7364f89922d55443670edd7772459b37c40f68047f4bf17.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=af3b7eccec8fe4820abeec78a11a1638)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/55224e45e724a6ab824e943f6e3caa377881d39dd8d83d1a8ec0454abf9fbc4f.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=117eb934198e595c7102d63b53b383c3)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/600eecded1d8022b3e5095ec28f972fa8a9697bb6810473aead202597c107dfb.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=601ae760357e12b349bfd39a37bad450)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/dd3941c2b7a3a352300d1948cfd01362d68ad661f8d6c5b16408c7cb8ca04c1b.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=73a5c041c15a9e71d6cb6c3b537c96d7)]
    2016-09-23 14:35:50 7 [dav4android.DavResource] Received <response> for https://<domain name>/dav.php/calendars/<user name>/<calendar w>/f82f8484df2f2dcd23b153cdff49288d406e181bd3702dc7f30a379c4254807c.ics
    	PARAMETER #1 = [getetag(DAV:): GetETag(eTag=08de53da464fa99950e8903d470dfd77)]
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 1473232121.R906.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 1472217361.R13.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: dd3941c2b7a3a352300d1948cfd01362d68ad661f8d6c5b16408c7cb8ca04c1b.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 55224e45e724a6ab824e943f6e3caa377881d39dd8d83d1a8ec0454abf9fbc4f.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 1474364111.R357.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: f82f8484df2f2dcd23b153cdff49288d406e181bd3702dc7f30a379c4254807c.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 1472717349.R296.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 1474026589.R663.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 45475301cd2c0ab7e7364f89922d55443670edd7772459b37c40f68047f4bf17.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 3a85603870ec714885792150587de157dc0d34754b6f9b52feca71456569c8a2.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 1472217259.R754.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 3b39b53755eb037dde98d8ff6479bf95e52bd87c311ac382a91dad90c57d93f3.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 1462784390.R575.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 600eecded1d8022b3e5095ec28f972fa8a9697bb6810473aead202597c107dfb.ics
    2016-09-23 14:35:50 7 [syncadapter.CalendarSyncManager] Found remote VEVENT: 1472217708.R617.ics
    

    DAVdroid queries all events since 20160923T143550Z. The server returns 207 (OK) and a list of events which is summarized at the end of above logs ("Found remote VEVENT"). There is no event 1474447140.R225.ics (please note that 1474447140.R225.ics isn't in the raw response, too, so it's not a parsing problem) → this event has to be removed locally.

    It's important that the "is not on server anymore, deleting" message doesn't mean that the event has been removed on the server, but that it's not within the queried time range anymore and thus should be removed locally.

    Can you try to disable the time range limit in DAVdroid? Of course this doesn't scale well, but it would be interesting whether the problem still occurs in this case.

    So something in the code used by DAVdroid to determine whether an entry is removed is triggering this. It may be a server bug or a DAVdroid bug.

    Or it's a feature and the events are really not within the queried time range, in which case they're correctly removed. Maybe it would be useful to get more information about the lost events: are they within time range (90 days by default, see DAVdroid account settings) or near the time range limit? Are they recurring events?

    However, all this information only applies to lost events and not duplicated ones, for which I don't have any idea yet.

    What about the exception I mentioned?

    It was related to thread #8 (the number after the date is the thread ID, while the PID is in the log file name), which seems to be an address book sync. Let's have a look at the logs of thread #8:

    2016-09-23 14:35:42 8 [syncadapter.SyncAdapterService$SyncAdapter] Sync for com.android.contacts has been initiated
    2016-09-23 14:35:42 8 [AccountSettings] Account <email address> has version 4, current version: 4
    2016-09-23 14:35:42 8 [AccountSettings] Account <email address> has version 4, current version: 4
    2016-09-23 14:35:42 8 [syncadapter.SyncManager] Preparing synchronization
    2016-09-23 14:35:42 8 [syncadapter.SyncManager] Querying capabilities
    2016-09-23 14:35:42 8 [HttpClient$1] --> PROPFIND https://<domain name>/dav.php/addressbooks/<user name>/default/ http/1.1
    2016-09-23 14:35:42 8 [HttpClient$1] Content-Type: application/xml; charset=utf-8
    2016-09-23 14:35:42 8 [HttpClient$1] Content-Length: 258
    2016-09-23 14:35:42 8 [HttpClient$1] Depth: 0
    2016-09-23 14:35:42 8 [HttpClient$1] 
    2016-09-23 14:35:42 8 [HttpClient$1] <?xml version='1.0' encoding='UTF-8' ?><propfind xmlns="DAV:" xmlns:CAL="urn:ietf:params:xml:ns:caldav" xmlns:CARD="urn:ietf:params:xml:ns:carddav"><prop><CARD:supported-address-data /><n0:getctag xmlns:n0="http://calendarserver.org/ns/" /></prop></propfind>
    2016-09-23 14:35:42 8 [HttpClient$1] --> END PROPFIND (258-byte body)
    2016-09-23 14:35:47 8 [cert4android.CustomCertManager] Certificate not trusted by system
    2016-09-23 14:35:47 8 [cert4android.CustomCertManager] Querying custom certificate trustworthiness
    2016-09-23 14:40:47 8 [HttpClient$1] <-- HTTP FAILED: javax.net.ssl.SSLHandshakeException: Handshake failed
    2016-09-23 14:40:47 8 [syncadapter.SyncManager] I/O exception during sync, trying again later
    EXCEPTION javax.net.ssl.SSLHandshakeException: Handshake failed
    	at com.android.org.conscrypt.OpenSSLSocketImpl.startHandshake(OpenSSLSocketImpl.java:390)
    	at okhttp3.internal.connection.RealConnection.connectTls(RealConnection.java:241)
    	at okhttp3.internal.connection.RealConnection.establishProtocol(RealConnection.java:198)
    	at okhttp3.internal.connection.RealConnection.buildConnection(RealConnection.java:174)
    […]
    	Suppressed: javax.net.ssl.SSLHandshakeException: Connection closed by peer
    		at com.android.org.conscrypt.NativeCrypto.SSL_do_handshake(Native Method)
    

    Seems there was a pending certificate decision which has not been answered within time, so the server has closed the connection in the meanwhile. It's only related to the address book sync, and it's a soft error, so the address book sync was re-scheduled and started again later.



  • @rfc2822 said in DAVdroid loses or duplicates events on sync:

    @equaeghe said in DAVdroid loses or duplicates events on sync:

    Well, as said three posts up, DAVdroid mistakenly assumes some entries where removed, while in reality they were not, as I verified by looking in the database

    DAVdroid doesn't query the whole database. It sends a REPORT calendar-query request with limited time range, [...]

    It's important that the "is not on server anymore, deleting" message doesn't mean that the event has been removed on the server, but that it's not within the queried time range anymore and thus should be removed locally.

    Can you try to disable the time range limit in DAVdroid? Of course this doesn't scale well, but it would be interesting whether the problem still occurs in this case.

    If I unset it, after resyncing, all events re-appear. So that was it, most likely, it was set to 0! I must have done that at some point (not very recently), but the very strange thing is that I didn't notice this before. I feel stupid for having bothered you about this, while it was a misconfiguration on my part. I am very sorry for the work this has caused you.

    So something in the code used by DAVdroid to determine whether an entry is removed is triggering this. It may be a server bug or a DAVdroid bug.

    Or it's a feature and the events are really not within the queried time range, in which case they're correctly removed. Maybe it would be useful to get more information about the lost events: are they within time range (90 days by default, see DAVdroid account settings) or near the time range limit? Are they recurring events?

    The recurring events that continue after the cut-off appeared also before the cut-off, which is logical, I guess, they correspond to one VEVENT.

    However, all this information only applies to lost events and not duplicated ones, for which I don't have any idea yet.

    Yes. That happened once, and the duplicate disappeared after a while. I'm now assuming that this duplication is something that was caused by the calendar app. In case it happens again, I'll report back in a new thread.

    What about the exception I mentioned?

    Seems there was a pending certificate decision which has not been answered within time, so the server has closed the connection in the meanwhile. It's only related to the address book sync, and it's a soft error, so the address book sync was re-scheduled and started again later.

    Thanks for the explanation.


  • developer

    @equaeghe Happy to hear that it now works for you. I recommend the default setting of 90 days into the past, which provides a good balance between availability of recent events and traffic/performance.


Log in to reply
 

Looks like your connection to Bitfire App Forums was lost, please wait while we try to reconnect.