Sometimes account reauthentication never finishes

Bug #1405651 reported by Niklas Wenzel on 2014-12-25
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
account-polld (Ubuntu)
Undecided
Niklas Wenzel
account-polld (Ubuntu RTM)
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) on 2014-12-25
Changed in account-polld (Ubuntu):
assignee: nobody → Niklas Wenzel (nikwen)
Niklas Wenzel (nikwen) on 2014-12-28
Changed in account-polld (Ubuntu):
status: New → In Progress
Niklas Wenzel (nikwen) on 2015-04-15
Changed in account-polld (Ubuntu):
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers