Duplicate events in inbox file, with and without ID

[promisedlandt]

Hello,

I'm using org-caldav to sync from my calendar to org. Config without server settings:

(setq org-caldav-sync-direction 'cal->org)
(setq org-caldav-show-sync-results nil)
(setq org-caldav-save-directory nl/instance-state-base)
(setq org-caldav-backup-file (concat nl/instance-state-base "org-caldav-backup.org"))
(setq org-caldav-delete-calendar-entries 'never)
(setq org-caldav-delete-org-entries 'always)
(setq org-caldav-resume-aborted 'never)

Issue: I have an appointment for 2023-01-17 in my calendar. This was synched to my inbox file 1429 times. 22 of those entries have the same ID, the other 1407 appear to have an empy properties drawer and no tag set.

The same issue affects other calendar entries as well, but newly created ones are fine. There is an old org-caldav-backup.org file from 2023-01-13 that does not have these entries, and I noticed the issue on 2023-01-16, so I'm guessing whatever went wrong happened somewhere in these last days, but since I had no appointments on the weekend I didn't notice it. That also means that the debug-buffer and sync state look perfectly normal.

Pure guesswork: there were aborted sync attempts (no idea why), which were not resumed as per my config, but they still left entries in my inbox. This would be unexpected behaviour for me - if a sync is aborted, there still should not be entries with duplicate IDs, and entries without any ID at all shouldn't be in the inbox, right?

Do you have any ideas?

I'm using the latest commit (cc1f16b8a4112aee63a0b9e3d7b38140f2b57686), but encountered the issue ~mid last year as well. Back then I just deleted the local org-caldav stuff and re-synched.

[jackkamm]

Not sure what might be causing this.

Recommend to increase verbosity with (setq org-caldav-debug-level 2) and see if there are any clues.

Also, I recommend to check the database file, named like ~/.emacs.d/org-caldav-XXXXX.el. See if you can find the problem event in org-caldav-event-list.

Pure guesswork: there were aborted sync attempts (no idea why), which were not resumed as per my config, but they still left entries in my inbox.

I think your hypothesis is possible. For example, in org-caldav-sync-calendar, we first call org-caldav-update-eventdb-from-cal to update the eventdb, then org-caldav-update-events-in-org to insert into the Org file, then finally org-caldav-save-sync-state to save the eventdb to file. Possibly, something goes wrong during insertion, or just after insertion before the eventdb is saved.

if a sync is aborted, there still should not be entries with duplicate IDs, and entries without any ID at all shouldn't be in the inbox, right

We do have some exception handling, but the coverage might not be perfect, and also if an error occurs after insertion, no cleanup happens to remove already-inserted entries.

[promisedlandt]

I set (setq org-caldav-debug-level 2) and the issue occurred again, but org-caldav-event-list looks perfectly normal. Do I need to also not set org-caldav-show-sync-results to nil, or did I check in the wrong place (the echo area)?

[jackkamm]

Debug output is written to a separate buffer, named something like *org-caldav-debug*.

I don't think org-caldav-show-sync-results affects it, but it might still be helpful to set it, as the sync output might also give additional clues.

[promisedlandt]

It took a while, but it happened now. I also have another idea of what might happen. I'm not calling org-caldav-sync manually, I'm using a function when emacs is idle, which I found here. My guess is that the caldav sync is not cleaning up for some reason, and since the sync is called automatically, there are 36 duplicates of the event, even if the caldav sync only leaves one duplicate. But I'm not sure.

Anyway, what happened today: I created an event called "Bb" at ~09:53 local time, and tried to sync at ~18:30 local time.

Error message in the org caldav sync result buffer:

CalDAV Sync finished.

== Sync errors: 

UID: 406560c3-24cf-430a-905d-1a74cc57c637.1677142401137
   Title: Bb
   Status: error  Action: error:inbox-notfound
   Calendar: Y2FsOi8vMC8zMQ

== Successful syncs: 

None.

The debug log is 4k lines, so I've put it in a gist (I have censored the calendar ID): https://gist.github.com/promisedlandt/b32a05ceacab3d4243312b358ffdb66f

[jackkamm]

Thanks, the debug log is helpful.

I think the offending event is actually a different one, 4fc20097-02a9-41ae-a641-0b3f1349dcd2.1677142492075.

While something is indeed going wrong with the "Bb" event, org-caldav manages to catch that error and proceed to the next event.

However the debug log shows that the sync always cuts off right after trying to fetch the next event:

Getting event UID 4fc20097-02a9-41ae-a641-0b3f1349dcd2.1677142492075.

I think some error must be happening at this point that org-caldav doesn't catch, causing the org-caldav-sync function to exit abruptly, without performing the final cleanup (org-caldav-save-sync-state).

You can try checking the *Messages* buffer to see if any error message is there. Also, you can try calling toggle-debug-on-error before calling org-caldav-sync, so that Emacs will enter the debugger and we can see where the error happens.

[promisedlandt]

The error still happens, but infrequently, and I wasn't diligent about checking the messages before quitting Emacs. I have debug on error enabled globally, but the debugger did not open. Manually calling org-caldav-sync after the issue occured worked completely fine, and had different output compared to the sync with issues (with issues: file was written after all events were synced, without issues: file was written after every single event).

This is a gist with the output of the Messages buffer, the first file is after the manual sync without issues, the second file is after the sync with issues:

https://gist.github.com/promisedlandt/3bfa0127a7bad4edb45231accb818736

[jackkamm]

The timing of the file saves is an interesting clue.

This comment might be related: https://github.com/dengste/org-caldav/issues/273#issuecomment-1536472670

We probably need to add another file save at some point during the sync, but need to track down where.

You can try adding (org-save-all-org-buffers) after sync in your timer, I would be interested to know if it makes the issue go away.

[promisedlandt]

I added a save function to the timer as you suggested, and the issue did not occur in the 3 weeks since. So this seems fixed for me!

We probably need to add another file save at some point during the sync, but need to track down where.

I'm not good with elisp, but if you prepare a branch (or tell me where to add what), I'll happily trial possible solutions.

[jackkamm]

I believe I fixed the problem in the latest commit and have closed the issue. Please re-open if you experience the problem again after updating.

[promisedlandt]

I have updated to the newest version and removed my own save function. Thanks for the fix!

[promisedlandt]

Unfortunately, 43fba8b59ff89903d1313c3343722160b7d5ff8b did not fix the issue. I removed my inbox file and org-caldav-bb for a fresh start. Below are some examples:

org-caldav log:

UID: 026ce32d4298421764270505ead1d406@overture
   Title: Ostern (Stille Tage)
   Status: new-in-cal  Action: cal->org

org-caldav-inbox_mailbox_private.org (entry appears 62 times, all with the same ID):

* Ostern (Stille Tage)                                             :calendar:
:PROPERTIES:
:ID:       026ce32d4298421764270505ead1d406@overture
:END:
<2022-04-17 Sun>

Additionally, there are some other caldav events with and without ID.

org-caldav log:

org-caldav-inbox_mailbox_private.org (entries are not located directly adjacent in the file):

* Opera
* Opera                                                            :calendar:
:PROPERTIES:
:ID:       909334bf-5b11-4889-aacd-a9db06861a75.1682761924062
:END:
<2023-05-03 Wed 12:00-13:00>