server
server copied to clipboard
etesync
malformed input vcard file causes unrecoverable error with no AIs for user
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:
- A) don't ingest bad data
- expected: if data ingested has an issue, it should be rejected before being saved
- actual: whenever a parse error occurrs, it's treated as a fatal crash with no little-to-no guidance to help an end-user recover
- eg: here's a similar reproducible experience when importing ICS: https://github.com/etesync/etesync-web/issues/224
- B) if you do ingest bad data, then leave an actionable way to fix said data
- expected: in clients (like
pim...webapp) and server logs (like etesync-dav), I can figure out how to locate the bad record (eg a link to an FAQ doc entry like "how to hand-edit the ID corresponding to record to exceptions for/myusername/SOMEHASH") - actual: local DAV server fails with 500s, leaving consumer (tbsync) with failure. etesync's own pim webapp just has persistent error icon leaving consumer with failure and very little explanation.
- expected: in clients (like
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:
- middle of screen in
pimwebapp: 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.
- 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:
<d:propfind xmlns:d="DAV:"><d:prop><d:getetag /></d:prop></d:propfind>
Response:
A server error occurred. Please contact the administrator.
- bottom of screen in
journalctl --pager-end --catalog --follow --user status etesync-dav.serviceoutput: 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'
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)
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;
- gone back to my Google account and re-exported a single large VCF file
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- opened etesync web ui
- searched for said contact name
- no results :(
expected: step 5 should've had bad contact ("Marco") to show up actual: no matches... so either:
- a. the bad import record is no longer even in my etesync account, in which case the "sync errors" dialog is just a perpetual, impossible-to-dismiss error that's forever tied to my account
- b. the bad record is in my etesync account, but I have no access to it
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
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 before using it. Then the uid getter() fails on line 212 of getFirstProperty because this.jCal is actually a zero-length array
The fix should be:
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);
}
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)
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:23 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:24 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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]: <href>/myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/WYdLLgu1-y8lR01S7TUAc_88fqD2y5lo.vcf</href>
Dec 01 23:49:25 mymachine etesync-dav[176702]: <href>/myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/Qx6V4RGaldqImY2vjrZcY43O46Yldd0z.vcf</href>
Dec 01 23:49:25 mymachine etesync-dav[176702]: <href>/myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/EU6CXpqaICuYR1mvAUy_WAlI6TTI7BeO.vcf</href>
Dec 01 23:49:25 mymachine etesync-dav[176702]: <href>/myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/f5nKMi6xMdhY1TztmJEH7aPJ557XLFyd.vcf</href>
Dec 01 23:49:25 mymachine etesync-dav[176702]: <href>/myuser/67lB_3nrGMYwIH5kMfcN3HMyYeslJMeW/1DIP0upLSBlVBblfXJ-vCjZhzt623iFs.vcf</href>
Dec 01 23:49:25 mymachine etesync-dav[176702]: </CR:addressbook-multiget>
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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='<stderr>' mode='w' encoding='utf-8'>,
Dec 01 23:49:25 mymachine etesync-dav[176702]: 'wsgi.file_wrapper': <class 'wsgiref.util.FileWrapper'>,
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,
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: