search

etesync / etesync-dav

This is a CalDAV and CardDAV adapter for EteSync
https://www.etesync.com
GNU General Public License v3.0
285 stars 45 forks source link

missing calendar events and etebase_python.Error: Invalid token #252

Closed stuart12 closed 2 years ago

stuart12 commented 2 years ago

hello, some calendar events are not being synchronised (from Android) into thunderbird (tbsync). A restart of etesync-dav and thunderbird does not make the exception/error go away or the missing calendar entries arrive. etesync-web shows that the calendar entry has been sent from Android to my etesync server. It is just etesync-dav that seems unable to send it to Thunderbird 91.4.0 with tbsync 3.0.1. I do not have problems with contacts. Should I delete the cache and restart?

Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Loaded default config
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Loaded arguments
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Starting Radicale
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] auth type is 'radicale.auth.htpasswd'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] storage type is 'etesync_dav.radicale.storage'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] rights type is 'etesync_dav.radicale.rights'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] web type is 'etesync_dav.radicale.web'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Listening on '[127.0.0.1]:37358'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Listening on '[::1]:37358'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Radicale server ready
Jan 20 16:45:44 kooka python3[142981]: [2022-01-20 16:45:44 +0100] [142981/Thread-1] [INFO] PROPFIND request for '/stuart/OvKup7OiE7Dn4Fn7t31rog8u/' with depth '0' received from 127.0.0.1 using 'Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101 Thunderbird/91.4.0'
Jan 20 16:45:44 kooka python3[142981]: [2022-01-20 16:45:44 +0100] [142981/Thread-1] [INFO] Successful login: 'stuart'
Jan 20 16:45:44 kooka python3[142981]: [2022-01-20 16:45:44 +0100] [142981/Thread-2] [ERROR] Invalid token.
Jan 20 16:45:44 kooka python3[142981]: Traceback (most recent call last):
Jan 20 16:45:44 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/radicale/storage.py", line 84, in run
Jan 20 16:45:44 kooka python3[142981]:     etesync.sync()
Jan 20 16:45:44 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 90, in sync
Jan 20 16:45:44 kooka python3[142981]:     self.sync_collection_list()
Jan 20 16:45:44 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 104, in sync_collection_list
Jan 20 16:45:44 kooka python3[142981]:     col_list = col_mgr.list(COL_TYPES, fetch_options)
Jan 20 16:45:44 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etebase/__init__.py", line 247, in list
Jan 20 16:45:44 kooka python3[142981]:     return CollectionListResponse(self._inner.list_multi(list(col_type), _inner(fetch_options)))
Jan 20 16:45:44 kooka python3[142981]: etebase_python.Error: Invalid token.
Jan 20 16:45:44 kooka python3[142981]: [2022-01-20 16:45:44 +0100] [142981/Thread-1] [ERROR] An exception occurred during PROPFIND request on '/stuart/OvDn4Fn7t31rog8u/': Invalid token.
Jan 20 16:45:50 kooka python3[142981]: [2022-01-20 16:45:50 +0100] [142981/Thread-3] [INFO] PROPFIND request for '/stuart/OvKup7On7t31rog8u323/' with depth '0' received from 127.0.0.1 using 'Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101 Thunderbird/91.4.0'
Jan 20 16:45:50 kooka python3[142981]: [2022-01-20 16:45:50 +0100] [142981/Thread-3] [INFO] Successful login: 'stuart'
Jan 20 16:45:50 kooka python3[142981]: [2022-01-20 16:45:50 +0100] [142981/Thread-3] [INFO] PROPFIND response status for '/stuart/OvKup7OiE7Dn4Fn7t31rog8u/' with depth '0' in 0.030 seconds: 207 Multi-Status
Jan 20 16:45:50 kooka python3[142981]: [2022-01-20 16:45:50 +0100] [142981/Thread-4] [INFO] OPTIONS request for '/stuart/' received from 127.0.0.1 using 'Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101 Thunderbird/91.4.0'
Jan 20 16:45:50 kooka python3[142981]: [2022-01-20 16:45:50 +0100] [142981/Thread-4] [INFO] OPTIONS response status for '/stuart/' in 0.001 seconds: 200 OK
Jan 20 16:45:50 kooka python3[142981]: [2022-01-20 16:45:50 +0100] [142981/Thread-5] [INFO] REPORT request for '/stuart/OvKup7OiE7Dn4Fn7t31rog8u/' with depth '1' received from 127.0.0.1 using 'Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101 Thunderbird/91.4.0'
Jan 20 16:45:50 kooka python3[142981]: [2022-01-20 16:45:50 +0100] [142981/Thread-5] [INFO] Successful login: 'stuart'
Jan 20 16:47:04 kooka python3[142981]: [2022-01-20 16:47:04 +0100] [142981/Thread-5] [INFO] REPORT response status for '/stuart/OvKup7OiE7Dn4Fn7t31rog8u/' with depth '1' in 74.397 seconds: 207 Multi-Status
Jan 20 16:47:05 kooka python3[142981]: [2022-01-20 16:47:05 +0100] [142981/Thread-6] [INFO] REPORT request for '/stuart/OvKup7OiE7Dn4Fn7t31rog8u/' with depth '1' received from 127.0.0.1 using 'Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101 Thunderbird/91.4.0'
Jan 20 16:47:05 kooka python3[142981]: [2022-01-20 16:47:05 +0100] [142981/Thread-6] [INFO] Successful login: 'stuart'
Jan 20 16:47:05 kooka python3[142981]: [2022-01-20 16:47:05 +0100] [142981/Thread-2] [ERROR] Invalid token.
Jan 20 16:47:05 kooka python3[142981]: Traceback (most recent call last):
Jan 20 16:47:05 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/radicale/storage.py", line 84, in run
Jan 20 16:47:05 kooka python3[142981]:     etesync.sync()
Jan 20 16:47:05 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 90, in sync
Jan 20 16:47:05 kooka python3[142981]:     self.sync_collection_list()
Jan 20 16:47:05 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 104, in sync_collection_list
Jan 20 16:47:05 kooka python3[142981]:     col_list = col_mgr.list(COL_TYPES, fetch_options)
Jan 20 16:47:05 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etebase/__init__.py", line 247, in list
Jan 20 16:47:05 kooka python3[142981]:     return CollectionListResponse(self._inner.list_multi(list(col_type), _inner(fetch_options)))
Jan 20 16:47:05 kooka python3[142981]: etebase_python.Error: Invalid token.

The start messages are (just to confirm the version numbers):

Jan 20 16:45:21 kooka systemd[1]: Starting EteSync CalDAV and CardDAV front-end/proxy for stuart...
Jan 20 16:45:22 kooka python3[142957]: Python 3.9.9
Jan 20 16:45:22 kooka runuser[142968]: pam_unix(runuser:session): session opened for user stuart(uid=1000) by (uid=0)
Jan 20 16:45:22 kooka runuser[142968]: pam_unix(runuser:session): session closed for user stuart
Jan 20 16:45:23 kooka python3[142973]: Collecting Radicale<3.0.6
Jan 20 16:45:23 kooka python3[142973]:   Using cached Radicale-3.0.5-py3-none-any.whl (121 kB)
Jan 20 16:45:24 kooka python3[142973]: Collecting etesync-dav
Jan 20 16:45:24 kooka python3[142973]:   Using cached etesync_dav-0.32.1-py3-none-any.whl
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: python-dateutil>=2.7.3 in /usr/lib/python3/dist-packages (from Radicale<3.0.6) (2.8.1)
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: vobject>=0.9.6 in /usr/lib/python3/dist-packages (from Radicale<3.0.6) (0.9.6.1)
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: defusedxml in /usr/lib/python3/dist-packages (from Radicale<3.0.6) (0.7.1)
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: passlib in /usr/lib/python3/dist-packages (from Radicale<3.0.6) (1.7.4)
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: requests[socks]>=2.21 in /usr/lib/python3/dist-packages (from etesync-dav) (2.25.1)
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: msgpack>=1.0.0 in /usr/lib/python3/dist-packages (from etesync-dav) (1.0.2)
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: Flask-WTF<1.0.0,>=0.14.2 in /usr/lib/python3/dist-packages (from etesync-dav) (0.14.3)
Jan 20 16:45:24 kooka python3[142973]: Collecting etebase>=0.30.0
Jan 20 16:45:24 kooka python3[142973]:   Using cached etebase-0.31.5-cp39-cp39-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (4.4 MB)
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: appdirs>=1.4.3 in /usr/lib/python3/dist-packages (from etesync-dav) (1.4.4)
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: Flask>=1.1.1 in /usr/lib/python3/dist-packages (from etesync-dav) (2.0.1)
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: etesync>=0.12.1 in /usr/lib/python3/dist-packages (from etesync-dav) (0.12.1)
Jan 20 16:45:24 kooka python3[142973]: Requirement already satisfied: PySocks!=1.5.7,>=1.5.6 in /usr/lib/python3/dist-packages (from requests[socks]>=2.21->etesync-dav) (1.7.1)
Jan 20 16:45:24 kooka python3[142973]: Installing collected packages: Radicale, etebase, etesync-dav
Jan 20 16:45:24 kooka python3[142973]: Successfully installed Radicale-3.0.5 etebase-0.31.5 etesync-dav-0.32.1
Jan 20 16:45:24 kooka systemd[1]: Started EteSync CalDAV and CardDAV front-end/proxy for stuart.
Jan 20 16:45:24 kooka python3[142981]: /usr/lib/python3/dist-packages/vobject/base.py:736: DeprecationWarning: invalid escape sequence \-
Jan 20 16:45:24 kooka python3[142981]:   patterns['name'] = '[a-zA-Z0-9\-_]+'
Jan 20 16:45:24 kooka python3[142981]: /usr/lib/python3/dist-packages/vobject/base.py:1219: DeprecationWarning: invalid escape sequence \;
Jan 20 16:45:24 kooka python3[142981]:   s = s.replace("\\", "\\\\").replace(";", "\;").replace(",", "\,")
Jan 20 16:45:24 kooka python3[142981]: /usr/lib/python3/dist-packages/vobject/base.py:1219: DeprecationWarning: invalid escape sequence \,
Jan 20 16:45:24 kooka python3[142981]:   s = s.replace("\\", "\\\\").replace(";", "\;").replace(",", "\,")
Jan 20 16:45:25 kooka python3[142981]: /usr/lib/python3/dist-packages/orderedmultidict/orderedmultidict.py:15: DeprecationWarning: Using or importing the ABCs from 'collections' instead of from 'collections.abc' is deprecated since Python 3.3, and in 3.10 it will stop working
Jan 20 16:45:25 kooka python3[142981]:   from collections import MutableMapping
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Loaded default config
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Loaded arguments
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Starting Radicale
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] auth type is 'radicale.auth.htpasswd'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] storage type is 'etesync_dav.radicale.storage'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] rights type is 'etesync_dav.radicale.rights'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] web type is 'etesync_dav.radicale.web'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Listening on '[127.0.0.1]:37358'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Listening on '[::1]:37358'
Jan 20 16:45:25 kooka python3[142981]: [2022-01-20 16:45:25 +0100] [142981] [INFO] Radicale server ready
tasn commented 2 years ago

It means the token is invalid, you'd need to re-add the user.

stuart12 commented 2 years ago

I only have one user (me). Other new events are making their way from etesync on Android into Thunderbird (and etesync-web). There are just some events that never get into thunderbird. Some events that I create in thunderbird appear to vanish.

Reading contacts mostly works but not all the time. I have a script that with the -n flag downloads all my contacts and does a grep. I ran it twice in a row:

:; ring -n curo CRITICAL:root:download from http://localhost:37358/stuart/UJTtsaCwtea0Z4HxvDdf0e6fQ/ failed with 500 :; ring -n curo Vanny Curo, m 0450940956

stuart12 commented 2 years ago

I get the same error in the TbSync account manager: HTTP Error 500 but sometimes the sync works and I get the status OK. etesync-dav's log shows the same thing. Sometimes the sync works and sometimes it fails:

Jan 21 16:41:15 kooka python3[142981]: [2022-01-21 16:41:15 +0100] [142981/Thread-80] [INFO] PROPFIND request for '/stuart/OvKup7OiE7Dn4Fn7t31rog8u/' with depth '0' received from 127.0.0.1 using 'Mozilla/5.0 (X11; >
Jan 21 16:41:15 kooka python3[142981]: [2022-01-21 16:41:15 +0100] [142981/Thread-80] [INFO] Successful login: 'stuart'
Jan 21 16:41:16 kooka python3[142981]: [2022-01-21 16:41:16 +0100] [142981/Thread-2] [ERROR] Invalid token.
Jan 21 16:41:16 kooka python3[142981]: Traceback (most recent call last):
Jan 21 16:41:16 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/radicale/storage.py", line 84, in run
Jan 21 16:41:16 kooka python3[142981]:     etesync.sync()
Jan 21 16:41:16 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 90, in sync
Jan 21 16:41:16 kooka python3[142981]:     self.sync_collection_list()
Jan 21 16:41:16 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 104, in sync_collection_list
Jan 21 16:41:16 kooka python3[142981]:     col_list = col_mgr.list(COL_TYPES, fetch_options)
Jan 21 16:41:16 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etebase/__init__.py", line 247, in list
Jan 21 16:41:16 kooka python3[142981]:     return CollectionListResponse(self._inner.list_multi(list(col_type), _inner(fetch_options)))
Jan 21 16:41:16 kooka python3[142981]: etebase_python.Error: Invalid token.
Jan 21 16:41:16 kooka python3[142981]: [2022-01-21 16:41:16 +0100] [142981/Thread-80] [ERROR] An exception occurred during PROPFIND request on '/stuart/OvKup7OiE7Dn4Fn7t31rog8u/': Invalid token.
Jan 21 16:50:06 kooka python3[142981]: [2022-01-21 16:50:06 +0100] [142981/Thread-81] [INFO] PROPFIND request for '/stuart/' with depth '0' received from 127.0.0.1 using 'Thunderbird CalDAV/CardDAV'
Jan 21 16:50:06 kooka python3[142981]: [2022-01-21 16:50:06 +0100] [142981/Thread-81] [INFO] Access to '/stuart/' denied for anonymous user
Jan 21 16:50:06 kooka python3[142981]: [2022-01-21 16:50:06 +0100] [142981/Thread-81] [INFO] PROPFIND response status for '/stuart/' with depth '0' in 0.001 seconds: 401 Unauthorized
Jan 21 16:50:06 kooka python3[142981]: [2022-01-21 16:50:06 +0100] [142981/Thread-82] [INFO] PROPFIND request for '/stuart/' with depth '0' received from 127.0.0.1 using 'Thunderbird CalDAV/CardDAV'
Jan 21 16:50:06 kooka python3[142981]: [2022-01-21 16:50:06 +0100] [142981/Thread-82] [INFO] Successful login: 'stuart'
Jan 21 16:50:06 kooka python3[142981]: [2022-01-21 16:50:06 +0100] [142981/Thread-2] [ERROR] Invalid token.
Jan 21 16:50:06 kooka python3[142981]: Traceback (most recent call last):
Jan 21 16:50:06 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/radicale/storage.py", line 84, in run
Jan 21 16:50:06 kooka python3[142981]:     etesync.sync()
Jan 21 16:50:06 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 90, in sync
Jan 21 16:50:06 kooka python3[142981]:     self.sync_collection_list()
Jan 21 16:50:06 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etesync_dav/local_cache/__init__.py", line 104, in sync_collection_list
Jan 21 16:50:06 kooka python3[142981]:     col_list = col_mgr.list(COL_TYPES, fetch_options)
Jan 21 16:50:06 kooka python3[142981]:   File "/tmp/etesync-dav@stuart/.local/lib/python3.9/site-packages/etebase/__init__.py", line 247, in list
Jan 21 16:50:06 kooka python3[142981]:     return CollectionListResponse(self._inner.list_multi(list(col_type), _inner(fetch_options)))
Jan 21 16:50:06 kooka python3[142981]: etebase_python.Error: Invalid token.
Jan 21 16:50:06 kooka python3[142981]: [2022-01-21 16:50:06 +0100] [142981/Thread-82] [ERROR] An exception occurred during PROPFIND request on '/stuart/': Invalid token.
Jan 21 16:50:07 kooka python3[142981]: [2022-01-21 16:50:07 +0100] [142981/Thread-83] [INFO] PROPFIND request for '/stuart/' with depth '0' received from 127.0.0.1 using 'Thunderbird CalDAV/CardDAV'
Jan 21 16:50:07 kooka python3[142981]: [2022-01-21 16:50:07 +0100] [142981/Thread-83] [INFO] Access to '/stuart/' denied for anonymous user
Jan 21 16:50:07 kooka python3[142981]: [2022-01-21 16:50:07 +0100] [142981/Thread-83] [INFO] PROPFIND response status for '/stuart/' with depth '0' in 0.001 seconds: 401 Unauthorized
Jan 21 16:50:07 kooka python3[142981]: [2022-01-21 16:50:07 +0100] [142981/Thread-84] [INFO] PROPFIND request for '/stuart/' with depth '0' received from 127.0.0.1 using 'Thunderbird CalDAV/CardDAV'
Jan 21 16:50:07 kooka python3[142981]: [2022-01-21 16:50:07 +0100] [142981/Thread-84] [INFO] Successful login: 'stuart'
Jan 21 16:50:07 kooka python3[142981]: [2022-01-21 16:50:07 +0100] [142981/Thread-84] [INFO] PROPFIND response status for '/stuart/' with depth '0' in 0.002 seconds: 207 Multi-Status
Jan 21 16:50:07 kooka python3[142981]: [2022-01-21 16:50:07 +0100] [142981/Thread-85] [INFO] PROPFIND request for '/stuart/' with depth '1' received from 127.0.0.1 using 'Thunderbird CalDAV/CardDAV'
Jan 21 16:50:07 kooka python3[142981]: [2022-01-21 16:50:07 +0100] [142981/Thread-85] [INFO] Successful login: 'stuart'
stuart12 commented 2 years ago

I was getting synchronisation problems and strange errors:

Feb 17 16:44:31 kooka python3[442535]: /usr/lib/python3/dist-packages/vobject/base.py:736: DeprecationWarning: invalid escape sequence \-
Feb 17 16:44:31 kooka python3[442535]:   patterns['name'] = '[a-zA-Z0-9\-_]+'
Feb 17 16:44:31 kooka python3[442535]: /usr/lib/python3/dist-packages/vobject/base.py:1219: DeprecationWarning: invalid escape sequence \;
Feb 17 16:44:31 kooka python3[442535]:   s = s.replace("\\", "\\\\").replace(";", "\;").replace(",", "\,")
Feb 17 16:44:31 kooka python3[442535]: /usr/lib/python3/dist-packages/vobject/base.py:1219: DeprecationWarning: invalid escape sequence \,
Feb 17 16:44:31 kooka python3[442535]:   s = s.replace("\\", "\\\\").replace(";", "\;").replace(",", "\,")
Feb 17 16:46:16 kooka python3[442847]: [2022-02-17 16:46:16 +0100] [442847/Thread-3] [ERROR] An exception occurred during GET request on '/.web': cannot import name 'URLField' from 'wtforms' (/usr/lib/python3/dist-packages/wtforms/__init__.py)

They appear to have gone away now that I have added --ignore-installed to the pip3 install command. I did not have to re-add the user (myself). It appears that in Debian sid, some packaged python3.9 packages are not compatible with etesync-dav-0.32.1.