account-polld tries hard to open a trust session and fails repeatedly

[Dave Morley]

Affects <= OTA7

Reproduce:
1. Add a google account and allow gmail
2. Make sure it works, (account n has 0 new updates etc…)
3. Change the account's password

Expected:
By looking at the logs, I'd expect the output to say something along the lines of "authentication failed, stopping poll"

Actual:
You'll see an endless repetition of:
2015/10/13 13:39:13 Polling account 7
2015/10/13 13:39:14 Error while polling 7: Token expired
2015/10/13 13:39:14 Poll for account 7 has failed: Token expired
2015/10/13 13:39:14 Ending poll for account 7
2015/10/13 13:39:14 New account data for existing account with id 7
2015/10/13 13:39:14 Starting poll for account 7
2015/10/13 13:39:14 Polling account 7

Memory on device is at a minimum too. As can be seen here http://paste.ubuntu.com/12436034/ this system has no app open.

Logs: I have included the entire .cache/upstart folder and syslog.

[Jean-Baptiste Lallement (jibel)]

This message is printed in a loop in dbus.log

Activating service name='com.google.code.AccountsSSO.SingleSignOn'
Successfully activated service 'com.google.code.AccountsSSO.SingleSignOn'
Activating service name='com.nokia.singlesignonui'
Successfully activated service 'com.nokia.singlesignonui'
Invalid prompt session: /build/mir-xon0uu/mir-0.14.1+15.04.20150821/src/server/scene/prompt_session_manager_impl.cpp(137): Throw in function virtual std::shared_ptr<mir::scene::PromptSession> mir::scene::PromptSessionManagerImpl::start_prompt_session_for(const std::shared_ptr<mir::scene::Session>&, const mir::scene::PromptSessionCreationParameters&) const
Dynamic exception type: N5boost16exception_detail10clone_implINS0_19error_info_injectorISt13runtime_errorEEEE
std::exception::what: Could not identify application session

Couldn't setup prompt session
UiProxy initialization failed!

[Jean-Baptiste Lallement (jibel)]

From unity8.log online-accounts-service keeps restarting over and over again

qtmir.mir: SessionListener::starting - this= SessionListener(0xb1935214) session= 0x92003a0c
qtmir.sessions: SessionManager::onSessionStarting - sessionName= online-accounts-service
qtmir.sessions: Session::Session() "online-accounts-service"
qtmir.mir: SessionListener::stopping - this= SessionListener(0xb1935214) session= 0x92003a0c
qtmir.sessions: SessionManager::onSessionStopping - sessionName= online-accounts-service
qtmir.sessions: Session::release "online-accounts-service"
qtmir.sessions: Session::~Session() "online-accounts-service"

[Alberto Mardegan (mardy)]

There is a process continuosly invoking online accounts, presumably with wrong parameters. Unfortunately I cannot tell which process it is from the logs.

Dave, can you still reproduce it? Next time it happens, please run:

   OAU_LOGGING_LEVEL=2 OAU_DAEMON_TIMEOUT=9999 online-accounts-service

and attach the output here.

Looking at top, I suspect that sync-monitor could be the client continuously invoking Online Accounts. I'm adding sync-monitor to the bug, just to have some people confirm whether it's possible that a failed invocation to online accounts results in a loop.

[kevin gunn (kgunn72)]

what's interesting is going back to the previous unity8.log (unity8.log7) in the zip. at the end of it is the beginning of that spew pattern listed in the previous comment.

[Dave Morley (davmor2)]

davmor2@stryder:~$ adb shell
ounts-serviceu-phablet:~$ OAU_LOGGING_LEVEL=2 OAU_DAEMON_TIMEOUT=9999 online-acc
signonui-service.cpp 227 queryDialog Got request: QMap(("AppId", QVariant(QString, "unconfined") ) ( "Caption" , QVariant(QString, "google") ) ( "ClientData" , QVariant(QVariantMap, QMap(("AllowedSchemes", QVariant(QStringList, ("https", "http")) ) ( "AuthPath" , QVariant(QString, "o/oauth2/auth?access_type=offline") ) ( "ClientId" , QVariant(QString, "759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com") ) ( "ClientSecret" , QVariant(QString, "juFngKUcuhB7IRQqHtSLavqJ") ) ( "ForceClientAuthViaRequestBody" , QVariant(bool, true) ) ( "Host" , QVariant(QString, "accounts.google.com") ) ( "RedirectUri" , QVariant(QString, "https://wiki.ubuntu.com/") ) ( "ResponseType" , QVariant(QString, "code") ) ( "Scope" , QVariant(QStringList, ("https://docs.google.com/feeds/", "https://www.googleapis.com/auth/googletalk", "https://www.googleapis.com/auth/userinfo.email", "https://www.googleapis.com/auth/userinfo.profile", "https://picasaweb.google.com/data/", "https://mail.google.com/", "https://www.google.com/m8/feeds/", "https://www.googleapis.com/auth/calendar", "https://www.googleapis.com/auth/carddav")) ) ( "TokenPath" , QVariant(QString, "o/oauth2/token") ) ) ) ) ( "FinalUrl" , QVariant(QString, "https://wiki.ubuntu.com/") ) ( "Identity" , QVariant(uint, 2) ) ( "Mechanism" , QVariant(QString, "web_server") ) ( "Method" , QVariant(QString, "oauth2") ) ( "OpenUrl" , QVariant(QString, "https://accounts.google.com/o/oauth2/auth?access_type=offline&client_id=759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com&redirect_uri=https://wiki.ubuntu.com/&state=473866745&response_type=code&scope=https://docs.google.com/feeds/ https://www.googleapis.com/auth/googletalk https://www.googleapis.com/auth/userinfo.email https://www.googleapis.com/auth/userinfo.profile https://picasaweb.google.com/data/ https://mail.google.com/ https://www.google.com/m8/feeds/ https://www.googleapis.com/auth/calendar https://www.googleapis.com/auth/carddav") ) ( "Pid" , QVariant(int, 2522) ) ( "StoredIdentity" , QVariant(bool, true) ) ( "UserName" , QVariant(QString, "") ) ( "requestId" , QVariant(QString, "/com/google/code/AccountsSSO/SingleSignOn/AuthSession_1") ) )
utils.cpp 49 apparmorProfileOfPeer App ID: "unconfined"
request-manager.cpp 113 runQueue Head: OnlineAccountsUi::Request(0x1146508)
Invalid prompt session: /build/mir-xon0uu/mir-0.14.1+15.04.20150821/src/server/scene/prompt_session_manager_impl.cpp(137): Throw in function virtual std::shared_ptr<mir::scene::PromptSession> mir::scene::PromptSessionManagerImpl::start_prompt_session_for(const std::shared_ptr<mir::scene::Session>&, const mir::scene::PromptSessionCreationParameters&) const
Dynamic exception type: N5boost16exception_detail10clone_implINS0_19error_info_injectorISt13runtime_errorEEEE
std::exception::what: Could not identify application session

Couldn't setup prompt session
UiProxy initialization failed!
signonui-service.cpp 227 queryDialog Got request: QMap(("AppId", QVariant(QString, "unconfined") ) ( "Caption" , QVariant(QString, "google") ...

[Alberto Mardegan (mardy)]

Thanks Dave for this info. Also, I checked with Dave on IRC that PID 2522 (from which the request starts) is account-polld:

    phablet 2522 0.0 1.4 934112 14176 ? Ssl Sep09 9:38 /usr/bin/account-polld

online-accounts-service tries to create a trusted session having PID 2522 as initiatior, but since account-polld has no window associated with it, mir cannot create the trust session.
I think there are two problems here:
1) when talking to signond, account-polld should set the "UiPolicy" parameter to 2 (aka NoUserInteractionPolicy), so that we won't try to open a trust session for it.
2) account-polld should not continuosly retry authenticating if the previous attempt just failed.

[Niklas Wenzel (nikwen)]

One can also find the following line in the account-polld log:

2015/09/17 09:29:13 Account 2 failed to authenticate: GDBus.Error:com.google.code.AccountsSSO.SingleSignOn.Error.UserInteraction: userActionFinished error: 2

> 2) account-polld should not continuosly retry authenticating if
> the previous attempt just failed.

Agreed, but I still think that it should try at least a few times, otherwise we get LP: #1405649 again. To me it happens very often that after rebooting the first authentication cycle fails because the phone has not established a network connection yet.

[Niklas Wenzel (nikwen)]

I tried to fix #2 in https://code.launchpad.net/~nikwen/account-polld/authentification-penalty-count/+merge/272031. I'll still have to test it though. ;)

[Niklas Wenzel (nikwen)]

Had a typo in the branch name. Here is the updated one. ;)

https://code.launchpad.net/~nikwen/account-polld/authentication-penalty-count/+merge/272031

[Niklas Wenzel (nikwen)]

I also tried to fix #1 but I couldn't find out how to get libsignon-glib to pass that parameter. Alberto, do you have any ideas here?

[Alberto Mardegan (mardy)]

Thanks Niklas for looking into this!
In accounts/account-watcher.c, in the account_info_login() function, there is a line calling ag_auth_data_get_login_parameters(), which gets passed NULL as a second parameter. Instead of passing NULL, we should build a GVariant containing a dictionary of extra parameters which we want to use.

You can see a similar example here:
https://github.com/GNOME/empathy/blob/master/libempathy/empathy-uoa-auth-handler.c#L177

The only difference is that instead of SIGNON_POLICY_REQUEST_PASSWORD you should use SIGNON_POLICY_NO_USER_INTERACTION.

[Niklas Wenzel (nikwen)]

Alberto, thank you for the example!

I had already suspected that we needed to pass a GVariant to ag_auth_data_get_login_parameters() but I couldn't figure out how to properly build that one and which key to use when adding the SIGNON_POLICY_NO_USER_INTERACTION value. I guess I need to read a proper introduction to Glib at some point to get a proper overview of how it works. That said, I learned a lot from the example. Thanks again!

I implemented this in https://code.launchpad.net/~nikwen/account-polld/no-user-interaction/+merge/272309. I've tested normal operation and that seems to work fine. I haven't tried to reproduce this bug though. :)

[Niklas Wenzel (nikwen)]

Both MPs should be ready for review now. :)

[Jean-Baptiste Lallement (jibel)]

 account-polld (0.1+15.04.20151016.1-0ubuntu1) vivid; urgency=medium
 .
   [ Alberto Mardegan ]
   * Remove non-working facebook integration. (LP: #1493733)
   * debian/control, debian/account-polld.conf:
     Remove mentions of Facebook from the descriptions.
 .
   [ Niklas Wenzel ]
   * Tell libsignon-glib not to open a trust session by passing
     SIGNON_POLICY_NO_USER_INTERACTION as the
     SIGNON_SESSION_DATA_UI_POLICY value (part of the issue experienced
     in LP: #1496773) (LP: #1496773)
   * When authentification of an account fails continuously, we should
     wait a bit before trying again (part of the issue experienced in LP:
     #1496773) (LP: #1496773)