Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Weird behaviour with KAddressBook #49

Closed
forty8bits opened this issue Mar 14, 2019 · 43 comments

Comments

Projects
None yet
3 participants
@forty8bits
Copy link

commented Mar 14, 2019

When creating new address book entries through KAddressBook (v5.10.3 on Manjaro), the following errors occur in etesync-dav:

[█████] DEBUG: Request content:
BEGIN:VCARD
VERSION:3.0
FN:Bob Loblaw
N:Loblaw;Bob;;;
UID:d9ad2907-8c54-428b-a89b-824aac5d5f3a
END:VCARD


[█████] ERROR: An exception occurred during PUT request on '/█████/1552563817.R271.vcf': <Model: Content> instance matching query does not exist:
SQL: SELECT "t1"."id", "t1"."journal_id", "t1"."uid", "t1"."content", "t1"."new", "t1"."dirty", "t1"."deleted" FROM "content" AS "t1" WHERE (("t1"."journal_id" = ?) AND ("t1"."uid" = ?)) LIMIT ? OFFSET ?
Params: [9, '1552563817.R271', 1, 0]
Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/peewee.py", line 6208, in get
    return clone.execute(database)[0]
  File "/usr/lib/python3.7/site-packages/peewee.py", line 3883, in __getitem__
    return self.row_cache[item]
IndexError: list index out of range

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/etesync/api.py", line 433, in get
    return self.get_content_class()._from_cache(self._cache_obj.content_set.where(pim.Content.uid == uid).get())
  File "/usr/lib/python3.7/site-packages/peewee.py", line 6213, in get
    (clone.model, sql, params))
etesync.pim.ContentDoesNotExist: <Model: Content> instance matching query does not exist:
SQL: SELECT "t1"."id", "t1"."journal_id", "t1"."uid", "t1"."content", "t1"."new", "t1"."dirty", "t1"."deleted" FROM "content" AS "t1" WHERE (("t1"."journal_id" = ?) AND ("t1"."uid" = ?)) LIMIT ? OFFSET ?
Params: [9, '1552563817.R271', 1, 0]

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 332, in __call__
    status, headers, answers = self._handle_request(environ)
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 505, in _handle_request
    environ, base_prefix, path, user)
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 948, in do_PUT
    new_item = parent_item.upload(href, items[0])
  File "/usr/lib/python3.7/site-packages/radicale_storage_etesync/__init__.py", line 365, in upload
    return self.get(href)
  File "/usr/lib/python3.7/site-packages/radicale_storage_etesync/__init__.py", line 335, in get
    etesync_item = self.collection.get(uid)
  File "/usr/lib/python3.7/site-packages/etesync/api.py", line 435, in get
    raise exceptions.DoesNotExist(e)
etesync.exceptions.DoesNotExist: <Model: Content> instance matching query does not exist:
SQL: SELECT "t1"."id", "t1"."journal_id", "t1"."uid", "t1"."content", "t1"."new", "t1"."dirty", "t1"."deleted" FROM "content" AS "t1" WHERE (("t1"."journal_id" = ?) AND ("t1"."uid" = ?)) LIMIT ? OFFSET ?
Params: [9, '1552563817.R271', 1, 0]

When checking on https://client.etesync.com the new entry is not synced initially, however upon a reboot of the machine the entry is synced, but KAddressBook now shows a duplicate entry, and attempts to merge these duplicates into one etc. do not fix the situation.

@forty8bits

This comment has been minimized.

Copy link
Author

commented Mar 14, 2019

Apologies, I forgot to mention I'm running etesync-dav v0.5.0 installed from the AUR.

@tasn

This comment has been minimized.

Copy link
Member

commented Mar 14, 2019

Thanks for reporting, will try to figure this out! It obviously shouldn't happen. :)

@tasn

This comment has been minimized.

Copy link
Member

commented Mar 14, 2019

I think I have a fix, could you please open /usr/lib/python3.7/site-packages/radicale_storage_etesync/__init__.py and change it as follows:

         uid = _trim_suffix(href, ('.ics', '.ical', '.vcf'))
-        etesync_item = self.collection.get(uid)
-        if etesync_item is None:
+        try:
+            etesync_item = self.collection.get(uid)
+        except api.execptions.DoesNotExist:

Please let me know if that fixes it. Though it will only fix the error (in the symptom) rather than the actual issue at hand which is why does KAddressBook think the contact already exists...

Edit: don't forget to restart etesync-dav after you make this change.

@forty8bits

This comment has been minimized.

Copy link
Author

commented Mar 14, 2019

Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 332, in __call__
    status, headers, answers = self._handle_request(environ)
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 505, in _handle_request
    environ, base_prefix, path, user)
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 948, in do_PUT
    new_item = parent_item.upload(href, items[0])
  File "/usr/lib/python3.7/site-packages/radicale_storage_etesync/__init__.py", line 359, in upload
    etesync_item = item.etesync_item
AttributeError: 'NoneType' object has no attribute 'etesync_item'
@tasn

This comment has been minimized.

Copy link
Member

commented Mar 14, 2019

Sorry, also change the following (in the function upload in line 351):

         content = vobject_item.serialize()
-        try:
-            item = self.get(href)
+        item = self.get(href)
+        if item is None:
+            etesync_item = self.collection.get_content_class().create(self.collection, content)
+        else:
             etesync_item = item.etesync_item
             etesync_item.content = content
-        except api.exceptions.DoesNotExist:
-            etesync_item = self.collection.get_content_class().create(self.collection, content)
@forty8bits

This comment has been minimized.

Copy link
Author

commented Mar 14, 2019

Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 332, in __call__
    status, headers, answers = self._handle_request(environ)
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 505, in _handle_request
    environ, base_prefix, path, user)
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 953, in do_PUT
    headers = {"ETag": new_item.etag}
AttributeError: 'NoneType' object has no attribute 'etag'
@tasn

This comment has been minimized.

Copy link
Member

commented Mar 14, 2019

OK, my attempts at a quick fix have failed. :)
Thanks a lot for your help, I'll try to dig deeper into this and figure out what's going on.

@forty8bits

This comment has been minimized.

Copy link
Author

commented Mar 14, 2019

No problem! 👍

@tasn

This comment has been minimized.

Copy link
Member

commented Mar 14, 2019

P.S: clearing your cache (rm ~/.config/etesync-dav/etesync_data.db) and restarting etesync-dav will probably "fix" (workaround) this issue for you. Though of course it doesn't fix the underlying issue that caused it...

@forty8bits

This comment has been minimized.

Copy link
Author

commented Apr 18, 2019

@tasn while issuing a POST request to create a new contact is definitely more intuitive, it seems the CardDAV standard actually allows for creation of new entries through PUT requests to specific endpoints defined by clients: https://tools.ietf.org/html/rfc6352#section-6.3.2

Could this be an issue whereby either etesync-dav or radicale aren't handling this possibility correctly?

@tasn

This comment has been minimized.

Copy link
Member

commented May 1, 2019

Oops, forgot to reply, sorry. It could be that. I doubt that it's an issue in Radicale, but it could very well be an issue with the EteSync radicale backend. Could you please remind me the version of EteSync dav the above backtrace was generated with? Or alternatively paste here a backtrace with latest radicale_storage_etesync so I can look into this hypothesis?

Thanks!

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 1, 2019

It was version 0.5.0 of etesync-dav from the AUR, which still appears to be the latest version. 👍

@tasn

This comment has been minimized.

Copy link
Member

commented May 1, 2019

That's etesync-dav, what about radicale_storage_etesync? I'm asking because the line numbers don't make sense which means it's from a version that's different to git latest.

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 1, 2019

Apologies, the corresponding version of python-radicale-storage-etesync from the AUR is 0.7.0.

@tasn

This comment has been minimized.

Copy link
Member

commented May 1, 2019

Oh, I think I see what's going on. It looks like KAddressBook is asking to create an item with a filename that's different to the item's UID, and EteSync doesn't like that.

Could you try maybe one last monkey-patch? Try changing return self.get(href) to return etesync_item. Does that fix it for you?

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 1, 2019

I made the change (in addition to the previous ones) and now the following occurs:

[█████] ERROR: An exception occurred during PUT request on '/█████/1556719768.R794.vcf': 'Contact' object has no attribute 'etag'
Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 332, in __call__
    status, headers, answers = self._handle_request(environ)
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 505, in _handle_request
    environ, base_prefix, path, user)
  File "/usr/lib/python3.7/site-packages/radicale/__init__.py", line 953, in do_PUT
    headers = {"ETag": new_item.etag}
AttributeError: 'Contact' object has no attribute 'etag'
@tasn

This comment has been minimized.

Copy link
Member

commented May 1, 2019

It seems that I'm not lucky enough to guess correctly. :)

I'll play with it here and let you know what needs to be done.

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 1, 2019

No problem. It seems like it could possibly be an issue in Radicale though; it looks like it expects an ETag back always, however according to http://sabre.io/dav/building-a-carddav-client/#creating-a-contact there are instances where an ETag may not be returned (this applies for entry updates too). They describe this as being the case if the server had to modify an item for some reason, so unless EteSync is modifying entries slightly for some reason then perhaps it is an issue with EteSync itself not returning ETag?

@tasn

This comment has been minimized.

Copy link
Member

commented May 1, 2019

That's not the issue. Radicale EteSync always returns an etag. It's just that my fix attempt above didn't return the right object (rant: I hate it that Python isn't typed!).

Could you please change the return to return self.get(etesync_item.uid)?
I tested it here and it seems to work. :)

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 1, 2019

That seems to get rid of the issue with creating new contacts, although I'm still seeing strange behaviour since the first successful test of this fix; notably taking any action in KAddressBook (updating existing contacts, creating new contacts, etc.) is seemingly triggering absolutely no action against etesync-dav (running with the -D flag for debug output) whatsoever. 😕

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 1, 2019

I should clarify. I guess it doesn't seem to get rid of the issue beyond the creation of a single contact given now nothing is having any effect; however I'm not sure if the issue now lies with KAddressBook or EteSync.

@tasn

This comment has been minimized.

Copy link
Member

commented May 1, 2019

Don't despair, that's progress. :)

Questions:

  1. Are you able to edit other contacts? That is, ones that already existed before?
  2. Are you able to edit contacts if you remove my suggested fix? That is, is this a regression following my fix, or was it always the case?
  3. Are you getting any errors from etesync-dav? KAddressBook?
  4. What exactly are you seeing when you say no action? It doesn't even make a request to etesync-dav?

Thanks again for all your help!

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 1, 2019

  1. Editing contacts which previously existed results in the same behaviour: KAddressBook doesn't indicate anything is wrong but EteSync DAV doesn't indicate anything at all. No changes are synced through to the EteSync Android application.
  2. I'll revert the file and let you know shortly.
  3. No errors are output during taking these actions anyway, as described in answer to 4 below, however when I restart Akonadi via akonadictl restart I see lots of activity in both the output of that command and in EteSync DAV. Of interest are the following:
    EteSync DAV...
    [█████] INFO: GET response status for '/█████/1556727439.R794.vcf' in 0.021 seconds: 404 Not Found
    
    Akonadi...
    org.kde.pim.davresource: Error when uploading item: 400 "There was a problem with the request. The item has not been created on the server.\nAccess was denied while attempting to upload http://█████@localhost:37358/█████/1556727439.R271.vcf. (500)."
    org.kde.pim.davresource: DavGroupwareResource::onItemFetched: Failed to parse item data.  "http://localhost:37358/█████/1556727439.R794.vcf"
    
  4. The process of editing or creating new users through the GUI seems to work and no indication is given that anything is going wrong. EteSync DAV shows absolutely zero output, as if no requests are even being made to it at all.

It's worth noting that on editing users, now that I have Akonadi output, it appears as though the same error as noted in answer to 3 above is shown, meaning it looks like the problem is a single corrupt or problematic item, which prevents any operation, even on other items, from succeeding. Upon restarting everything I also noted that I got just one of many test contacts I created through to the Android application, but other new entries and edits to existing entries (done both before and after creation of the one successfully synced entry) didn't come through at all.

@tasn

This comment has been minimized.

Copy link
Member

commented May 1, 2019

I wonder if what I'm doing, with the rewriting of the filename is legal. I remember that it is, and I remember it working, but I'm not 100% sure anymore following your reports.

I also just checked, and KDE doesn't seem to be on the list of clients radicale is confirmed to work with: https://radicale.org/clients/

I wonder if it's just because no one bothered, or if there are known issues.

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 1, 2019

Reverting the file has allowed a few more (but not all) entries to sync through to the Android EteSync client, and has changed the output of EteSync DAV, however Akonadi still shows some errors in the same format as above, and as mentioned not all edits were synced. There are also many duplicates in KAddressBook now, which is behaviour I seen initially with this issue each time I restarted EteSync DAV to try to force the new entries to sync.

I may reinstate the changes and start with a fresh address book to see if maybe the data hasn't just become corrupt somehow during this process of debugging the issue. It may be a day or two before I can get to this though, although I'll try get to it sooner.

Also, interesting that it's not listed there, although KDE Kontact (which includes KAddressBook etc.) is mentioned at https://github.com/Kozea/Radicale/wiki/Sharing-Calendars so it looks like the KDE PIM suite was accounted for at least at some point. 🤔

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 1, 2019

Also, I'm not sure if this is definitive or not, but the page I linked to in a previous comment mentions:

Creating a contact is almost identical, except that you (as a client) are responsible for determining the url of the object, and UID.

So it's possible that rewriting the filename as you said you're doing could be an issue?

@tasn

This comment has been minimized.

Copy link
Member

commented May 1, 2019

You are responsible, yes, but it doesn't say anything about the server rewriting it... For whatever it's worth, we don't modify the UID, we just make sure the URL is the same as the UID. :)

Could you maybe start afresh, that is, with a new collection and test there with my suggested change from above? I wonder if the issues were just because of leftover buggy contacts. Essentially what you suggested. :)

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 2, 2019

It does mention the following elsewhere, in relation to UIDs and URLs in one of their examples:

In this case all urls ended with .vcf. This is often the case, but you must not rely on this. In this case the UID in the vCards was also identical to a part of the url. This too is often the case, but again not something you can rely on, so don't make any assumptions.

The url and the UID have no meaningful relationship, so treat both those items as separate unique identifiers.

Again, I'm no expert and you've likely researched this topic a lot more than I have in the process of creating EteSync! It's just something I thought could be useful.

I will start afresh and try again once I get a block of time for it, likely later tonight. 👍

@tasn

This comment has been minimized.

Copy link
Member

commented May 2, 2019

Yes, they are separate unique identifiers, I know that. Though to make things easier and consistent, in EteSync we enforce an additional restriction, which is the url is <uid>.vcf. It makes everything much simpler. The standard, for all I know, is fine with the server renaming things, so it shouldn't be a problem. I wonder what's going on.

@forty8bits

This comment has been minimized.

Copy link
Author

commented May 2, 2019

Do you know of any clients other than KAddressBook which make use of the PUT method of creating new entries rather than the POST method? It may be interesting to test one too, as while the POST method is the more convenient one, if the PUT one is valid then it may be worth testing this behaviour definitively using more than one client.

Again, I don't mean to get sucked into discussion on interpreting the standard before I test from afresh as we've agreed, but it really does read to me as though the URL and UID are special cases which probably shouldn't be changed by the server when a client uses the PUT method for entry creation; from the standard (emphasis mine):

Clients populate address book collections with address object
resources. The URL for each address object resource is entirely
arbitrary and does not need to bear a specific relationship (but
might) to the address object resource's vCard properties or other
metadata. New address object resources MUST be created with a PUT
request targeted at an unmapped URI.
A PUT request targeted at a
mapped URI updates an existing address object resource.

When servers create new resources, it's not hard for the server to
choose a unique URL. It's slightly tougher for clients, because a
client might not want to examine all resources in the collection and
might not want to lock the entire collection to ensure that a new one
isn't created with a name collision. However, there is an HTTP
feature to mitigate this. If the client intends to create a new
address resource, the client SHOULD use the HTTP header "If-None-
Match: *" on the PUT request. The Request-URI on the PUT request
MUST include the target collection, where the resource is to be
created, plus the name of the resource in the last path segment. The
"If-None-Match" header ensures that the client will not inadvertently
overwrite an existing resource even if the last path segment turned
out to already be used.

It seems like it's acknowledged that allowing the server to create new resources is the more convenient option, but outlines rules for clients doing so which don't seem to allow for success while also returning a URL (or UID) different to the one provided by the client? It's possible this is in another of the RFCs, but I do suspect this could be worth looking into if my tests from afresh later don't work as we hope.

@tasn

This comment has been minimized.

Copy link
Member

commented May 2, 2019

I have no idea if other clients use it too. It probably doesn't matter though because the radicale interface for backends unifies POST and PUT. That is, there's only function a backend should implement, called upload, that handles both a new entry and an update.

As for the excerpts from the RFC: the first one just describes that PUT should also create. I don't see it having any weight on what we are doing here, because later on there could be "the server is allowed to remap URIs" or something of that sort that essentially lets us create a new URI.
As for the second part: as you said, it just shows it as an option, so not a strong indication.

I really don't know enough about the DAV spec. My experience with it mostly comes from debugging etesync-dav and testing it against existing clients. For all I know people use it successfully with Thunderbird (Lighting, CardBook and TbSync), Evolution, Contacts/Calendar.app and iOS DAV. I can't be sure though as it's just based on people's reports. I've personally tested it with all of the above (other than Evolution) and it does seem to work.

Anyhow, let's wait and see if my fix actually does anything. I'd love to have a DAV expert weigh in about this URL rewrite thing if you know anyone. :|

@devurandom

This comment has been minimized.

Copy link

commented Jul 6, 2019

Are you still working on a fix?

I am also using Akonadi and also have trouble syncing contacts. What I observed from etesync-dav --debug logs is that Akonadi tries to PUT a VCard, which succeeds with 201, and then it immediately triest to GET it, which fails with a 404. Then Akonadi stops syncing entirely. This seems to be what you describe here.

EteSync DAV version: 0.6.0
Radicale Storage EteSync version: 0.8.0
Radicale version: 2.1.11
Fedora 30 KDE
KDE Applications 19.04.2
KDE Plasma 5.15.5
KDE Frameworks 5.59.0

@tasn

This comment has been minimized.

Copy link
Member

commented Jul 8, 2019

That's useful to know, thanks! I think there's no escaping it. I'll have to stop the URL rewriting that we currently do (and simplifies things!) and start following whatever clients want as a URL. :|

@tasn

This comment has been minimized.

Copy link
Member

commented Jul 9, 2019

@devurandom, if I send you a potential fix (I can either push it to a branch on this repo or compile a binary for you, whichever you prefer), will you be able to test it to verify it works?

Same goes to you @forty8bits .

@devurandom

This comment has been minimized.

Copy link

commented Jul 9, 2019

@devurandom, if I send you a potential fix (I can either push it to a branch on this repo or compile a binary for you, whichever you prefer), will you be able to test it to verify it works?

I should be able to build etesync-dav with setup.py. Giving me a branch or a patch is sufficient.

tasn added a commit to etesync/radicale_storage_etesync that referenced this issue Jul 10, 2019

@tasn

This comment has been minimized.

Copy link
Member

commented Jul 10, 2019

@devurandom, to test this you'd need the latest pyetesync from Git (master branch), and the latest from this branch https://github.com/etesync/radicale_storage_etesync/tree/kaddress

It should just work, but if it doesn't, maybe try removing from kaddressbook and adding back, or any other jigging that you think may work. :)

It passed my local tests, but I don't have kaddressbook installed, so who knows. :)

@devurandom

This comment has been minimized.

Copy link

commented Jul 10, 2019

I setup a virtualenv venv, activated it using . ./venv/bin/activate.fish, ran python3 setup.py install in pyetesync, radicale_storage_etesync (in branch kaddress) and etesync-dav. Then I started venv/bin/etesync-dav --debug and saw a lot of messages whooshing by (way way more than before) and they seemed to be generally successful.

At some point the HTTP handler used by Akonadi (KDE's http.so) segfaulted, but that might have different causes.

@tasn

This comment has been minimized.

Copy link
Member

commented Jul 10, 2019

Sounds like success to me. 🤣

From your description it sounds like etesync-dav works. I fixed the underlying issue you described, that I know for sure, but maybe there's something else.

I'd suggest you report the issue to the KDE folks, doesn't matter what etesync-dav does wrong, Akonadi shouldn't be crashing.

Out of interest, what's the last response you get from etesync-dav before the crash? Wonder if there's anything obviously suspicious there.
Also, are you able to get the backtrace from Akonadi?

@devurandom

This comment has been minimized.

Copy link

commented Jul 10, 2019

I wouldn't bother with the http.so crash. It happened only once and I did not have debug info files, so DrKonqi could not automatically report a bug. I consider this issue fixed.

@tasn

This comment has been minimized.

Copy link
Member

commented Jul 10, 2019

Just to confirm, KAddressBook now works as intended and this ticket can be closed? 🎉

@devurandom

This comment has been minimized.

Copy link

commented Jul 11, 2019

Akonadi Console and EteSync for Android show the same amount of entries in my address book, so I consider the problem fixed.

@tasn

This comment has been minimized.

Copy link
Member

commented Jul 11, 2019

Great to know, thanks! I'll release a new version soon. :)

@devurandom

This comment has been minimized.

Copy link

commented Jul 11, 2019

Great to know, thanks! I'll release a new version soon. :)

Thanks for looking into it!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.