etebase_python.Error: Invalid token

[stuart12]

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 etesync-dav@stuart.service - 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 etesync-dav@stuart.service - 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]

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]

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]

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]

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.