GNOME Bugzilla – Bug 761450
[CalDAV] Refresh expired OAuth2 token beforehand
Last modified: 2016-11-27 08:03:52 UTC
Hi, I've been recently noticed by my university that my computer was generating huge amount of DNS queries in their network. After investigation, we noticed that it was the calendar service of evolution-data-server which was generating hundreds of queries per second to a google server. After killing the process "evolution-calendar-factory" the queries stopped but started again after reboot. Since I removed my google account from the setting panel "Online accounts" the queries definitely stopped, but it's not a satisfying solution since I can't get the sync with my google account now. Please let me know if you need further informations. Thanks for your help !
Thanks for a bug report. You are right that it could do this, but I was never able to reproduce it myself, or reliably. Could you enable the Calendar part of the Online Accounts account, then run: $ CALDAV_DEBUG=all /usr/libexec/evolution-calendar-factory -w on a terminal and then watch it when it'll get insane again, please? I think it got in some odd state where it was unable to login to the server, but it was unable to give up (as it usually should after the second try), and it was repeating "indefinitely" with the wrong/none credentials. I do not want to see the whole log, only check which requests are repeating in it and whether the username and password are being passed to the server (eventually whether any WWW-Authenticate headers are passed towards the server).
Hi again, Thanks for your answer. In fact it goes insane directly after I enable the online account but regarding the logs from the command you given me it doesn't seem to go insane at all. What parts could be interesting for you ? What should I search for ? Something I find quite strange is that I'm trying to log with a google account and I repeatedly see "http://apple.com/ns/ical/" in the logs.
(In reply to Chida from comment #2) > In fact it goes insane directly after I enable the online account but > regarding the logs from the command you given me it doesn't seem to go > insane at all. > > What parts could be interesting for you ? What should I search for ? I guess there is some instantly repeating request for something on the server, which fails, but the code doesn't recognize it properly and tries once again, instead of failing. Thus anything what repeats constantly, aka what the backend tries to do at all. > Something I find quite strange is that I'm trying to log with a google > account and I repeatedly see "http://apple.com/ns/ical/" in the logs. That's correct, that's an XML namespace "name".
Created attachment 323083 [details] output of CALDAV_DEBUG=all /usr/libexec/evolution-calendar-factory -w Here is the output of the command CALDAV_DEBUG=all /usr/libexec/evolution-calendar-factory -w Hope it will help, it doesn't go insane after that there is no more output but it's still generating DNS requests.
Thanks for the update. If I understand this correctly: > it doesn't go insane after that there is no more output > but it's still generating DNS requests. then there is nothing new added in the log, but there is an ongoing flood of DNS queries anyway? I would expect that the calendar server would generate it only together with the server touching. Unless it's related to an online/offline checking. Maybe. How did you notice the DNS queries, please? I'm not so good in networking debugging, I'm sorry. I can understand that by killing the process the flood might stop, though it might not necessary be the right cause. It can also be that goa-daemon got into some odd state. If you let the calendars finish its update after start, and then kill the goa-daemon process (other parts of the system might get unhappy due to it, eventually auto-restart it), will the DNS flood stop too? The difference is that you'll kill the goa-daemon, instead of the evolution-calendar-factory. I'd still prefer to be able to debug the DNS queries and eventually identify the root cause of this and fix it, on whichever side it'll be.
> Thanks for the update. If I understand this correctly: > > > it doesn't go insane after that there is no more output > > but it's still generating DNS requests. > > then there is nothing new added in the log, but there is an ongoing flood of > DNS queries anyway? I would expect that the calendar server would generate > it only together with the server touching. Unless it's related to an > online/offline checking. Maybe. Yes it's exactly what is happening > How did you notice the DNS queries, please? I'm not so good in networking > debugging, I'm sorry. I can understand that by killing the process the flood > might stop, though it might not necessary be the right cause. Mhh it's the Administrator of network of the university where I'm working who noticed that my computer was generating thousands of DNS queries. Then I used dnstop to check how many queries my computer was producing. With wireshark I also checked for dns queries and I noticed they were heading for a google server. So I deduced It was linked to evolution and then searched which process was responsible of it by killing some processes to see if it was stopping the flood or not. > It can also be that goa-daemon got into some odd state. If you let the > calendars finish its > update after start, and then kill the goa-daemon process (other parts of the > system might get unhappy due to it, eventually auto-restart it), will the > DNS flood stop too? The difference is that you'll kill the goa-daemon, > instead of the evolution-calendar-factory. You are right I tried to kill the goa-daemon and it is also stopping the flood. So maybe it's not coming from the evolution-calendar-factory after all ?
Okay, now that I killed goa-daemon, I don't know what exactly happend, but the problem seems to be resolved ?! Dns queries are back to normal even after a reboot.
(In reply to Chida from comment #7) > Dns queries are back to normal even after a reboot. It can be a coincident. The things work this way: a) you configure a new GOA account for Google services b) the GOA account has stored an OAuth2 token in keyring c) any application (which depends what parts you keep enabled in the GOA) can ask GOA for the OAuth2 token. Like with the calendar, it's the calendar backend which asks GOA for the token. d) (I do not develop GOA, thus this is more of "as I heard" than "as I know") when the application asks for the OAuth2 token, the GOA talks to the Google server and refreshes the token. e) the problem is that GOA does that for each single calendar, mail account... Thus even if you open 3 calendar at a very short delay between it, the GOA talks to the Google server 3 times. That can cause timeouts eventually, which I've got with one ownCloud server where I had configured more than 10 different sources (Calendars, Tasks and Memos). I've no idea what exactly could cause GOA to behave oddly. I know that the CalDAV calendar backend could do asimilar thing, that's why i asked for the calendar factory log, because there could be shown this odd behaviour, exhibited by repeated server requests and (possibly) failed responses. What I know is that Rishi made some changes for the upcoming GOA 3.20.0 which try to address the possible timeouts. Whether it'll have any influence on the issue you were experiencing I do not know.
(In reply to Milan Crha from comment #8) > e) the problem is that GOA does that for each single calendar, mail > account... > Thus even if you open 3 calendar at a very short delay between it, the GOA > talks to the Google server 3 times. That can cause timeouts eventually, > which I've got with one ownCloud server where I had configured more than > 10 > different sources (Calendars, Tasks and Memos). > > [snip] > > What I know is that Rishi made some changes for the upcoming GOA 3.20.0 > which try to address the possible timeouts. Whether it'll have any influence > on the issue you were experiencing I do not know. That is bug 751524 The patches should already be in gnome-online-accounts-3.18.3 and 3.16.5. Which version are you using?
I'm currently using version 3.18.4-1.fc23 but perhaps it has been updated in between and the bug held from an ancient version, I don't know.
(In reply to Milan Crha from comment #8) > d) (I do not develop GOA, thus this is more of "as I heard" than "as I know") > when the application asks for the OAuth2 token, the GOA talks to the > Google server and refreshes the token. It depends on the method used by the application. If you call goa_oauth2_based_call_get_access_token then it will give you the access token from the keyring without hitting the network. If you call goa_account_call_ensure_credentials then it will use the network to verify that the credentials in the keyring actually work, and, in case of OAuth2 tokens, try to refresh them. > e) the problem is that GOA does that for each single calendar, mail > account... > Thus even if you open 3 calendar at a very short delay between it, the GOA > talks to the Google server 3 times. That can cause timeouts eventually, > which I've got with one ownCloud server where I had configured more than 10 > different sources (Calendars, Tasks and Memos). These days (ie. since 3.16.x or bug 751524) GOA will coalesce pending goa_account_call_ensure_credentials calls against the same account and use the network only once. The logs should reflect this. See https://wiki.gnome.org/Projects/GnomeOnlineAccounts/Debugging
As far as I can tell, this issue is caused by an error returned from the server: > Daily Limit Exceeded. The quota will be reset at midnight Pacific Time (PT). > You may monitor your quota usage and adjust limits in the API Console: > https://console.developers.google.com/apis/api/caldav/quotas?project=923794261470 which the Google server denotes as a 403 Forbidden error, thus it's pretty hard to recognize ordinary Forbidden with this "temporary" Forbidden, without looking into the returned content. I wish they use a different status code that 403 in this case. Anyway, I fixed this with the below change. It was enough to use the first chunk only (thus basically a one-liner), but I also added some "try to guess the error message and propagate it into the UI" code, which will help to identify the issue more easily. As it contain the new translatable string, then it's for the development version only. Created commit 24b3f04 in eds master (3.21.91+)
Thanks for figuring it out, Milan!
*** Bug 770265 has been marked as a duplicate of this bug. ***
I was notified that this is still not the best solution and I admit it really isn't, because it doesn't fix the real cause. I received a log where an OAuth2 calendar tried to talk to the Google server without the OAuth2 header, which leads to a 401 or 403 responses from the server, and after several tries even the "Daily Limit Exceeded" issue. The cause of this that the OAuth2 token expired, but it was not refreshed properly. As it was expired, it was not used and the bad things happened. I made the CalDAV code properly refresh the OAuth2 token when it is expired, before any communication to the server is done, thus there is no 401 or 403 with the OAuth2. The "easiest" reproducer was to setup an hour refresh internal on the calendar and then leave it idle. The tokens are granted for approximately 56 minutes, thus after the hour the token is expired and it was not used. Created commit 3fa36f8 in eds master (3.21.92+)
I'm seeing this (on debian testing) with goa-daemon 3.22 (and evolution-data-server 3.22.0-2), exactly the same symptoms. Dumping dns I see lots of queries for www.googleapis.com. Stopping the calendar syncing stops this query flood. % CALDEV_DEBUG=all /usr/lib/evolution/evolution-calendar-factory -w does not output anything during this.
Commit 3fa36f8 is in that code btw.
(In reply to Miek Gieben from comment #16) > I'm seeing this (on debian testing) with goa-daemon 3.22 (and > evolution-data-server 3.22.0-2), exactly the same symptoms. Thanks for the notice. I currently track the issue in bug #771547. Even it mentions "internal google auth", it will address GOA accounts as well. > % CALDEV_DEBUG=all /usr/lib/evolution/evolution-calendar-factory -w > > does not output anything during this. Right, it's due to a typo, you named it CALDEV instead of CALDAV (use 'A' instead of 'E' in that part). :) But no need to capture the log, it'll be full of requests against the google server with no Bearer authentication header with an immediate response from the server that some daily limit had been reached and the login is disabled for some time.