events sometimes deleted on device soon after adding/changing



  • Sometimes, after adding (or modifying) calendar event, with DAVDroid 1.10.1.1-ose it gets removed from devices seconds or minutes later. Interesting thing is, (at least sometimes) calendar entries remain to be accessible via owncloud web interface, but are still deleted from android device calendar. If sync is disabled on devices, problem doesn't happen and events are never removed (as expected).

    For example, on 2018-03-15 at 11:35am. Server is debian-packaged owncloud 7.0.13~dfsg-1 on apache 2.4.10-10+deb8u11 (I know, not supported anymore). One or two new events were added on device, and seconds later they disappear.

    apache server logs don't seem to show the error:
    https://paste.fedoraproject.org/paste/O0p~sQbliHwby6A7G4fxIw
    (in owncloud logs nothing for that timeperiod)

    Davdroid debug:
    https://paste.fedoraproject.org/paste/DMDjE4CKo9KGRx7q4e200A

    Logcat:
    https://paste.fedoraproject.org/paste/BgP-xEkqFiBySnjsT1wJ4A

    apart from Davdroid complaining that KeyStore.bks is missing, this seems to be relevant part:

    [resource.LocalCalendar] Processing dirty exceptions  
    [syncadapter.SyncManager] Uploading dirty entries     
    [syncadapter.SyncManager] Uploading locally modified record 55c54fe2-dca2-4453-9974-daf0b37851a8.ics
    [syncadapter.SyncManager] Uploading locally modified record 71bf14a9-532a-4f12-92c6-113273ee3088.ics
    [syncadapter.SyncManager] Uploading new record fa2774ea-b812-4982-a6e2-ca89b84c25d8.ics
    [syncadapter.SyncManager] Uploading new record ad5e98c1-d3ff-4f71-9f1d-477283f9abc6.ics
    [syncadapter.SyncManager] Checking sync state
    [syncadapter.SyncManager] Listing local resources
    [syncadapter.SyncManager] Found 7 local resources
    [syncadapter.SyncManager] Listing remote resources
    [syncadapter.SyncManager] Comparing local/remote entries
    [syncadapter.SyncManager] 55c54fe2-dca2-4453-9974-daf0b37851a8.ics is not on server anymore, deleting
    [syncadapter.SyncManager] fa2774ea-b812-4982-a6e2-ca89b84c25d8.ics has been changed on server (current ETag=8fea78a6da42689633fce5393ae3a74a, last known ETag=null)
    [syncadapter.SyncManager] 71bf14a9-532a-4f12-92c6-113273ee3088.ics is not on server anymore, deleting
    [syncadapter.SyncManager] ad5e98c1-d3ff-4f71-9f1d-477283f9abc6.ics has been changed on server (current ETag=0e24306c77711012ab357e7dee0c413e, last known ETag=null)
    [syncadapter.SyncManager] Downloading remote entries
    [syncadapter.CalendarSyncManager] Downloading 2 events (20 at once)
    [syncadapter.CalendarSyncManager] Downloading https://owncloud.example.voyager.hr/owncloud/remote.php/caldav/calendars/mnalis/sastanci/fa2774ea-b812-4982-a6e2-ca89b84c25d8.ics, https://owncloud.example.voyager.hr/owncloud/
    [syncadapter.CalendarSyncManager] Updating fa2774ea-b812-4982-a6e2-ca89b84c25d8.ics in local calendar
    [syncadapter.CalendarSyncManager] Updating ad5e98c1-d3ff-4f71-9f1d-477283f9abc6.ics in local calendar
    [syncadapter.SyncManager] Post-processing
    [syncadapter.SyncManager] Saving sync state
    [syncadapter.SyncManager] Saving CTag=3160 
    
    

    I'm planing on upgrading server (and probably getting rid of owncloud in favor of something else supported in Debian like radicale) some time in the future; but there is no guarantee that the problem won't be happening again there (if it is device/davdroid related instead of server/owncloud related).

    So, few questions:

    • anything obvious what is going on and if it could be fixed (or further debugged) by me?

    • could DAVdroid be modified to detect such condition (entries disappear in same session when they were uploaded) and such silent deletions replaced (or at least accompanied) by warning notification?

    • alternatively, could DAVdroid be set to do one-way sync only (as a means of backup -- eg. choice between two-way sync / only uploading changes to server / only downloading from server)


  • developer

    Hello,

    I don't see anything unexpected in the logs, so I'm not sure that I understand the problem. Can you please provide exact steps to reproduce the problem (including expected and actual results)?



  • Problem happens sporadically (few times a month), so I'm unfortunately unable to provide efficient trigger. It might be that staying a little longer (like 30-90 seconds) in "edit event" window makes it more likely to trigger, or it may be that adding/editing several events in short time makes it happen; but those are just subjective guesses.

    It usually happens like this:

    • wifi is available, and sync is enabled.
    • I add "event A" in today's calendar
    • I add "event B" in today's calendar
    • I add "event C" in today's calendar
    • I add "event D" in today's calendar
    • I modify "event B" in today's calendar
    • for a while, latest version of all 4 events are visible in calendar on device.
    • After few seconds (or minutes) however, "event B", "event C" and "event D" (or maybe some other combination with more of less events) disappear from android device calendar (leaving it with just event "A" for example).

    Expected result is that I have latest version of all 4 events in calendar on android device.
    Actual result is that several events (let's say 3 of them in example above) get silently deleted, and only one remains.

    That is how it happened in report above - I've been adding (and editing) several events (not deleting any of them!) and suddenly several of them get deleted (without my intervention) from calendar app.

    What can I do to provide more helpful debug next time it happens (as I seem to be unable to trigger it at will)?

    (also update to original post: it seems that calendar entries that got deleted on android device but that did remain visible in owncloud web interface on server only did so for some amount of time; and that [perhaps on next schedules davdroid sync few hours later?] they got deleted from owncloud web interface too).


  • developer

    Thanks for the additional details. Unfortunately, I don't have an idea what's wrong.

    What can I do to provide more helpful debug next time it happens (as I seem to be unable to trigger it at will)?

    I suggest to enable verbose logs in DAVdroid and let them active until the problem occurs. Then disable the logs again and analyze the latest syncs.



  • Hi there !
    Same problem for me, with the last version of davdroid-ose (but pretty sure it was the same with the previous one).
    It's synchonized with a SOGo service. 2 calendars with a lot of events (more than 500 for each one).
    It was ok during 6 months, but since 2 or 3 weeks, I discovered some events displayed on SOGo and on my mac are not on the Android device.
    It seems events around May but I'm not sure if it's because of the month or the creation date of event.
    The typical case : I try to create an event in May from Samsung Calendar (the same result with another Android app). The event disappears from Android Calendar after creating. But I can see it on iCal and SOGo.

    I don't have any SD card for the moment so I can't export the verbose log.



  • Ok, I've managed to reproduce it with verbose external logging.

    The problem happens at 2018-03-28 at about 12:37 CEST. I had moved one event "test jakna žuta" from 2018-03-28 to 2018-03-29, and then began entering several events for 2018-03-28 (which is "today" at the time) (in IIRC probably not chronological order), namely:

        12h-13h Vijci kranjec
        13h-14h doktorica uputnica
        14h-15h Vrbani mjeri podnice
        15h-16h Tuš
    

    then after adding one of them, at about 12:37 +- 1 min something happens, and calendar on android phone suddenly shows only:

        14h-15h Vrbani mjeri podnice
        15h-16h Tuš
    

    the other two events silently disappear from device. I disable wifi and data on android phone, and visit owncloud instance from notebook web interface, and I can still see all 4 events in Calendar there...

    apache logs: https://paste.fedoraproject.org/paste/liO49A2Ik9NkQpL6PU842w

    ownclouds log probably irrelevant, but since it is not timestamped I cannot tell, so including it too:
    https://paste.fedoraproject.org/paste/RW2pXvolzBUwDrmKEah9CA

    detailed davdroid log davdroid-12051-20180328-123600.txt: https://paste.fedoraproject.org/paste/yBTUQCKnVizHhkxjuUJPvg

    detailed davdroid log davdroid-12012-20180328-123559.txt: https://paste.fedoraproject.org/paste/oZusL1X45OMiyFsa1Tg2WQ

    hopefully they will shed some light into the situation...

    Thanks!


  • developer

    @mnalis For instance "12h-13h Vijci kranjec":

    1. DAVdroid seen the locally created event
    2018-03-28 12:37:02 5 [syncadapter.SyncManager] Found local record #6653 without file name; generating file name/UID if necessary
    2018-03-28 12:37:02 5 [AndroidEvent] Read event entity from calender provider
    	PARAMETER #0 = availability=0 dtstart=1522231200000 lastSynced=0 accessLevel=0 eventTimezone=Europe/Zagreb _sync_id=1f8bca5b-7c29-4a5b-ba41-fb72878b8f3e.ics hasAttendeeData=1 allDay=0 dtend=1522234800000 eventStatus=1 _id=6653 uid2445=1f8bca5b-7c29-4a5b-ba41-fb72878b8f3e guestsCanModify=0 dirty=1 guestsCanInviteOthers=1 lastDate=1522234800000 cal_sync1=3206 guestsCanSeeGuests=1 selfAttendeeStatus=0 mutators=com.android.calendar hasExtendedProperties=0 organizer=mnalis-owncloud@voyager.hr eventColor_index= title=Vijci kranjec calendar_id=6 deleted=0 hasAlarm=1 isOrganizer=1
    
    1. DAVdroid successfully uploads the event as 1f8bca5b-7c29-4a5b-ba41-fb72878b8f3e.ics.
    2018-03-28 12:37:06 5 [HttpClient] --> PUT https://owncloud.example.voyager.hr/owncloud/remote.php/caldav/calendars/mnalis/sastanci/1f8bca5b-7c29-4a5b-ba41-fb72878b8f3e.ics
    2018-03-28 12:37:06 5 [HttpClient] Content-Type: text/calendar;charset=utf-8
    2018-03-28 12:37:06 5 [HttpClient] Content-Length: 1805
    2018-03-28 12:37:06 5 [HttpClient] If-None-Match: *
    2018-03-28 12:37:06 5 [HttpClient] 
    2018-03-28 12:37:06 5 [HttpClient] BEGIN:VCALENDAR
    VERSION:2.0
    PRODID:+//IDN bitfire.at//DAVdroid/1.10.1.1-ose ical4j/2.x
    BEGIN:VEVENT
    DTSTAMP:20180328T103704Z
    UID:1f8bca5b-7c29-4a5b-ba41-fb72878b8f3e
    SUMMARY:Vijci kranjec
    DTSTART;TZID=Europe/Zagreb:20180328T120000
    DTEND;TZID=Europe/Zagreb:20180328T130000
    …
    2018-03-28 12:37:06 5 [HttpClient] <-- 201 Created https://owncloud.example.voyager.hr/owncloud/remote.php/caldav/calendars/mnalis/sastanci/1f8bca5b-7c29-4a5b-ba41-fb72878b8f3e.ics (199ms)
    
    1. At the next sync, the server doesn't list it anymore when DAVdroid requests all events since 20180328T123708Z:
    2018-03-28 12:37:08 5 [HttpClient] --> REPORT https://owncloud.example.voyager.hr/owncloud/remote.php/caldav/calendars/mnalis/sastanci/
    2018-03-28 12:37:08 5 [HttpClient] Content-Type: application/xml; charset=utf-8
    2018-03-28 12:37:08 5 [HttpClient] Content-Length: 328
    2018-03-28 12:37:08 5 [HttpClient] Depth: 1
    2018-03-28 12:37:08 5 [HttpClient] 
    2018-03-28 12:37:08 5 [HttpClient] <?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="20180328T123708Z" /></CAL:comp-filter></CAL:comp-filter></CAL:filter></CAL:calendar-query>
    2018-03-28 12:37:08 5 [HttpClient] --> END REPORT (328-byte body)
    
    1. … so DAVdroid locally deletes the event.

    So it seems like you have set the "past time event limit" of this DAVdroid account to "0", which means that only events since the sync time will be synced (and past events will be dismissed).

    Does it work when you set the past time event limit to, for instance, 90 days (default value)?

    Edit: I see the DAVdroid queries for events since 20180328 12:37 UTC, although it's 12:37 local time. So this might be confusing because some today events might be removed when the past time event limit is 0, which is actually happening here. This should be fixed by https://gitlab.com/bitfireAT/dav4android/commit/869e7cd26278e28435f6261784560066ffba6f5f so that DAVdroid converts the local time to UTC when quering the events. However, setting the past time event limit to a higher value (1 day, 30 days, whatever) should always work.



  • Thanks!! It was indeed set to "0". Which is strange, as I distinctly remember setting it to "sync all events" when that feature came about (as I want old events that I delete on phone or web automatically propagate to the other side, even it they were a year or few ago...)

    Could it be that some upgrade or reinstallation of DAVdroid reset that empty string to "0" ?

    On related note, should "0" even be allowed as value, as in best case it will only make a sync a very little faster than "1", but could have potentially disastrous results when changing timezones (manually, or automatically, or different TZ settings in server/client side [for example when country changes its timezone defs]) etc?

    I've now set it to "90" as you recommend, but if it is safe I would like to make it empty string again. I've never had problems back in the days when it always synced all events, and I'd like for it to keep working the way I'm used to.

    I'll leave debug on for some time in case problem reappears.

    Thanks again for helping (and for writing this great piece of free software!)


  • developer

    @mnalis said in events sometimes deleted on device soon after adding/changing:

    Could it be that some upgrade or reinstallation of DAVdroid reset that empty string to "0" ?

    Maybe. It should not be the case, but I'd have to investigate before and I don't think that's worth it.

    On related note, should "0" even be allowed as value, as in best case it will only make a sync a very little faster than "1", but could have potentially disastrous results when changing timezones (manually, or automatically, or different TZ settings in server/client side [for example when country changes its timezone defs]) etc?

    The worst thing that can happen is that some events of today are not shown on the Android device. Since the fix I have linked in my previous post, "0" actually means "now" and not "the current hour/minute, but in UTC" like before. So "0" should now (= in future DAVdroid versions) work as expected (= all events since the exact time of synchronization), but personally I'd never use 0. Syncing a few days, weeks, even months into the past doesn't have an impact on the performance and allows you to look up recent events in the calendar.

    I've now set it to "90" as you recommend, but if it is safe I would like to make it empty string again. I've never had problems back in the days when it always synced all events, and I'd like for it to keep working the way I'm used to.

    The problem is that the empty value doesn't scale at the moment, because it does a simple PROPFIND for all events. So if you have 100.000 events over 10 years, every sync lists 100.000 events. However, WebDAV collection sync (RFC 6578) is planned for DAVdroid 1.12. We will soon release DAVdroid 1.11 which contains preparations for this feature. With WebDAV collection sync, you can use the empty value without performance impact.