Sometimes account reauthentication never finishes

Bug #1405651 reported by Niklas Wenzel
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
account-polld (Ubuntu)
Fix Released
Undecided
Niklas Wenzel
account-polld (Ubuntu RTM)
New
Undecided
Unassigned

Bug Description

Sometimes account reauthentication never finishes for one account. As a result, account-polld blocks for all accounts and only polls the other accounts once again.
Looking at the logs, the info->watcher->callback() call in accounts/account-watcher.c seems to be blocking forever.
http://bazaar.launchpad.net/~ubuntu-push-hackers/account-polld/trunk/view/head:/accounts/account-watcher.c#L114

Excerpt from the logs:

2014/12/23 09:19:15 Received Poll()
2014/12/23 09:19:15 Starting poll for account 3
2014/12/23 09:19:15 Starting poll for account 2
2014/12/23 09:19:15 Poll for account 2 was successful
2014/12/23 09:19:15 Ending poll for account 2
2014/12/23 09:19:15 Starting poll for account 4
2014/12/23 09:19:15 Polling account 3
2014/12/23 09:19:15 Polling account 2
2014/12/23 09:19:15 Polling account 4
2014/12/23 09:19:15 Error while polling 4: Token expired
2014/12/23 09:19:15 Poll for account 4 has failed: Token expired
2014/12/23 09:19:15 Ending poll for account 4
2014/12/23 09:19:15 Error while polling 2: Token expired
2014/12/23 09:19:15 Error while polling 3: Token expired
2014/12/23 09:19:15 Poll for account 3 has failed: Token expired
2014/12/23 09:19:15 Ending poll for account 3
2014/12/23 09:19:16 New account data for existing account with id 3
2014/12/23 09:19:21 New account data for existing account with id 4
2014/12/23 09:24:20 Received Poll()
2014/12/23 09:24:20 Leaving poll for account 4 as penaly count is 1
2014/12/23 09:24:20 Leaving poll for account 3 as penaly count is 1
2014/12/23 09:32:25 Received Poll()

[Nothing after this line until a reboot]

Here's an excerpt from the logs which contains debug output added by me (https://code.launchpad.net/~nikwen/account-polld/fixes-test) as well as some other changes:

2014/12/13 14:53:18 Received Poll()
2014/12/13 14:53:18 Received signal from pollChan
2014/12/13 14:53:18 Starting poll for account 4
2014/12/13 14:53:18 Starting poll for account 2
2014/12/13 14:53:18 Starting poll for account 3
2014/12/13 14:53:18 Polling account 4
2014/12/13 14:53:18 Polling account 2
2014/12/13 14:53:18 Polling account 3
2014/12/13 14:53:18 Error while polling 3: Token expired
Account: Refresh
Account: Login in refresh cb
Account: Info clear
Starting authentication session for account 3
2014/12/13 14:53:18 Poll for account 3 has failed: Token expired
Account: Set up auth session successfully
Account: NULL checks
Account: auth_data 0
Account: error 1
Account: info 0
Account: info->session 0
Account: info->auth_params 0
Account: ag_auth_data_get_mechanism(auth_data) 0
Account: account_info_login_cb 0
Account: Started async auth session process
2014/12/13 14:53:18 Ending poll for account 3
2014/12/13 14:53:18 Error while polling 4: Token expired
Account: Refresh
Account: Login in refresh cb
Account: Info clear
2014/12/13 14:53:18 Poll for account 4 has failed: Token expired
2014/12/13 14:53:18 Ending poll for account 4
Starting authentication session for account 4
Account: Set up auth session successfully
Account: NULL checks
Account: auth_data 0
Account: error 1
Account: info 0
Account: info->session 0
Account: info->auth_params 0
Account: ag_auth_data_get_mechanism(auth_data) 0
Account: account_info_login_cb 0
Account: Started async auth session process
2014/12/13 14:53:19 Account 2 has 0 gmail updates to report
2014/12/13 14:53:19 Poll for account 2 was successful
2014/12/13 14:53:19 Ending poll for account 2
2014/12/13 14:53:19 Previous messages: []string{}
Authentication for account 4 complete
Account: Notify
Account: Notify => Callback call done
Account: Very end of login cb
2014/12/13 14:53:20 New account data for existing account with id 4
2014/12/13 14:53:20 Starting poll for account 4
2014/12/13 14:53:20 Polling account 4
2014/12/13 14:53:21 Account 4 has 0 gmail updates to report
2014/12/13 14:53:21 Poll for account 4 was successful
2014/12/13 14:53:21 Ending poll for account 4
2014/12/13 14:53:21 Previous messages: []string{}
2014/12/13 14:58:24 Received Poll()
2014/12/13 14:58:24 Received signal from pollChan
2014/12/13 14:58:24 Starting poll for account 4
2014/12/13 14:58:24 Starting poll for account 2
2014/12/13 14:58:24 Polling account 4
2014/12/13 14:58:24 Polling account 2
Authentication for account 3 complete
Account: Notify
2014/12/13 14:58:25 Account 4 has 0 gmail updates to report
2014/12/13 14:58:25 Poll for account 4 was successful
2014/12/13 14:58:25 Ending poll for account 4
2014/12/13 14:58:25 Previous messages: []string{}
QSocketNotifier: Can only be used with threads started with QThread
QSocketNotifier: Can only be used with threads started with QThread
2014/12/13 14:58:54 Poll for account 2 has timed out out after 30s
2014/12/13 14:58:54 Ending poll for account 2
2014/12/13 15:06:29 Received Poll()

[Nothing after this line until a reboot]

Related branches

Niklas Wenzel (nikwen)
Changed in account-polld (Ubuntu):
assignee: nobody → Niklas Wenzel (nikwen)
Niklas Wenzel (nikwen)
Changed in account-polld (Ubuntu):
status: New → In Progress
Niklas Wenzel (nikwen)
Changed in account-polld (Ubuntu):
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.