Bad REPORT request

[idmyn]

Not sure how related this is to #16 or whether this is more of an issue with the etesync web client import feature but I figured I'd flag it up here.

I had imported a large (~1400 events) .ics file through the etesync web client (client.etesync.com) into a fresh calendar, and although it didn't throw up any errors at that stage, and appeared fine in the web client view, when trying to view the calendar in Calendar.app via etesync-dav the calendar appeared but without any events. Calendar.app gave the following error message:

Console output:

[700002bc5000] WARNING: Bad REPORT request on '/dmy@tuta.io/f8d2941c4aa242e53ad9c004041867553b90d64545b0ff3107c9bdfa20702de2/': Failed to filter item '02hkpnm2uhhh1tmrppnch1thus@google.com.ics' from 'dmy@tuta.io/f8d2941c4aa242e53ad9c004041867553b90d64545b0ff3107c9bdfa20702de2': Main component missing
WARNING:radicale:Bad REPORT request on '/dmy@tuta.io/f8d2941c4aa242e53ad9c004041867553b90d64545b0ff3107c9bdfa20702de2/': Failed to filter item '02hkpnm2uhhh1tmrppnch1thus@google.com.ics' from 'dmy@tuta.io/f8d2941c4aa242e53ad9c004041867553b90d64545b0ff3107c9bdfa20702de2': Main component missing
ERROR:root:No module named 'pytz'

(there were lots of 'pytz' errors above and below but I've only included one)

Notably, when I deleted the calendar through the etesync android app, made a new calendar, and imported the same file through the android app, I didn't have any trouble with etesync-dav.

[tasn]

Could you please try creating another calendar (a temporary one), import again through the web client, and see if it fails again? I wonder if it was a one time thing, or a consistent issue with the web client import.

I wonder if the problem is with the sheer size or with one of the entries. The import from the app is well tested with calendars of all sizes and a variety of odd events. The web import is newer so not as much.

[idmyn]

I've tried this again (with the same .ics file) and found very similar results. Calendar.app gave a near-identical error message, but reported server response of "500" instead of "400".

The console output (in addition to a "main component missing" error that looks very similar to what I reported the first time) included this (potentially helpful?) response:

[70000c6dc000] ERROR: An exception occurred during PROPFIND request on '/dmy@tuta.io/64658fa1644579c12c65286902aeb7a5dc558fa9458fc911a539755fdd570715/': 'VTIMEZONE components must contain a valid TZID'
ERROR:radicale:An exception occurred during PROPFIND request on '/dmy@tuta.io/64658fa1644579c12c65286902aeb7a5dc558fa9458fc911a539755fdd570715/': 'VTIMEZONE components must contain a valid TZID'

[tasn]

That's interesting. This error essentially means that you have a bad entry in your collection, so it actually didn't import things correctly. Could you maybe run etesync-dav -D and see if we get more useful information?

[idmyn]

Done. I've now got an output file with ~1000 lines! Any tips for what I should be looking for?

[tasn]

The above error. It should have a stack trace and potentially extra information (like the request sent/response built) around it.

[idmyn]

Makes sense, haha. Here's what my search brought up - any use?

[70000355c000] ERROR: An exception occurred during PROPFIND request on '/dmy@tuta.io/64658fa1644579c12c65286902aeb7a5dc558fa9458fc911a539755fdd570715/': 'VTIMEZONE components must contain a valid TZID'
Traceback (most recent call last):
  File "site-packages/radicale/__init__.py", line 332, in __call__
  File "site-packages/radicale/__init__.py", line 505, in _handle_request
  File "site-packages/radicale/__init__.py", line 813, in do_PROPFIND
  File "site-packages/radicale/xmlutils.py", line 812, in propfind
  File "site-packages/radicale/xmlutils.py", line 909, in _propfind_response
  File "site-packages/radicale_storage_etesync/__init__.py", line 144, in etag
  File "site-packages/vobject/base.py", line 254, in serialize
  File "site-packages/vobject/icalendar.py", line 1001, in serialize
  File "site-packages/vobject/behavior.py", line 85, in validate
  File "site-packages/vobject/base.py", line 124, in validate
  File "site-packages/vobject/icalendar.py", line 1069, in validate
vobject.base.ValidateError: 'VTIMEZONE components must contain a valid TZID'
ERROR:radicale:An exception occurred during PROPFIND request on '/dmy@tuta.io/64658fa1644579c12c65286902aeb7a5dc558fa9458fc911a539755fdd570715/': 'VTIMEZONE components must contain a valid TZID'
Traceback (most recent call last):
  File "site-packages/radicale/__init__.py", line 332, in __call__
  File "site-packages/radicale/__init__.py", line 505, in _handle_request
  File "site-packages/radicale/__init__.py", line 813, in do_PROPFIND
  File "site-packages/radicale/xmlutils.py", line 812, in propfind
  File "site-packages/radicale/xmlutils.py", line 909, in _propfind_response
  File "site-packages/radicale_storage_etesync/__init__.py", line 144, in etag
  File "site-packages/vobject/base.py", line 254, in serialize
  File "site-packages/vobject/icalendar.py", line 1001, in serialize
  File "site-packages/vobject/behavior.py", line 85, in validate
  File "site-packages/vobject/base.py", line 124, in validate
  File "site-packages/vobject/icalendar.py", line 1069, in validate
vobject.base.ValidateError: 'VTIMEZONE components must contain a valid TZID'

[tasn]

I was hoping we would get to see the actually broken event, though unfortunately it's not the case.

Maybe try adding print(self.etesync_item.content) in the beginning of the function etag just before the return in line 144 of site-packages/radicale_storage_etesync/__init__.py. That should add some more information.

[idmyn]

No such luck, debug output was the same. My def etag(self) function started at line 134 and returned at 136 (before I made the edit) - might that have something to do with it? There's also a def etag(self) at line 222, but I assumed line 134 would be the one you meant. The function I edited returns with get_etag(self.item.serialize())

[tasn]

It looks like you have multiple versions installed and you're editing the wrong one. I took line 144 directly from your backtrace from above:
File "site-packages/radicale_storage_etesync/__init__.py", line 144, in etag

[idmyn]

Ahh. I've tried running locate in terminal (and updating its database), but it only finds one file: /usr/local/lib/python3.7/site-packages/radicale_storage_etesync/__init__.py, which is the file I edited. I've checked the corresponding directories for other python versions but there no sign of radicale. Any ideas how I might find the correct file?

[tasn]

This path looks correct. One thing you can try is using strace (run strace python etesync-dav) and then try to find the correct file in the output. I'm sure there's a more python specific way, but I have no idea. :)

[anthonymvicente]

I believe I'm getting a similar issue when trying to setup a calendar with Evolution on Gnome. Here is part of the stacktrace I'm seeing

d8f0700] WARNING: Bad REPORT request on '/anthony@mvicente.com/14789637835a61b277a04da041c66dce442ab6218faf7ec20d3c2a1879657e58/': Failed to filter item 'bad5a739cff6cca418ed5283b5ad65fd676bf1515851ca2ba59929bee43ae604.ics' from 'anthony@mvicente.com/14789637835a61b277a04da041c66dce442ab6218faf7ec20d3c2a1879657e58': Overwritten recurrence with RRULESET
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/radicale/xmlutils.py", line 1270, in report
    if not all(match(item, filter_) for filter_ in filters):
  File "/usr/lib/python3.8/site-packages/radicale/xmlutils.py", line 1270, in <genexpr>
    if not all(match(item, filter_) for filter_ in filters):
  File "/usr/lib/python3.8/site-packages/radicale/xmlutils.py", line 1252, in match
    return _comp_match(item, filter_[0])
  File "/usr/lib/python3.8/site-packages/radicale/xmlutils.py", line 207, in _comp_match
    if not _comp_match(item, child, level=level + 1):
  File "/usr/lib/python3.8/site-packages/radicale/xmlutils.py", line 204, in _comp_match
    if not _time_range_match(item.item, filter_[0], tag):
  File "/usr/lib/python3.8/site-packages/radicale/xmlutils.py", line 279, in _time_range_match
    _visit_time_ranges(vobject_item, child_name, range_fn, infinity_fn)
  File "/usr/lib/python3.8/site-packages/radicale/xmlutils.py", line 337, in _visit_time_ranges
    for child, is_recurrence, recurrences in get_children(
  File "/usr/lib/python3.8/site-packages/radicale/xmlutils.py", line 325, in get_children
    raise ValueError("Overwritten recurrence with RRULESET")
ValueError: Overwritten recurrence with RRULESET

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/radicale/__init__.py", line 981, in do_REPORT
    status, xml_answer = xmlutils.report(
  File "/usr/lib/python3.8/site-packages/radicale/xmlutils.py", line 1273, in report
    raise ValueError("Failed to filter item %r from %r: %s" %
ValueError: Failed to filter item 'bad5a739cff6cca418ed5283b5ad65fd676bf1515851ca2ba59929bee43ae604.ics' from 'anthony@mvicente.com/14789637835a61b277a04da041c66dce442ab6218faf7ec20d3c2a1879657e58': Overwritten recurrence with RRULESET
[7f8fad8f0700] DEBUG: Response content:
Bad Request
[7f8fad8f0700] INFO: REPORT response status for '/anthony@mvicente.com/14789637835a61b277a04da041c66dce442ab6218faf7ec20d3c2a1879657e58/' with depth '1' in 6.204 seconds: 400 Bad Request

I'm also attaching the full debug session below in case that helps. I did notice another stacktrace at the beginning, when I would have been having Evolution discover the calendar for the first time.
etesync-dav.txt

[tasn]

Thanks @anthonymvicente. I don't think it's related, though I'll have to take a better look at it to be sure.

I'm also pretty sure I've seen this error before, though I don't remember what was the cause. Could you please open a new ticket for this issue and we can discuss it there? Thanks, and sorry for the slow reply.

[anthonymvicente]

@tasn Apologies, I was originally creating an issue, and this popped up as possibly related and I misdiagnosed it. I've created a new issue with my problem, thanks for letting me know!
#112

[tasn]

Nothing to be sorry about, and thanks a lot for reporting! I'll follow up with the other ticket next week (I'm at FOSDEM this weekend).