vdirsyncer
vdirsyncer copied to clipboard
pimutils
Ocassionally, google backend fail
I've a cron on two machines that syncs all my calendars, including a single google calendar one:
0 * * * * chronic vdirsyncer -v DEBUG sync
For some reason, I get a few emails a day for 401 errors. The odd thing is:
- Which machine fails varies.
- They fail only from time to time.
The full debug output is here.
My configuration:
[general]
status_path = "~/.local/share/vdirsyncer/status/"
##### Contacts ######
[pair contacts]
a = "contacts_local"
b = "contacts_fastmail"
collections = null
metadata = []
conflict_resolution = ["command", "vimdiff"]
[storage contacts_local]
type = "filesystem"
path = "~/.local/share/contacts/cards/"
fileext = ".vcf"
[storage contacts_fastmail]
type = "carddav"
url = "https://carddav.messagingengine.com/dav/addressbooks/user/[email protected]/Default/"
username = "[email protected]"
password.fetch = ["command", "~/.local/bin/vdirsyncer-pass", "fastmail:carddav"]
##### Calendars ######
[pair calendars]
a = "calendars_local"
b = "calendars_fastmail"
collections = ["from b"]
metadata = ["color", "displayname"]
conflict_resolution = ["command", "vimdiff"]
[storage calendars_local]
type = "filesystem"
path = "~/.local/share/calendars/"
fileext = ".ics"
[storage calendars_fastmail]
type = "caldav"
url = "https://caldav.messagingengine.com/"
username = "[email protected]"
password.fetch = ["command", "~/.local/bin/vdirsyncer-pass", "fastmail:caldav"]
##### Work Calendars #####
[pair work_calendars]
a = "calendars_local"
b = "calendars_google"
collections = ["[email protected]"]
metadata = ["color", "displayname"]
conflict_resolution = ["command", "vimdiff"]
[storage calendars_google]
type = "google_calendar"
token_file = "~/.cache/vdirsyncer/google.token"
client_id = "1066339489224-5v10lce8q2i7d4ivo441bjus5d3178uu.apps.googleusercontent.com"
client_secret = "REDACTED"
I can't do anything against that though. Best I can recommend is to wrap vdirsyncer with a retry-script
I do think so, I can't imagine why we would send invalid auth headers sometimes. Also we let oauthlib handle all that, and that library is pretty popular.
If you manage to dump raw traffic (particularly auth headers), perhaps this will be easier. I think mitmproxy has a logging mode as well?
That's really hard, because of how timed apart the failures are. I just ran this:
for i in $(seq 1 50); do vdirsyncer sync work_calendars; done;
And all 50 tried worked fine. :(
I'll try and leave that on both computers at some point if I'm out for the weekend or something.
Okay, so I finally had the time to leave mitm running, and vdirsyncer debugging:
Debug output:
debug: Using 1 maximal workers.
Syncing work_calendars/[email protected]
debug: PROPFIND https://apidata.googleusercontent.com/caldav/v2/hbarrera%40shiftgig.com/events/
debug: {'User-Agent': '1066339489224-5v10lce8q2i7d4ivo441bjus5d3178uu.apps.googleusercontent.com', 'Content-Type': 'application/xml; charset=UTF-8', 'Depth': '1'}
debug: <?xml version="1.0" encoding="utf-8" ?>
debug: <D:propfind xmlns:D="DAV:">
debug: <D:prop>
debug: <D:resourcetype/>
debug: <D:getcontenttype/>
debug: <D:getetag/>
debug: </D:prop>
debug: </D:propfind>
debug:
debug: Sending request...
debug: 401
debug: {'Vary': 'Origin, X-Origin', 'WWW-Authenticate': 'Bearer realm="https://accounts.google.com/", error=invalid_token', 'Content-Type': 'application/vnd.google.gdata.error+xml; charset=UTF-8', 'Content-Encoding': 'gzip', 'Date': 'Sun, 02 Apr 2017 18:00:03 GMT', 'Expires': 'Sun, 02 Apr 2017 18:00:03 GMT', 'Cache-Control': 'private, max-age=0', 'X-Content-Type-Options': 'nosniff', 'X-Frame-Options': 'SAMEORIGIN', 'X-XSS-Protection': '1; mode=block', 'Server': 'GSE', 'Alt-Svc': 'quic=":443"; ma=2592000; v="37,36,35"', 'Transfer-Encoding': 'chunked'}
debug: <?xml version="1.0" encoding="UTF-8"?>
debug: <errors xmlns="http://schemas.google.com/g/2005">
debug: <error>
debug: <domain>GData</domain>
debug: <code>authError</code>
debug: <location type="header">Authorization</location>
debug: <internalReason>Invalid Credentials</internalReason>
debug: </error>
debug: </errors>
/usr/lib/python3.6/site-packages/urllib3/connectionpool.py:852: InsecureRequestWarning: Unverified HTTPS request is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings
InsecureRequestWarning)
error: Unknown error occured for work_calendars/[email protected]: 401 Client Error: Unauthorized for url: https://apidata.googleusercontent.com/caldav/v2/hbarrera%40shiftgig.com/events/
error: Use `-vdebug` to see the full traceback.
debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/cli/tasks.py", line 69, in sync_collection
debug: partial_sync=pair.partial_sync
debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/sync.py", line 561, in sync
debug: b_nonempty = b_info.prepare_new_status()
debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/sync.py", line 472, in prepare_new_status
debug: for href, etag in self.storage.list():
debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/storage/dav.py", line 801, in list
debug: for x in DAVStorage.list(self):
debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/storage/dav.py", line 609, in list
debug: headers=headers)
debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/storage/dav.py", line 358, in request
debug: return http.request(method, url, session=self._session, **more)
debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/http.py", line 183, in request
debug: r.raise_for_status()
debug: File "/usr/lib/python3.6/site-packages/requests/models.py", line 909, in raise_for_status
debug: raise HTTPError(http_error_msg, response=self)
error: 1 out of 2 tasks failed.
Request:
PROPFIND /caldav/v2/hbarrera%40shiftgig.com/events/ HTTP/1.1
Host: apidata.googleusercontent.com
User-Agent: 1066339489224-5v10lce8q2i7d4ivo441bjus5d3178uu.apps.googleusercontent.com
Accept-Encoding: gzip, deflate
Accept: */*
Connection: keep-alive
Content-Type: application/xml; charset=UTF-8
Depth: 1
Authorization: Bearer ya29.G[REDACTED]-A
Content-Length: 280
<?xml version="1.0" encoding="utf-8" ?>
<D:propfind xmlns:D="DAV:">
<D:prop>
<D:resourcetype/>
<D:getcontenttype/>
<D:getetag/>
</D:prop>
</D:propfind>
Response:
HTTP/1.1 401 Unauthorized
Vary: Origin
Vary: X-Origin
WWW-Authenticate: Bearer realm="https://accounts.google.com/", error=invalid_token
Content-Type: application/vnd.google.gdata.error+xml; charset=UTF-8
Date: Sun, 02 Apr 2017 18:00:03 GMT
Expires: Sun, 02 Apr 2017 18:00:03 GMT
Cache-Control: private, max-age=0
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-XSS-Protection: 1; mode=block
Server: GSE
Alt-Svc: quic=":443"; ma=2592000; v="37,36,35"
Transfer-Encoding: chunked
content-length: 209
111
<?xml version="1.0" encoding="UTF-8"?>
<errors xmlns="http://schemas.google.com/g/2005">
<error>
<domain>GData</domain>
<code>authError</code>
<location type="header">Authorization</location>
<internalReason>Invalid Credentials</internalReason>
</error>
</errors>
0
Running vdirsyncer sync again a moment later works fine.
My cron runs hourly; is it possible that when running, it doesn't see the token as expires, uses it, but it expires while on-the-wire (it lasts EXACTLY an hour)?
Oh, BTW, I applied this diff to use mitmproxy (in case you see the above warning):
--- a/vdirsyncer/storage/google.py
+++ b/vdirsyncer/storage/google.py
@@ -35,7 +35,9 @@ class GoogleSession(dav.DAVSession):
self.url = url
self.useragent = client_id
- self._settings = {}
+ self._settings = {
+ 'verify': False,
+ }
if not have_oauth2:
raise exceptions.UserError('requests-oauthlib not installed')
Please try changing your cron interval config to something else (every 40 mins?) to see if your suspicion is true
On Sun, Apr 02, 2017 at 11:17:08AM -0700, Hugo Osvaldo Barrera wrote:
Okay, so I finally had the time to leave
mitmrunning, and vdirsyncer debugging:Debug output:
debug: Using 1 maximal workers. Syncing work_calendars/[email protected] debug: PROPFIND https://apidata.googleusercontent.com/caldav/v2/hbarrera%40shiftgig.com/events/ debug: {'User-Agent': '1066339489224-5v10lce8q2i7d4ivo441bjus5d3178uu.apps.googleusercontent.com', 'Content-Type': 'application/xml; charset=UTF-8', 'Depth': '1'} debug: <?xml version="1.0" encoding="utf-8" ?> debug: <D:propfind xmlns:D="DAV:"> debug: <D:prop> debug: <D:resourcetype/> debug: <D:getcontenttype/> debug: <D:getetag/> debug: </D:prop> debug: </D:propfind> debug: debug: Sending request... debug: 401 debug: {'Vary': 'Origin, X-Origin', 'WWW-Authenticate': 'Bearer realm="https://accounts.google.com/", error=invalid_token', 'Content-Type': 'application/vnd.google.gdata.error+xml; charset=UTF-8', 'Content-Encoding': 'gzip', 'Date': 'Sun, 02 Apr 2017 18:00:03 GMT', 'Expires': 'Sun, 02 Apr 2017 18:00:03 GMT', 'Cache-Control': 'private, max-age=0', 'X-Content-Type-Options': 'nosniff', 'X-Frame-Options': 'SAMEORIGIN', 'X-XSS-Protection': '1; mode=block', 'Server': 'GSE', 'Alt-Svc': 'quic=":443"; ma=2592000; v="37,36,35"', 'Transfer-Encoding': 'chunked'} debug: <?xml version="1.0" encoding="UTF-8"?> debug: <errors xmlns="http://schemas.google.com/g/2005"> debug: <error> debug: <domain>GData</domain> debug: <code>authError</code> debug: <location type="header">Authorization</location> debug: <internalReason>Invalid Credentials</internalReason> debug: </error> debug: </errors> /usr/lib/python3.6/site-packages/urllib3/connectionpool.py:852: InsecureRequestWarning: Unverified HTTPS request is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings InsecureRequestWarning) error: Unknown error occured for work_calendars/[email protected]: 401 Client Error: Unauthorized for url: https://apidata.googleusercontent.com/caldav/v2/hbarrera%40shiftgig.com/events/ error: Use `-vdebug` to see the full traceback. debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/cli/tasks.py", line 69, in sync_collection debug: partial_sync=pair.partial_sync debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/sync.py", line 561, in sync debug: b_nonempty = b_info.prepare_new_status() debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/sync.py", line 472, in prepare_new_status debug: for href, etag in self.storage.list(): debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/storage/dav.py", line 801, in list debug: for x in DAVStorage.list(self): debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/storage/dav.py", line 609, in list debug: headers=headers) debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/storage/dav.py", line 358, in request debug: return http.request(method, url, session=self._session, **more) debug: File "/usr/lib/python3.6/site-packages/vdirsyncer/http.py", line 183, in request debug: r.raise_for_status() debug: File "/usr/lib/python3.6/site-packages/requests/models.py", line 909, in raise_for_status debug: raise HTTPError(http_error_msg, response=self) error: 1 out of 2 tasks failed.Request:
PROPFIND /caldav/v2/hbarrera%40shiftgig.com/events/ HTTP/1.1 Host: apidata.googleusercontent.com User-Agent: 1066339489224-5v10lce8q2i7d4ivo441bjus5d3178uu.apps.googleusercontent.com Accept-Encoding: gzip, deflate Accept: */* Connection: keep-alive Content-Type: application/xml; charset=UTF-8 Depth: 1 Authorization: Bearer ya29.G[REDACTED]-A Content-Length: 280 <?xml version="1.0" encoding="utf-8" ?> <D:propfind xmlns:D="DAV:"> <D:prop> <D:resourcetype/> <D:getcontenttype/> <D:getetag/> </D:prop> </D:propfind>Response:
HTTP/1.1 401 Unauthorized Vary: Origin Vary: X-Origin WWW-Authenticate: Bearer realm="https://accounts.google.com/", error=invalid_token Content-Type: application/vnd.google.gdata.error+xml; charset=UTF-8 Date: Sun, 02 Apr 2017 18:00:03 GMT Expires: Sun, 02 Apr 2017 18:00:03 GMT Cache-Control: private, max-age=0 X-Content-Type-Options: nosniff X-Frame-Options: SAMEORIGIN X-XSS-Protection: 1; mode=block Server: GSE Alt-Svc: quic=":443"; ma=2592000; v="37,36,35" Transfer-Encoding: chunked content-length: 209 111 <?xml version="1.0" encoding="UTF-8"?> <errors xmlns="http://schemas.google.com/g/2005"> <error> <domain>GData</domain> <code>authError</code> <location type="header">Authorization</location> <internalReason>Invalid Credentials</internalReason> </error> </errors> 0Running
vdirsyncer syncagain a moment later works fine.My cron runs hourly; is it possible that when running, it doesn't see the token as expires, uses it, but it expires while on-the-wire (it lasts EXACTLY an hour)?
Oh, BTW, I applied this diff to use
mitmproxy(in case you see the above warning):--- a/vdirsyncer/storage/google.py +++ b/vdirsyncer/storage/google.py @@ -35,7 +35,9 @@ class GoogleSession(dav.DAVSession): self.url = url self.useragent = client_id - self._settings = {} + self._settings = { + 'verify': False, + } if not have_oauth2: raise exceptions.UserError('requests-oauthlib not installed')-- You are receiving this because you commented. Reply to this email directly or view it on GitHub: https://github.com/pimutils/vdirsyncer/issues/575#issuecomment-291004121
I did exactly that on one machine (well, 20 minutes), and left it at an hour in another.
The hourly one failed almost every time, the other didn't fail once.
It looks like my suspicion is correct, and running exactly at the time of expiration might make the token expire after being read but before being received by google.
We should probably renew it slight before it's expiration to avoid this.
Could you try patching oauthlib (or changing expiration times in your token file before executing vdirsyncer) to see if this fixes things? Another possible problem is a skewed clock on your system.
Another thing is that oauthlib appears to be using "one hour" as some sort of default value. Perhaps this applies here. Could you do the auth dance (deleting the token file before) and capture it with mitmproxy?
Otherwise this might very well be a conceptual problem in oauthlib, i.e. oauthlib unrealistically assumes a perfect system clock.
On Tue, Apr 04, 2017 at 05:32:15AM -0700, Hugo Osvaldo Barrera wrote:
I did exactly that on one machine (well, 20 minutes), and left it at an hour in another.
The hourly one failed almost every time, the other didn't fail once.
It looks like my suspicion is correct, and running exactly at the time of expiration might make the token expire after being read but before being received by google.
We should probably renew it slight before it's expiration to avoid this.
-- You are receiving this because you commented. Reply to this email directly or view it on GitHub: https://github.com/pimutils/vdirsyncer/issues/575#issuecomment-291485192
So I haven't forgotten about this: quite the contrary, I'm still suffering it. After I set my laptop and desktop to sync every 20 minutes, the errors started again. I now set one to do an hourly cron and the other to do it every 20-minutes. It's working. EXTREMELY odd. It looks like two clients can't connect for the same user at the same time, but I'll keep experimenting with this extreme quirkyness.
It's also possible that they're all very frequent failures that are driving me mad and I'm just seeing patterns where there aren't any.
I have the same issue, a crontab running every 1 hour but it failed approximately 1 time every day.
