unknown error occurred in prepare_new_status

[vwegert]

I'm using vdirsyncer to mirror events from Google Calendar to a local storage (see config below). A few weeks ago, my installation of vdirsyncer suddenly started throwing error messages - without changes to the configuration and AFAIR also without changes to the installed versions. In the meantime, I performed a full upgrade in the hope that it would fix things - no such luck.

The problem only concerns one of the calendars I mirror. I've isolated that calendar in a new pair, removed all of the data except for tokens and config, ran the discovery and then an initial sync - this already results in the error. The abbreviated log is

Syncing mirror_NAME/NAME@gmail.com
debug: ====================
debug: REPORT https://apidata.googleusercontent.com/caldav/v2/NAME%40gmail.com/events/
...
debug: Normalized URL from '/caldav/v2/NAME%40gmail.com/events/qnitr7sqer05bgu5faluld07qc_R20230710%40google.com.ics' to '/caldav/v2/NAME@gmail.com/events/qnitr7sqer05bgu5faluld07qc_R20230710@google.com.ics'
...
debug: ====================
debug: REPORT https://apidata.googleusercontent.com/caldav/v2/NAME%40gmail.com/events/
debug: {'User-Agent': '997242834677-nminddka3d1pd395bsq09656rj8jbfif.apps.googleusercontent.com', 'Content-Type': 'application/xml; charset=UTF-8', 'Depth': '1', 'Authorization': 'Bearer ya29.a0AfB_byBu-eYx29h6_2c6CoO3aV-yB-9dQx8RFIdCeE9GYVY1CrWAaah0Lrn_7jJpy0xdHJuDpxDuWEH_WOWXs_53PG1ZWDfG18JP_X9YY2QHvA2K-nHM7ykcyTKZMDSBV0l0FJDhH5F8PyiLlcG01LUeRshzcOjQKbbq79QaCgYKAXASARMSFQHGX2Mi1A-yzwMw3WlCPr8qod46mA0174'}
debug: b'<?xml version="1.0" encoding="utf-8" ?>\n            <C:calendar-query xmlns="DAV:"\n                xmlns:C="urn:ietf:params:xml:ns:caldav">\n                <prop>\n                    <getcontenttype/>\n                    <getetag/>\n                </prop>\n                <C:filter>\n                \n                <C:comp-filter name="VCALENDAR">\n                    <C:comp-filter name="VEVENT">\n                        <C:time-range start="20230816T174201Z" end="20240212T174201Z"/>\n                    </C:comp-filter>\n                </C:comp-filter>\n                \n                </C:filter>\n            </C:calendar-query>'
debug: Sending request...
debug: 207
debug: <CIMultiDictProxy('Date': 'Tue, 14 Nov 2023 16:42:01 GMT', 'Pragma': 'no-cache', 'Cache-Control': 'no-cache, no-store, max-age=0, must-revalidate', 'Expires': 'Mon, 01 Jan 1990 00:00:00 GMT', 'Content-Type': 'text/xml; charset=UTF-8', 'Vary': 'Origin', 'Vary': 'X-Origin', 'Vary': 'Referer', 'Content-Encoding': 'gzip', 'Server': 'ESF', 'X-XSS-Protection': '0', 'X-Frame-Options': 'SAMEORIGIN', 'X-Content-Type-Options': 'nosniff', 'Alt-Svc': 'h3=":443"; ma=2592000,h3-29=":443"; ma=2592000', 'Transfer-Encoding': 'chunked')>
debug: <StreamReader 17930 bytes>
...
debug: Normalized URL from '/caldav/v2/NAME%40gmail.com/events/qnitr7sqer05bgu5faluld07qc%40google.com.ics' to '/caldav/v2/NAME@gmail.com/events/qnitr7sqer05bgu5faluld07qc@google.com.ics'
warning: Skipping identical href: '/caldav/v2/NAME@gmail.com/events/qnitr7sqer05bgu5faluld07qc@google.com.ics'
...
debug: Already normalized: '/caldav/v2/NAME@gmail.com/events/qnitr7sqer05bgu5faluld07qc@google.com.ics'
...
debug: Already normalized: '/caldav/v2/NAME@gmail.com/events/qnitr7sqer05bgu5faluld07qc_R20230710@google.com.ics'
...
debug: ====================
debug: REPORT https://apidata.googleusercontent.com/caldav/v2/NAME%40gmail.com/events/
...
debug: Already normalized: '/caldav/v2/NAME@gmail.com/events/qnitr7sqer05bgu5faluld07qc_R20230710@google.com.ics'
debug: Skipping '/caldav/v2/NAME@gmail.com/events/qnitr7sqer05bgu5faluld07qc_R20230710@google.com.ics', properties are missing.
debug: Already normalized: '/caldav/v2/NAME@gmail.com/events/qnitr7sqer05bgu5faluld07qc@google.com.ics'
debug: Skipping '/caldav/v2/NAME@gmail.com/events/qnitr7sqer05bgu5faluld07qc@google.com.ics', properties are missing.
error: Unknown error occurred for mirror_NAME/NAME@gmail.com: /caldav/v2/NAME@gmail.com/events/qnitr7sqer05bgu5faluld07qc@google.com.ics
error: Use `-vdebug` to see the full traceback.
debug:   File "/usr/lib/python3.11/site-packages/vdirsyncer/cli/tasks.py", line 72, in sync_collection
debug:     await sync.sync(
debug:   File "/usr/lib/python3.11/site-packages/vdirsyncer/sync/__init__.py", line 146, in sync
debug:     a_nonempty = await a_info.prepare_new_status()
debug:                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
debug:   File "/usr/lib/python3.11/site-packages/vdirsyncer/sync/__init__.py", line 66, in prepare_new_status
debug:     async for href, item, etag in self.storage.get_multi(prefetch):
debug:   File "/usr/lib/python3.11/site-packages/vdirsyncer/storage/dav.py", line 556, in get_multi
debug:     raise exceptions.NotFoundError(href)

I've tried to identify the entries causing the trouble using https://developers.google.com/calendar/api/v3/reference/events/get - these are the responses I'm seeing:

{
 "kind": "calendar#event",
 "etag": "\"3389037076879000\"",
 "id": "qnitr7sqer05bgu5faluld07qc",
 "status": "cancelled",
 "htmlLink": "https://www.google.com/calendar/event?...",
 "updated": "2023-11-14T16:04:02.191Z",
 "start": {
  "date": "2023-05-27"
 },
 "end": {
  "date": "2023-05-28"
 },
 "recurrence": [
  "RRULE:FREQ=DAILY;UNTIL=20230709;INTERVAL=2"
 ],
 "transparency": "transparent",
 "iCalUID": "qnitr7sqer05bgu5faluld07qc@google.com"
}

and

{
 "kind": "calendar#event",
 "etag": "\"3389036654314000\"",
 "id": "qnitr7sqer05bgu5faluld07qc_R20230710",
 "status": "cancelled",
 "htmlLink": "https://www.google.com/calendar/event?...",
 "updated": "2023-11-14T16:04:02.191Z",
 "start": {
  "date": "2023-07-10"
 },
 "end": {
  "date": "2023-07-11"
 },
 "recurrence": [
  "RRULE:FREQ=DAILY;INTERVAL=2"
 ],
 "transparency": "transparent",
 "iCalUID": "qnitr7sqer05bgu5faluld07qc_R20230710@google.com"
}

I can't find entries in the calendar matching these dates - not surprising since they are cancelled. I can't find anything in the recycle bin either.

• Your vdirsyncer version
  vdirsyncer, version 0.19.2
• If applicable, which server software (and which version) you're using
  Syncing Google calendar to local file
• Your Python version
  Python 3.11.5
• Your operating system
  Gentoo Linux
• Your config file

[general]
status_path = "~/.vdirsyncer/status/"

[pair mirror_NAME]
a = "google_cal"
b = "local_cal"
collections = [ "NAME@gmail.com" ]
conflict_resolution = "a wins"
partial_sync = "ignore"

[storage google_cal]
type = "google_calendar"
token_file = "~/.vdirsyncer/tokens/google_cal_volker"
client_id = "CLIENT_ID"
client_secret = "CLIENT_SECRET"
start_date = "datetime.now() - timedelta(days=90)"
end_date   = "datetime.now() + timedelta(days=90)"
read_only  = true

[storage local_cal]
type = "singlefile"
path = "~/public_html/%s.ics"

[WhyNotHugo]

The error message indicates that no events are returned by google when requesting items with those UIDs.

Your configuration rule syncs items in the last 90 days. The first one repeated daily until more than 90 days ago, so it doesn't fit the criteria. I don't think that it should even have been listed when listing events in the first place.

[vwegert]

@WhyNotHugo That sounds plausible. In this case, the root cause would be a buggy server implementation that I can't do anything about... Is there a way to let vdirsyncer ignore such events (or rather treat them as non-existent and remove them from the local storage) rather than aborting the sync altogether?

[vwegert]

I have temporarily fixed this by applying the following patch:

diff --git a/vdirsyncer/storage/dav.py b/vdirsyncer/storage/dav.py
index 697ebf0..c12cab2 100644
--- a/vdirsyncer/storage/dav.py
+++ b/vdirsyncer/storage/dav.py
@@ -550,7 +550,8 @@ class DAVStorage(Storage):
                 else:
                     rv.append((href, Item(raw), etag))
             for href in hrefs_left:
-                raise exceptions.NotFoundError(href)
+                dav_logger.warning(f"Server did not supply properties for {href}")
+#               raise exceptions.NotFoundError(href)
 
             for href, item, etag in rv:
                 yield href, item, etag

This is quite similar to the change proposed with #866, so it would be really great to get the PR merged...