Merge lp:~nikwen/account-polld/authenticate-again-fix into lp:~ubuntu-push-hackers/account-polld/trunk

[Niklas Wenzel]

When an account fails to authenticate once (e.g. when there is no network connection after booting), it needs to try to login again afterwards.

Currently the old error permanently prevents it from trying again as a.authData.Error != nil, which makes the poll() function exit immediately. Therefore, that flag needs to be reset to make the account authenticate again afterwards.

This MP also prevents the info->watcher->callback() call in accounts/account-watcher.c from blocking (LP: #1405651) by not polling the account if the new token hasn't been loaded yet.

Excerpt from the logs:

2014/10/19 17:23:15 Received Poll()
2014/10/19 17:23:15 Leaving poll for account 3 as penaly count is 1
2014/10/19 17:23:15 Starting poll for account 4
2014/10/19 17:23:15 Polling account 4
2014/10/19 17:23:15 Account 4 failed to authenticate: GDBus.Error:com.google.code.AccountsSSO.SingleSignOn.Error.NoConnection: Host accounts.google.com not found
2014/10/19 17:23:45 Poll for account 4 has timed out out after 30s
2014/10/19 17:23:45 Ending poll for account 4
2014/10/19 17:28:50 Received Poll()
2014/10/19 17:28:50 Starting poll for account 3
2014/10/19 17:28:50 Leaving poll for account 4 as penaly count is 1
2014/10/19 17:28:50 Polling account 3
2014/10/19 17:28:50 Account 3 failed to authenticate: GDBus.Error:com.google.code.AccountsSSO.SingleSignOn.Error.NoConnection: Host accounts.google.com not found
2014/10/19 17:29:20 Poll for account 3 has timed out out after 30s
2014/10/19 17:29:20 Ending poll for account 3
2014/10/19 17:34:25 Received Poll()
2014/10/19 17:34:25 Leaving poll for account 3 as penaly count is 1
2014/10/19 17:34:25 Starting poll for account 4
2014/10/19 17:34:25 Polling account 4
2014/10/19 17:34:25 Account 4 failed to authenticate: GDBus.Error:com.google.code.AccountsSSO.SingleSignOn.Error.NoConnection: Host accounts.google.com not found
2014/10/19 17:34:55 Poll for account 4 has timed out out after 30s
2014/10/19 17:34:55 Ending poll for account 4
2014/10/19 17:40:00 Received Poll()
2014/10/19 17:40:00 Starting poll for account 3
2014/10/19 17:40:00 Leaving poll for account 4 as penaly count is 1
2014/10/19 17:40:00 Polling account 3
2014/10/19 17:40:00 Account 3 failed to authenticate: GDBus.Error:com.google.code.AccountsSSO.SingleSignOn.Error.NoConnection: Host accounts.google.com not found
2014/10/19 17:40:30 Poll for account 3 has timed out out after 30s
2014/10/19 17:40:30 Ending poll for account 3

[John Lenton (chipaca)]

I'm not understanding how this fixes the issue you purport it to. Care to explain?

What it does is carry on a single poll even if auth fails. If this works for you, we're doing something wrong.

review: Needs Information

[Niklas Wenzel (nikwen)]

Hi,

Of course, I can explain what this fix does. Let's have a look at what the current code in trunk does.

In the Poll() function it checks whether the account should be polled based on whether auth data is given, based on whether the application is blacklisted and based on the current penalty count. (http://bazaar.launchpad.net/~ubuntu-push-hackers/account-polld/trunk/view/99/cmd/account-polld/account_manager.go#L64)

If those tests pass (which is what they do in my log file), the poll() function is called. (http://bazaar.launchpad.net/~ubuntu-push-hackers/account-polld/trunk/view/99/cmd/account-polld/account_manager.go#L109)
It outputs "Polling account <account-number>" and checks whether the appropriate click package for the account type (e.g. the Gmail webapp) is installed and if it's not, it aborts polling.
The next thing it does is checking whether authentication failed and if it did, it will abort.
And here comes the problem. If an account fails to authenticate, it won't try to login again as what happens is this: Since a.authData.Error is still set to something else than nil, poll() will always abort. Therefore, this account won't be polled again.

However, I'm seeing the problem you described. It's that if auth fails in the following "else if", it will still try to poll the account, right? http://bazaar.launchpad.net/~ubuntu-push-hackers/account-polld/trunk/view/99/cmd/account-polld/main.go#L115

So you are right and this should be fixed somewhere else. I'll look into where to fix it.

Looking at an example with Tokens which expired, I also found the following issue:

It does not reset the a.authData.Error field to nil when it grabs new tokens.
If the token expires, it calls the account_watcher_refresh() function (http://bazaar.launchpad.net/~ubuntu-push-hackers/account-polld/trunk/view/99/accounts/account-watcher.c#L298) from the poll() function (http://bazaar.launchpad.net/~ubuntu-push-hackers/account-polld/trunk/view/99/cmd/account-polld/account_manager.go#L129). This will soon call the account_info_clear_login() function (http://bazaar.launchpad.net/~ubuntu-push-hackers/account-polld/trunk/view/99/accounts/account-watcher.c#L60), which is in my opinion the proper place to reset the Error field.

I added a workaround for this in the following fix, so don't merge this one either. https://code.launchpad.net/~nikwen/account-polld/directly-poll-with-new-account-data-fix/+merge/238901

I'll try to fix both bugs properly next weekend. Therefore, you don't need to look into merging any of my merge proposals until then.

[Niklas Wenzel (nikwen)]

review: Needs Fixing

[Niklas Wenzel (nikwen)]

Ok, what I called the "second bug" in my last message, doesn't seem to be one. The Error field is reset here: http://bazaar.launchpad.net/~ubuntu-push-hackers/account-polld/trunk/view/99/accounts/account-watcher.c#L134

[Niklas Wenzel (nikwen)]

What really needs to be fixed here is that the Error field is populated here but is never reset: http://bazaar.launchpad.net/~ubuntu-push-hackers/account-polld/trunk/view/99/accounts/accounts.go#L95

[Niklas Wenzel (nikwen)]

Ok, I looked into the issue again and I think I fixed it properly but I wasn't able to reproduce the issue in a way that allows me to test my new code any more.
I'll have my device running my writable images with these additions this night and hope that the issue (or signs that it was fixed properly) will appear in the logs again.

You can find my changes here: https://code.launchpad.net/~nikwen/account-polld/error-fixes-new

[Niklas Wenzel (nikwen)]

To give you a short update: I was able to reproduce the issue again and found out that I first need to do the doneChan fix properly in order to be able to test my new code. I haven't got down to that yet but I'll try to do it as soon as possible. ;)

[Niklas Wenzel (nikwen)]

Ok, I decided to give it a go now just after writing my last message. I'll test my experimental code overnight and tell you whether it works.

[Niklas Wenzel (nikwen)]

Ok, I continued work on it and it's almost ready. For now I rewrote all three merge proposals but the code is still only in my testing branch. I'll split it up as soon as it's ready.
There's just one error left which I need to sort out but I'll have to wait until the Gmail tokens expire again to debug it. Is there any way to force refreshing the tokens?

[Niklas Wenzel (nikwen)]

I just updated the code in testing and now it doesn't block anymore when a token expires. Since I modified the code again, I'll have to wait for the tokens to expire again to test the most recent version...

[Niklas Wenzel (nikwen)]

Ok, I think I finally fixed that issue. I'll have to wait until the tokens expire to test it again though. I'll keep you updated. ;)

[Niklas Wenzel (nikwen)]

Finally, I have a fix. :)
I've had this for a few weeks and tested it but account-polld kept failing sometimes and I thought it was caused by my changes. Now that I saw exactly the same failure on an installation without my account-polld changes I can be sure that it hasn't been caused by me.
For sure I'll look into the other bug as well. ;)

review: Approve

[Niklas Wenzel (nikwen)]

Btw, here's the bug report to the other issue I found: https://bugs.launchpad.net/ubuntu/+source/account-polld/+bug/1405651

[lp:~nikwen/account-polld/authenticate-again-fix]

102. By Niklas Wenzel on 2014-12-26

Fix issue with closures

103. By Niklas Wenzel on 2014-12-27

Fix LP: #1405651 as well

[Niklas Wenzel (nikwen)]

This also prevents the info->watcher->callback() call in accounts/account-watcher.c from blocking now (LP: #1405651) by not polling the account if the new token hasn't been loaded yet.

[John Lenton (chipaca)]

review: Approve

=== modified file 'cmd/account-polld/account_manager.go'
--- cmd/account-polld/account_manager.go	2014-10-14 21:34:15 +0000
+++ cmd/account-polld/account_manager.go	2014-12-27 21:43:02 +0000
@@ -129,6 +129,7 @@
 		if err == plugins.ErrTokenExpired {
 			a.watcher.Refresh(a.authData.AccountId)
 			a.authData.Enabled = false
+			a.authData.Error = err
 		}
 		a.doneChan <- err
 	} else {

=== modified file 'cmd/account-polld/main.go'
--- cmd/account-polld/main.go	2014-10-14 21:34:15 +0000
+++ cmd/account-polld/main.go	2014-12-27 21:43:02 +0000
@@ -1,6 +1,7 @@
 /*
  Copyright 2014 Canonical Ltd.
  Authors: Sergio Schvezov <[e-mail]>
+ Authors: Niklas Wenzel <[e-mail]>
 
  This program is free software: you can redistribute it and/or modify it
  under the terms of the GNU General Public License version 3, as published
@@ -137,12 +138,25 @@
 		case <-pollBus.PollChan:
 			var wg sync.WaitGroup
 			for _, v := range mgr {
-				wg.Add(1)
-				poll := v.Poll
-				go func() {
-					defer wg.Done()
-					poll(false)
-				}()
+				if v.authData.Error != plugins.ErrTokenExpired { // Do not poll if the new token
+				                                                 // hasn't been loaded yet
+					wg.Add(1)
+					go func(accountManager *AccountManager) {
+						defer wg.Done()
+
+						if accountManager.authData.Error != nil {
+							// Make the account try to authenticate again in Poll()
+							log.Println("Retrying to authenticate existing account with id",
+							                               accountManager.authData.AccountId)
+							accountManager.penaltyCount = 0
+							accountManager.authData.Error = nil
+						}
+
+						accountManager.Poll(false)
+					}(v)
+				} else {
+					log.Println("Skipping account with id", v.authData.AccountId, "as it is refreshing its token")
+				}
 			}
 			wg.Wait()
 			pollBus.SignalDone()