etesync-web icon indicating copy to clipboard operation
etesync-web copied to clipboard

etebase_python.Error: Invalid token

Open stuart12 opened this issue 2 years ago • 6 comments

hello, once again etesync-dav has started failing with Invalid token. Some updates get through but others fail and are lost. Any idea what is going on and how I can get etesync-dav working again?

Aug 09 21:01:49 kooka systemd[1]: Starting [email protected] - EteSync CalDAV and CardDAV front-end/proxy for stuart...
Aug 09 21:01:49 kooka etesync_dav-v0.31.2[295674]: EteSync DAV version:  0.31.2
Aug 09 21:01:49 kooka etesync_dav-v0.31.2[295674]: Radicale version:  3.0.3
Aug 09 21:01:49 kooka runuser[295679]: pam_unix(runuser:session): session opened for user stuart(uid=1000) by (uid=0)
Aug 09 21:01:49 kooka runuser[295679]: pam_unix(runuser:session): session closed for user stuart
Aug 09 21:01:49 kooka systemd[1]: Started [email protected] - EteSync CalDAV and CardDAV front-end/proxy for stuart.
Aug 09 21:01:50 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:50 +0200] [295692] [INFO] Loaded default config
Aug 09 21:01:50 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:50 +0200] [295692] [INFO] Loaded arguments
Aug 09 21:01:50 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:50 +0200] [295692] [INFO] Starting Radicale
Aug 09 21:01:50 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:50 +0200] [295692] [INFO] auth type is 'radicale.auth.htpasswd'
Aug 09 21:01:50 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:50 +0200] [295692] [INFO] storage type is 'etesync_dav.radicale.storage'
Aug 09 21:01:50 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:50 +0200] [295692] [INFO] rights type is 'etesync_dav.radicale.rights'
Aug 09 21:01:50 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:50 +0200] [295692] [INFO] web type is 'etesync_dav.radicale.web'
Aug 09 21:01:50 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:50 +0200] [295692] [INFO] Listening on '[127.0.0.1]:37358'
Aug 09 21:01:50 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:50 +0200] [295692] [INFO] Listening on '[::1]:37358'
Aug 09 21:01:50 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:50 +0200] [295692] [INFO] Radicale server ready
Aug 09 21:01:57 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:57 +0200] [295692/Thread-1] [INFO] GET request for '/stuart/UJTtsaCgCAwtea0Z4H/' received from ::1 using 'python-requests/2.28.1'
Aug 09 21:01:57 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:57 +0200] [295692/Thread-1] [INFO] Successful login: 'stuart'
Aug 09 21:01:57 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:57 +0200] [295692/Thread-2] [ERROR] Invalid token.
Aug 09 21:01:57 kooka etesync_dav-v0.31.2[295692]: Traceback (most recent call last):
Aug 09 21:01:57 kooka etesync_dav-v0.31.2[295692]:   File "etesync_dav/radicale/storage.py", line 84, in run
Aug 09 21:01:57 kooka etesync_dav-v0.31.2[295692]:   File "etesync_dav/local_cache/__init__.py", line 90, in sync
Aug 09 21:01:57 kooka etesync_dav-v0.31.2[295692]:   File "etesync_dav/local_cache/__init__.py", line 104, in sync_collection_list
Aug 09 21:01:57 kooka etesync_dav-v0.31.2[295692]:   File "etebase/__init__.py", line 247, in list
Aug 09 21:01:57 kooka etesync_dav-v0.31.2[295692]: etebase_python.Error: Invalid token.
Aug 09 21:01:57 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:01:57 +0200] [295692/Thread-1] [ERROR] An exception occurred during GET request on '/stuart/UJTtsaCgCAwt/': Invalid token.
Aug 09 21:02:23 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:02:23 +0200] [295692/Thread-3] [INFO] GET request for '/stuart/UJTtsaCgCAwtea0Z4HxvD/' received from ::1 using 'python-requests/2.28.1'
Aug 09 21:02:23 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:02:23 +0200] [295692/Thread-3] [INFO] Successful login: 'stuart'
Aug 09 21:02:24 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:02:24 +0200] [295692/Thread-3] [INFO] GET response status for '/stuart/UJTtsaCgCAwt/' in 1.020 seconds: 200 OK
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:02:36 +0200] [295692/Thread-4] [INFO] PROPFIND request for '/stuart/7bPP3rT6XhdBq/' with depth '0' received from 127.0.0.1 using 'Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Thunderbird/102.11.0'
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:02:36 +0200] [295692/Thread-5] [INFO] REPORT request for '/stuart/J_NqYOvK/' with depth '1' received from 127.0.0.1 using 'Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Thunderbird/102.11.0'
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:02:36 +0200] [295692/Thread-5] [INFO] Successful login: 'stuart'
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:02:36 +0200] [295692/Thread-4] [INFO] Successful login: 'stuart'
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]: [2023-08-09 21:02:36 +0200] [295692/Thread-2] [ERROR] Invalid token.
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]: Traceback (most recent call last):
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]:   File "etesync_dav/radicale/storage.py", line 84, in run
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]:   File "etesync_dav/local_cache/__init__.py", line 90, in sync
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]:   File "etesync_dav/local_cache/__init__.py", line 104, in sync_collection_list
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]:   File "etebase/__init__.py", line 247, in list
Aug 09 21:02:36 kooka etesync_dav-v0.31.2[295692]: etebase_python.Error: Invalid token.

stuart12 avatar Aug 09 '23 19:08 stuart12

I have restarted my etesync-dav (many times) and am still getting lots of

Aug 11 11:11:51 kooka etesync_dav-v0.31.2[847782]: [2023-08-11 11:11:51 +0200] [847782/Thread-10] [INFO] Successful login: 'stuart'
Aug 11 11:11:51 kooka etesync_dav-v0.31.2[847782]: [2023-08-11 11:11:51 +0200] [847782/Thread-3] [ERROR] Invalid token.
Aug 11 11:11:51 kooka etesync_dav-v0.31.2[847782]: Traceback (most recent call last):
Aug 11 11:11:51 kooka etesync_dav-v0.31.2[847782]:   File "etesync_dav/radicale/storage.py", line 84, in run
Aug 11 11:11:51 kooka etesync_dav-v0.31.2[847782]:   File "etesync_dav/local_cache/__init__.py", line 90, in sync
Aug 11 11:11:51 kooka etesync_dav-v0.31.2[847782]:   File "etesync_dav/local_cache/__init__.py", line 104, in sync_collection_list
Aug 11 11:11:51 kooka etesync_dav-v0.31.2[847782]:   File "etebase/__init__.py", line 247, in list
Aug 11 11:11:51 kooka etesync_dav-v0.31.2[847782]: etebase_python.Error: Invalid token.
Aug 11 11:11:51 kooka etesync_dav-v0.31.2[847782]: [2023-08-11 11:11:51 +0200] [847782/Thread-10] [ERROR] An exception occurred during REPORT request on '/stuart/7bPP3rT6XhdB/': Invalid token.

Where is this token stored? Is it in thunderbird, the etesync-dav process, on disk, on my self-hosted etesync server? What do I have to remove or restart to get a new valid token? Is the token used between thunderbird and etesync-dav or between etesync-dav and etesync?

stuart12 avatar Aug 11 '23 09:08 stuart12

In desperation, I tried removing the storedSession from etesync_creds but that made things worse with:

Aug 11 11:28:42 kooka etesync_dav-v0.31.2[848808]: [2023-08-11 11:28:42 +0200] [848808/Thread-3] [INFO] Successful login: 'stuart'
Aug 11 11:28:42 kooka etesync_dav-v0.31.2[848808]: [2023-08-11 11:28:42 +0200] [848808/Thread-3] [ERROR] An exception occurred during GET request on '/': 'authToken'

stuart12 avatar Aug 11 '23 09:08 stuart12

I tried removing the database and that just gave me the dreaded:

Aug 11 11:31:59 kooka etesync_dav-v0.31.2[848929]: [2023-08-11 11:31:59 +0200] [848929/Thread-7] [ERROR] An exception occurred during GET request on '/stuart/UJTtsaCgCAwtea0Z4/': <Model: CollectionEntity> instance matching query does not exist:
Aug 11 11:31:59 kooka etesync_dav-v0.31.2[848929]: SQL: SELECT "t1"."id", "t1"."local_user_id", "t1"."uid", "t1"."eb_col", "t1"."new", "t1"."dirty", "t1"."deleted", "t1"."stoken", "t1"."local_stoken" FROM "collectionentity" AS "t1" WHERE (("t1"."local_user_id" = ?) AND (("t1"."uid" = ?) AND NOT "t1"."deleted")) LIMIT ? OFFSET ?
Aug 11 11:31:59 kooka etesync_dav-v0.31.2[848929]: Params: [1, 'UJTtsaCgCAwtea0Z4HxvDdf0e6fANyaQ', 1, 0]

stuart12 avatar Aug 11 '23 09:08 stuart12

I thus disabled the etesync tasks and etesync calendar in thunderbird 102.11.0 before re-enabling etesync calendar. This gave me a new set of error messages:

Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]: [2023-08-11 11:37:00 +0200] [849038/Thread-44] [INFO] Successful login: 'stuart'
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]: [2023-08-11 11:37:00 +0200] [849038/Thread-38] [ERROR] database is locked
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]: Traceback (most recent call last):
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "peewee.py", line 2949, in execute_sql
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]: sqlite3.OperationalError: database is locked
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]: During handling of the above exception, another exception occurred:
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]: Traceback (most recent call last):
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "etesync_dav/radicale/storage.py", line 84, in run
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "etesync_dav/local_cache/__init__.py", line 92, in sync
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "etesync_dav/local_cache/__init__.py", line 157, in sync_collection
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "etesync_dav/local_cache/__init__.py", line 225, in push_collection
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "peewee.py", line 6199, in save
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "peewee.py", line 1785, in inner
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "peewee.py", line 1856, in execute
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "peewee.py", line 2320, in _execute
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "peewee.py", line 2962, in execute
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "peewee.py", line 2956, in execute_sql
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "peewee.py", line 2732, in __exit__
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "peewee.py", line 183, in reraise
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]:   File "peewee.py", line 2949, in execute_sql
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]: peewee.OperationalError: database is locked
Aug 11 11:37:00 kooka etesync_dav-v0.31.2[849038]: [2023-08-11 11:37:00 +0200] [849038/Thread-44] [ERROR] An exception occurred during REPORT request on '/stuart/J_NqYOvKup7OiE/': database is locked

but after these error messages the Invalid token errors have stopped and thunderbird is once again synchronising my calendar entries.

stuart12 avatar Aug 11 '23 09:08 stuart12

On another machine I got the above error message again so I upgraded to: Flask-3.1.1 Flask-WTF-1.2.2 PySocks-1.7.1 Radicale-3.2.3 appdirs-1.4.4 asn1crypto-1.5.1 blinker-1.9.0 certifi-2025.7.14 cffi-1.17.1 charset_normalizer-3.4.2 click-8.2.1 cryptography-45.0.5 defusedxml-0.7.1 etebase-0.31.8 etesync-0.12.1 etesync-dav-0.35.0 furl-2.1.4 idna-3.10 itsdangerous-2.2.0 jinja2-3.1.6 markupsafe-3.0.2 msgpack-1.1.1 orderedmultidict-1.0.1 packaging-25.0 passlib-1.7.4 peewee-3.18.2 pika-1.3.2 py-1.11.0 pyasn1-0.6.1 pycparser-2.22 pyparsing-3.2.3 python-dateutil-2.9.0.post0 pytz-2025.2 requests-2.32.4 six-1.17.0 urllib3-2.5.0 vobject-0.9.9 werkzeug-3.1.3 wtforms-3.2.1

But the Invalid token error still occurs. Any hints?

Jul 22 14:54:23 host etesync-dav[107448]: [107448/Thread-2] [ERROR] Invalid token.
                                            Traceback (most recent call last):
                                              File "/var/cache/etesync-dav@stuart/home/.local/lib/python3.12/site-packages/etesync_dav/radicale/storage.py", line 84, in run
                                                etesync.sync()
                                              File "/var/cache/etesync-dav@stuart/home/.local/lib/python3.12/site-packages/etesync_dav/local_cache/__init__.py", line 94, in sync
                                                self.sync_collection_list()
                                              File "/var/cache/etesync-dav@stuart/home/.local/lib/python3.12/site-packages/etesync_dav/local_cache/__init__.py", line 108, in sync_collection_list
                                                col_list = col_mgr.list(COL_TYPES, fetch_options)
                                                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                              File "/var/cache/etesync-dav@stuart/home/.local/lib/python3.12/site-packages/etebase/__init__.py", line 247, in list
                                                return CollectionListResponse(self._inner.list_multi(list(col_type), _inner(fetch_options)))
                                                                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                            etebase_python.Error: Invalid token.
Jul 22 14:54:23 host radicale[107448]: [107448/Thread-8 (process_request_thread)] [ERROR] An exception occurred during HEAD request on '/?????/???????????/': Invalid token.

stuart12 avatar Jul 22 '25 13:07 stuart12

I fixed the problem by deleting data/etesync_creds & data/htpasswd, recreating the etesync_dav user using http://localhost:37358/.web/, deleting the calendar from Thunderbird, and recreating the Thunderbird calendar using the new etesync_dav user. Note that some operations such as a simple dump of the calendar entries worked even when Thunderbird and Evolution were unable to download all of the calendar's entries.

stuart12 avatar Jul 22 '25 14:07 stuart12