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.

Sign up for GitHub

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

Jump to bottom

etebase_python.Error: Invalid token #266

Open
stuart12 opened this issue Aug 9, 2023 · 4 comments
Open

etebase_python.Error: Invalid token #266

stuart12 opened this issue Aug 9, 2023 · 4 comments

Comments

@stuart12
Copy link

stuart12 commented Aug 9, 2023

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
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@stuart12