etesync / server

The Etebase server (so you can run your own)
https://www.etesync.com
GNU Affero General Public License v3.0
1.55k stars 76 forks source link

malformed input vcard file causes unrecoverable error with no AIs for user #111

Open jzacsh opened 2 years ago

jzacsh commented 2 years ago

tl;dr user-input shouldn't cause crash, it should be reject (or a graceful way out should be offered, if it's not rejected).

warning: I'm not sure where this issue should live - I'm hopping around etesync codebases at this point, so "server" seems like a generic enough home...

feedback/bug report

(All of the "actual" descriptions have a corresponding screenshot/inlined pastie below.)

Two things I think could be better:

symptoms

Early on when setting up etesync, I believe my import from 6 months ago apparently had some bad record that I must've been allowed to ignore. Lately I've noticed the pim webapp has a little red error icon, though (screenshot below).

Then much later downstream when I'm setting up DAV sync, I eventually hit the same(?) error. I think it's the same - all I have is symptoms to share right now, no proof:

Here's a screenshot of all the errors and a text transcription of what's shown here's a screenshot where you can see all the information I have to go on; summarizing the screenshot: 1. **middle of screen in `pim` webapp**: _some_ contact imported (months and months ago) from Google Contacts is producing the import error - **feedback**: there's nothing call to action here here. That is: there's no indication of how to find the supposedly bad contact data that triggered this exception. That is: how should one fix this? Find the corresponding etesync data and hand-edit it? Delete all my etesync account data and re-import (I hope not)?, etc. 2. **top of screen in tbsync**: you can see tbsync fails I'm _entirely guessing_ due to the above error - the only other log I have to go on from tbsync is the next bits of info (2.a) and (3)... - **rightside of screen** eventlog from this thunderbird add on says: ``` URL: http://localhost:37358/MYUSER/SOME_OPAQUE_HASH/ (PROPFIND) Request: Response: A server error occurred. Please contact the administrator. ``` 3. **bottom of screen in `journalctl --pager-end --catalog --follow --user status etesync-dav.service` output**: I get ``` Nov 28 16:36:31 mymachine etesync-dav[843]: [2021-11-28 16:36:31 -0600] [843/Thread-448] [ERROR] An exception occurred during PROPFIND request on '/MYUSER/SOME_OPAQUE_HASH/': Failed to parse item 'SECOND_OPAQUE_HASH.vcf' in 'MYUSER/SOME_OPAQUE_HASH' Nov 28 16:37:28 mymachine etesync-dav[843]: [2021-11-28 16:37:28 -0600] [843/Thread-456] [ERROR] An exception occurred during GET request on '/MYUSER/SOME_OPAQUE_HASH/': Failed to serialize item 'THIRD_OPAQUE_HASH.vcf' from 'MYUSER/SOME_OPAQUE_HASH': 'VCARD components must contain at least 1 FN' ``` ![Screenshot from 2021-11-28 16-41-04](https://user-images.githubusercontent.com/156228/143790702-bfd06787-676c-4b0c-baae-2a149fbfba36.png)
jzacsh commented 2 years ago

once I've managed to figure out how to hand-fix this particular error I'm really running into (separately - perhaps I'll try to catch folks in matrix chat) I'll come back here and try to propose a generic solution (eg once I've dug through the importer logic, I'm sure proposal no.1 above will be the fastest)

jzacsh commented 2 years ago

Huh, interestingly on the point of feedback (B) above -- giving user a way to recover -- I don't see a way yet, even though I've identified the bad data.

Here's what I've done;

  1. gone back to my Google account and re-exported a single large VCF file
  2. grepd the file for the text shown in etesync's pim... web ui --> found it on line 4300 --> identified the contact the data belongs to
  3. opened etesync web ui
  4. searched for said contact name
  5. no results :(

expected: step 5 should've had bad contact ("Marco") to show up actual: no matches... so either:

jzacsh commented 2 years ago

mini-update: -D flag, per etesync-dav readme luckily means I can easily use my existing install - via systemctl that: systemctl --full --user edit etesync-dav.service (and then modify the Exec line to have a -D at the end).

I'm able to confirm that the error that the web UI is showing is the exact same parse error causing a "full-stop"[1] on contacts sync.

full stracktrace of the above error ``` $ journalctl -xef --user-unit etesync-dav.service | grep -C 90 -E 'Failed.to.parse' Dec 01 20:51:10 mymachine etesync-dav[105099]: Traceback (most recent call last): Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/etesync_dav/radicale/storage_etebase_collection.py", line 245, in _get Dec 01 20:51:10 mymachine etesync-dav[105099]: item = vobject.readOne(etesync_item.content) Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/vobject/base.py", line 1155, in readOne Dec 01 20:51:10 mymachine etesync-dav[105099]: return next(readComponents(stream, validate, transform, ignoreUnreadable, Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/vobject/base.py", line 1101, in readComponents Dec 01 20:51:10 mymachine etesync-dav[105099]: vline = textLineToContentLine(line, n) Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/vobject/base.py", line 925, in textLineToContentLine Dec 01 20:51:10 mymachine etesync-dav[105099]: return ContentLine(*parseLine(text, n), **{'encoded': True, Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/vobject/base.py", line 813, in parseLine Dec 01 20:51:10 mymachine etesync-dav[105099]: raise ParseError("Failed to parse line: {0!s}".format(line), lineNumber) Dec 01 20:51:10 mymachine etesync-dav[105099]: vobject.base.ParseError: At line 14: Failed to parse line: Some Place\,\nBronx\, NY Dec 01 20:51:10 mymachine etesync-dav[105099]: The above exception was the direct cause of the following exception: Dec 01 20:51:10 mymachine etesync-dav[105099]: Traceback (most recent call last): Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/radicale/app/__init__.py", line 105, in __call__ Dec 01 20:51:10 mymachine etesync-dav[105099]: status, headers, answers = self._handle_request(environ) Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/radicale/app/__init__.py", line 276, in _handle_request Dec 01 20:51:10 mymachine etesync-dav[105099]: status, headers, answer = function( Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/radicale/app/propfind.py", line 372, in do_PROPFIND Dec 01 20:51:10 mymachine etesync-dav[105099]: status, xml_answer = xml_propfind( Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/radicale/app/propfind.py", line 65, in xml_propfind Dec 01 20:51:10 mymachine etesync-dav[105099]: for item, permission in allowed_items: Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/radicale/app/propfind.py", line 313, in _collect_allowed_items Dec 01 20:51:10 mymachine etesync-dav[105099]: for item in items: Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/etesync_dav/radicale/storage.py", line 560, in discover Dec 01 20:51:10 mymachine etesync-dav[105099]: yield collection._get(href) Dec 01 20:51:10 mymachine etesync-dav[105099]: File "/usr/lib/python3.9/site-packages/etesync_dav/radicale/storage_etebase_collection.py", line 264, in _get Dec 01 20:51:10 mymachine etesync-dav[105099]: raise RuntimeError("Failed to parse item %r in %r" % Dec 01 20:51:10 mymachine etesync-dav[105099]: RuntimeError: Failed to parse item 'THIRD_OPAQUE_HASH.vcf' from 'myuser/SOME_OPAQUE_HASH' ```

Note: this doesn't really change anything since I think bullet (b) in my last comment still stands: I ultimately have some broken data that I cannot access as a normal user. Next step I think is to see if I can figure out how to write a query myself into whatever the underlying datastore is, and delete the bad record by hand. (and then later think proper fix - ie bullet (A) in my original report above).


[1]: that is: no items seem to serve out of the collection - the entire request 500s I guess, or maybe just tbsync doesn't handle partial failures? I'm not sure

jzacsh commented 2 years ago
EDIT: I've ported this comment to the appropriate repo github.com/etesync/etesync-web/issues/224#issuecomment-984308641 side-note: I found a parsing bug here where etesync's wrapper [doesn't check the contents it gets back from `ICAL.parse` call](https://github.com/etesync/etesync-web/blob/c0d884afd7499d3174b405bb10a2629eec376ecc/src/Collections/ImportDialog.tsx#L109) before using it. Then the `uid` getter() [fails on line 212 of getFirstProperty because `this.jCal` is actually a zero-length array](https://github.com/mozilla-comm/ical.js/blob/91ffc6503a439194dd9402a9ee92309419be66e9/lib/ical/component.js#L211) The fix should be: ```diff function onFileDropContact(acceptedFiles: File[], rejectedFiles: File[]) { const itemsCreator = (fileText: string) => { const mainComp = ICAL.parse(fileText); - return mainComp.map((comp) => { + return mainComp.filter(c => c.length).map((comp) => { const ret = new ContactType(new ICAL.Component(comp)); if (!ret.uid) { ret.uid = uuid.v4(); } return ret; }); }; onFileDropCommon(itemsCreator, acceptedFiles, rejectedFiles); } ```
jzacsh commented 2 years ago

I ultimately have some broken data that I cannot access as a normal user.

tl;dr: this^ is no longer true.. on my phone at least

Oh, also! Teeny-tiny success: I figured out Android's default contacts app lets me see the bad record (whereas webapp still doesn't). So I was able to delete it (and without deleting the totally-fine Google contacts copy: tap overflow menu --> tap "view linked contacts" --> tap etesync one --> tap overflow menu --> delete .. this ultimately deletes just etesync's copy)

jzacsh commented 2 years ago

I ultimately have some broken data that I cannot access as a normal user.

tl;dr: this^ is no longer true.. on my phone at least

tl;dr confirmed that^ fix was limited to phone and server databases; laptop's DB still has bad record

So despite my deleting successfully (last comment), tbsync on thunderbird now seems to hit a new and different, but related HTTP 500 where the nature of the error looks the same but .. maybe it's an error about a locally-cached copy somewhere I can't see... like an offline copy of the etebase data?

journalctl -xef --user-unit etesync-dav.service | grep -C 6 -Ei error ``` Dec 01 23:49:23 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'PROPFIND', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=7>, Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.run_once': False, Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.url_scheme': 'http', -- Dec 01 23:49:23 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'PROPFIND', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=7>, Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.run_once': False, Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.url_scheme': 'http', -- Dec 01 23:49:24 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'PROPFIND', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=7>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.run_once': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.url_scheme': 'http', -- Dec 01 23:49:24 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'PROPFIND', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=7>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.run_once': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.url_scheme': 'http', -- Dec 01 23:49:24 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'PROPFIND', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=7>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.run_once': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.url_scheme': 'http', -- Dec 01 23:49:24 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'PROPFIND', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=7>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.run_once': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.url_scheme': 'http', -- Dec 01 23:49:24 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'PROPFIND', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=7>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.run_once': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.url_scheme': 'http', -- Dec 01 23:49:24 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'PROPFIND', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=7>, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.run_once': False, Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.url_scheme': 'http', -- Dec 01 23:49:25 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'REPORT', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=7>, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.run_once': False, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.url_scheme': 'http', -- Dec 01 23:49:25 mymachine etesync-dav[176702]: /myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/WYdLLgu1-y8lR01S7TUAc_88fqD2y5lo.vcf Dec 01 23:49:25 mymachine etesync-dav[176702]: /myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/Qx6V4RGaldqImY2vjrZcY43O46Yldd0z.vcf Dec 01 23:49:25 mymachine etesync-dav[176702]: /myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/EU6CXpqaICuYR1mvAUy_WAlI6TTI7BeO.vcf Dec 01 23:49:25 mymachine etesync-dav[176702]: /myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/f5nKMi6xMdhY1TztmJEH7aPJ557XLFyd.vcf Dec 01 23:49:25 mymachine etesync-dav[176702]: /myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/1DIP0upLSBlVBblfXJ-vCjZhzt623iFs.vcf Dec 01 23:49:25 mymachine etesync-dav[176702]: Dec 01 23:49:25 mymachine etesync-dav[176702]: [2021-12-01 23:49:25 -0600] [176702/Thread-23] [ERROR] An exception occurred during REPORT request on '/myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/': Failed to serialize item 'R4EkUcr296wpVGfwjQAqfDtgZHiq6mr2.vcf' from 'myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW': 'VCARD components must contain at least 1 FN' Dec 01 23:49:25 mymachine etesync-dav[176702]: Traceback (most recent call last): Dec 01 23:49:25 mymachine etesync-dav[176702]: File "/usr/lib/python3.9/site-packages/radicale/item/__init__.py", line 337, in serialize Dec 01 23:49:25 mymachine etesync-dav[176702]: self._text = self.vobject_item.serialize() Dec 01 23:49:25 mymachine etesync-dav[176702]: File "/usr/lib/python3.9/site-packages/vobject/base.py", line 254, in serialize Dec 01 23:49:25 mymachine etesync-dav[176702]: return behavior.serialize(self, buf, lineLength, validate) Dec 01 23:49:25 mymachine etesync-dav[176702]: File "/usr/lib/python3.9/site-packages/vobject/behavior.py", line 157, in serialize Dec 01 23:49:25 mymachine etesync-dav[176702]: cls.validate(obj, raiseException=True) Dec 01 23:49:25 mymachine etesync-dav[176702]: File "/usr/lib/python3.9/site-packages/vobject/behavior.py", line 93, in validate Dec 01 23:49:25 mymachine etesync-dav[176702]: raise base.ValidateError(m .format(cls.name, val[0], key)) Dec 01 23:49:25 mymachine etesync-dav[176702]: vobject.base.ValidateError: 'VCARD components must contain at least 1 FN' Dec 01 23:49:25 mymachine etesync-dav[176702]: The above exception was the direct cause of the following exception: Dec 01 23:49:25 mymachine etesync-dav[176702]: Traceback (most recent call last): Dec 01 23:49:25 mymachine etesync-dav[176702]: File "/usr/lib/python3.9/site-packages/radicale/app/__init__.py", line 105, in __call__ Dec 01 23:49:25 mymachine etesync-dav[176702]: status, headers, answers = self._handle_request(environ) Dec 01 23:49:25 mymachine etesync-dav[176702]: File "/usr/lib/python3.9/site-packages/radicale/app/__init__.py", line 276, in _handle_request Dec 01 23:49:25 mymachine etesync-dav[176702]: status, headers, answer = function( Dec 01 23:49:25 mymachine etesync-dav[176702]: File "/usr/lib/python3.9/site-packages/radicale/app/report.py", line 286, in do_REPORT Dec 01 23:49:25 mymachine etesync-dav[176702]: status, xml_answer = xml_report( Dec 01 23:49:25 mymachine etesync-dav[176702]: File "/usr/lib/python3.9/site-packages/radicale/app/report.py", line 216, in xml_report Dec 01 23:49:25 mymachine etesync-dav[176702]: element.text = item.serialize() Dec 01 23:49:25 mymachine etesync-dav[176702]: File "/usr/lib/python3.9/site-packages/radicale/item/__init__.py", line 339, in serialize Dec 01 23:49:25 mymachine etesync-dav[176702]: raise RuntimeError("Failed to serialize item %r from %r: %s" % Dec 01 23:49:25 mymachine etesync-dav[176702]: RuntimeError: Failed to serialize item 'R4EkUcr296wpVGfwjQAqfDtgZHiq6mr2.vcf' from 'myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW': 'VCARD components must contain at least 1 FN' Dec 01 23:49:25 mymachine etesync-dav[176702]: [2021-12-01 23:49:25 -0600] [176702/Thread-24] [INFO] REPORT request for '/myuser/6Y6m3QcoQpPAJ_BKoXECIoQcZCCE5Ij0/' with depth '1' received from 127.0.0.1 using 'Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101 Thunderbird/91.3.2' Dec 01 23:49:25 mymachine etesync-dav[176702]: [2021-12-01 23:49:25 -0600] [176702/Thread-24] [DEBUG] Request headers: Dec 01 23:49:25 mymachine etesync-dav[176702]: {'CONTENT_LENGTH': '166', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'CONTENT_TYPE': 'text/xml; charset=utf-8', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'GATEWAY_INTERFACE': 'CGI/1.1', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'HTTP_ACCEPT': 'text/xml', -- Dec 01 23:49:25 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'REPORT', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=7>, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.run_once': False, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.url_scheme': 'http', -- Dec 01 23:49:25 mymachine etesync-dav[176702]: 'REQUEST_METHOD': 'REPORT', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SCRIPT_NAME': '', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_NAME': 'localhost', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_PORT': '37358', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_PROTOCOL': 'HTTP/1.1', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'SERVER_SOFTWARE': 'WSGIServer/0.2', Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.errors': <_io.TextIOWrapper name='' mode='w' encoding='utf-8'>, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': , Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.input': <_io.BufferedReader name=17>, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.multiprocess': False, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.multithread': True, Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.run_once': False, ```
jzacsh commented 2 years ago

update: I deleted my local data (etesync-dav del myuser && systemctl --user restart etesync-dav.service), setup my user again and reconfigured tbsync, but now I get the same error, just the hash has changed (I'm guessing that's just the re-sync down from pim.etesync.. servers).

So it's probably the same record somehow...

tl;dr confirmed that^ fix was limited to phone and server databases; laptop's DB still has bad record

... despite that^ claim that I succeeded in deleting it :thinking: