Bug 86824 - [signon] Support plain username/password accounts
Summary: [signon] Support plain username/password accounts
Status: RESOLVED FIXED
Alias: None
Product: SyncEvolution
Classification: Unclassified
Component: SyncEvolution (show other bugs)
Version: unspecified
Hardware: All All
: medium enhancement
Assignee: SyncEvolution Community
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-11-28 15:55 UTC by Alberto Mardegan
Modified: 2015-04-01 13:16 UTC (History)
1 user (show)

See Also:
i915 platform:
i915 features:


Attachments
Refactor the AuthProvider in preparation of later changes (13.17 KB, text/plain)
2014-11-28 15:55 UTC, Alberto Mardegan
Details
Split the signon backend (23.31 KB, patch)
2014-12-12 13:46 UTC, Alberto Mardegan
Details | Splinter Review
Remove failure count (17.01 KB, patch)
2014-12-12 13:47 UTC, Alberto Mardegan
Details | Splinter Review
Do not create identities (3.68 KB, patch)
2014-12-12 13:47 UTC, Alberto Mardegan
Details | Splinter Review
Pass the AgAuthData to the SignonAuthProvider (5.66 KB, patch)
2014-12-12 13:48 UTC, Alberto Mardegan
Details | Splinter Review
Implement getCredentials (6.85 KB, patch)
2014-12-12 13:50 UTC, Alberto Mardegan
Details | Splinter Review
fix memory leak (1.72 KB, patch)
2015-02-13 15:57 UTC, Patrick Ohly
Details | Splinter Review
address minor performance issue (2.00 KB, patch)
2015-02-13 15:57 UTC, Patrick Ohly
Details | Splinter Review
fix incorrect GVariant usage (1.62 KB, patch)
2015-02-13 15:57 UTC, Patrick Ohly
Details | Splinter Review
unrelated cleanup of username sanity check (4.49 KB, patch)
2015-02-13 15:58 UTC, Patrick Ohly
Details | Splinter Review
handle 403 error (1.43 KB, patch)
2015-02-13 15:58 UTC, Patrick Ohly
Details | Splinter Review
signon: move libaccounts-based plugins into their own source file (23.31 KB, patch)
2015-03-03 09:49 UTC, Patrick Ohly
Details | Splinter Review
AuthProvider: removed failure count (17.14 KB, patch)
2015-03-03 09:50 UTC, Patrick Ohly
Details | Splinter Review
signon-accounts: do not create identities on the fly (3.68 KB, patch)
2015-03-03 09:50 UTC, Patrick Ohly
Details | Splinter Review
signon-accounts: pass the AgAuthData to the SignonAuthProvider (5.83 KB, patch)
2015-03-03 09:51 UTC, Patrick Ohly
Details | Splinter Review
signon-accounts: implement getCredentials (7.18 KB, patch)
2015-03-03 09:51 UTC, Patrick Ohly
Details | Splinter Review
signon: ensure consistent use of "username" provider prefix (4.49 KB, patch)
2015-03-03 09:51 UTC, Patrick Ohly
Details | Splinter Review
WebDAV: handle 403 during Google OAuth authentication (1.43 KB, patch)
2015-03-03 09:52 UTC, Patrick Ohly
Details | Splinter Review

Description Alberto Mardegan 2014-11-28 15:55:53 UTC
Created attachment 110171 [details]
Refactor the AuthProvider in preparation of later changes

The signon backend currently supports only OAuth-based accounts, while it could be used also as a credentials provider.
Comment 1 Patrick Ohly 2014-11-28 16:12:24 UTC
Comment on attachment 110171 [details]
Refactor the AuthProvider in preparation of later changes

An explanation how auth failures are detected and resolved now would be useful. I have a hard time understanding how the replacement of the NE_AUTH error handling is working.

The commit message should not only explain what is changed, but also why the new code is better.
Comment 2 Alberto Mardegan 2014-12-12 13:46:35 UTC
Created attachment 110784 [details] [review]
Split the signon backend
Comment 3 Alberto Mardegan 2014-12-12 13:47:00 UTC
Created attachment 110785 [details] [review]
Remove failure count
Comment 4 Alberto Mardegan 2014-12-12 13:47:23 UTC
Created attachment 110786 [details] [review]
Do not create identities
Comment 5 Alberto Mardegan 2014-12-12 13:48:04 UTC
Created attachment 110787 [details] [review]
Pass the AgAuthData to the SignonAuthProvider
Comment 6 Alberto Mardegan 2014-12-12 13:50:20 UTC
Created attachment 110788 [details] [review]
Implement getCredentials

I removed the previous patch and posted five new patches which implement the feature described in this bug report.
It's all still to be tested, but I think it's ready for a preliminary code review.

I also extended the comments and commit messages to explain why we are doing what.
Comment 7 Alberto Mardegan 2014-12-16 15:00:57 UTC
I just wanted to mention that I've now tested the new feature as described here:

https://lists.launchpad.net/ubuntu-phone/msg10806.html

and it seems to be working fine.
Comment 8 Patrick Ohly 2015-02-09 14:30:26 UTC
Comment on attachment 110787 [details] [review]
Pass the AgAuthData to the SignonAuthProvider

Review of attachment 110787 [details] [review]:
-----------------------------------------------------------------

::: src/backends/signon/signon-accounts.cpp
@@ +96,2 @@
>          }
> +        GVariant *extraOptions = g_variant_builder_end(&builder);

Who ensures that the created GVariant gets freed?

I suspect that this needs to be:
GVarianteCXX extraOptions(g_variant_take_ref(g_variant_build_end(&builder)), TRANSFER_REF);
Comment 9 Patrick Ohly 2015-02-09 14:32:12 UTC
(In reply to Patrick Ohly from comment #8)
> Comment on attachment 110787 [details] [review] [review]
> Pass the AgAuthData to the SignonAuthProvider
> 
> Review of attachment 110787 [details] [review] [review]:
> -----------------------------------------------------------------
> 
> ::: src/backends/signon/signon-accounts.cpp
> @@ +96,2 @@
> >          }
> > +        GVariant *extraOptions = g_variant_builder_end(&builder);
> 
> Who ensures that the created GVariant gets freed?
> 
> I suspect that this needs to be:
> GVarianteCXX extraOptions(g_variant_take_ref(g_variant_build_end(&builder)),
> TRANSFER_REF);

There are two such constructs in the code.
Comment 10 Patrick Ohly 2015-02-09 17:19:59 UTC
cppcheck found some issues:

/data/runtests/work/sources/syncevolution/src/backends/signon/signon-accounts.cpp:130: cppcheck performance: stlcstrReturn - Returning the result of c_str() in a function that returns std::string is slow and redundant.
/data/runtests/work/sources/syncevolution/src/backends/signon/signon-accounts.cpp:154: cppcheck performance: stlcstrReturn - Returning the result of c_str() in a function that returns std::string is slow and redundant.
Checking /data/runtests/work/sources/syncevolution/src/backends/signon/signon-accounts.cpp: USE_SIGNON...
Checking /data/runtests/work/sources/syncevolution/src/backends/pbap/PbapSyncSource.cpp: ENABLE_PBAP...
/data/runtests/work/sources/syncevolution/src/backends/signon/signon.cpp:77: cppcheck performance: stlcstrReturn - Returning the result of c_str() in a function that returns std::string is slow and redundant.
/data/runtests/work/sources/syncevolution/src/backends/signon/signon.cpp:119: cppcheck performance: stlcstrReturn - Returning the result of c_str() in a function that returns std::string is slow and redundant.
Comment 11 Patrick Ohly 2015-02-13 15:41:03 UTC
The "force token refresh" feature can be tested on Ubuntu Vivid. It currently fails.

Steps to reproduce:
* create a Google account in unity-control-center
* ag-tool list-accounts
* SYNCEVOLUTION_DEBUG=1 ./syncevolution --print-databases --daemon=no loglevel=4 syncURL=https://www.googleapis.com/.well-known/carddav username=uoa:<account id>,google-contacts backend=carddav
=> fails with 403 error because /usr/share/accounts/services/google-contacts.service does not contain the carddav scope
* edit /usr/share/accounts/services/google-contacts.service and add 'https://www.googleapis.com/auth/carddav' to 'Scope'
* restart signond with "LoggingLevel=2" in ~/.config/signond.conf
* run syncevolution again
=> still fails with a 403 error because neon never reports a NE_AUTH error and therefore the SyncEvolution "force token refresh" code is not used
* patch SyncEvolution, recompile
* run again
=> still fails, signond keeps returning the unusable access token

SyncEvolution debug output from that last run:

[DEBUG 00:00:00] using username 'uoa:2,google-contacts' from context for WebDAV, password not set
[DEBUG 00:00:00] looking for identity provider for uoa:2,google-contacts
[DEBUG 00:00:00] looking up account ID 2 and service 'google-contacts'
[DEBUG 00:00:00] enabled service: google-calendar
[DEBUG 00:00:00] enabled service: google-contacts
[DEBUG 00:00:00] signon-identity.c:559: signon_identity_new_from_db 559: 13
[DEBUG 00:00:00] using signond identity 13
[DEBUG 00:00:00] signon-identity.c:627: signon_identity_create_session 627
[DEBUG 00:00:00] signon-identity.c:662: signon_identity_create_session 662
[DEBUG 00:00:00] timout 300s, retry 5s => resending allowed
HTTP session to https://www.googleapis.com:443 begins.
[DEBUG 00:00:00] client cert is missing
[INFO 00:00:00] start database search at https://www.googleapis.com/.well-known/carddav, from sync config '@default', syncURL='https://www.googleapis.com/.well-known/carddav'
[DEBUG 00:00:00] testing https://www.googleapis.com:443/.well-known/carddav
[DEBUG 00:00:00] debugging: read all WebDAV properties of https://www.googleapis.com:443/.well-known/carddav
[DEBUG 00:00:00] starting PROPFIND, credentials unverified, no deadline
[DEBUG 00:00:00] retrieving OAuth2 token
[DEBUG 00:00:00] asking for authentication with method oauth2, mechanism web_server and parameters {'ForceClientAuthViaRequestBody': <true>, 'Host': <'accounts.google.com'>, 'AllowedSchemes': <['https', 'http']>, 'ClientSecret': <'3NbR94RM-DTnA81BWjiJe4TP'>, 'Scope': <['https://www.googleapis.com/auth/userinfo.email', 'https://mail.google.com/', 'https://www.google.com/m8/feeds/', 'https://www.googleapis.com/auth/calendar', 'https://www.googleapis.com/auth/carddav']>, 'ClientId': <'796629365126.apps.googleusercontent.com'>, 'AuthPath': <'o/oauth2/auth?access_type=offline'>, 'ResponseType': <'code'>, 'RedirectUri': <'https://live.gnome.org/Evolution'>, 'TokenPath': <'o/oauth2/token'>}
[DEBUG 00:00:00] signon-identity.c:508: identity_new_from_db_cb
[DEBUG 00:00:00] signon-identity.c:393: identity_registered: /com/google/code/AccountsSSO/SingleSignOn/Identity_0
[DEBUG 00:00:00] signon-identity.c:432: identity_registered: 
[DEBUG 00:00:00] signon-identity-info.c:99: signon_identity_info_new_from_variant: 
[DEBUG 00:00:00] signon-auth-session.c:740: Object path received: /com/google/code/AccountsSSO/SingleSignOn/AuthSession_0
[DEBUG 00:00:00] signon-identity.c:328: State changed to DATA_UPDATED
[DEBUG 00:00:00] signon-identity.c:1000: 1000 identity_process_updated
[DEBUG 00:00:00] authentication result: {'AccessToken': <'ya29.GQHZpQNpDO8UYEE2lJEa7tc5h8DmQEQHNfXg_0pYE9yV7u3lI1ueqxMFP0ulXI6pMzKCo8GzWM_Zag'>, 'ExpiresIn': <3600>, 'RefreshToken': <''>}, ???
[DEBUG 00:00:00] got new OAuth2 token 'ya29.GQHZpQNpDO8UYEE2lJEa7tc5h8DmQEQHNfXg_0pYE9yV7u3lI1ueqxMFP0ulXI6pMzKCo8GzWM_Zag' for next request
ah_create, for WWW-Authenticate
Running pre_send hooks
[DEBUG 00:00:00] using OAuth2 token 'ya29.GQHZpQNpDO8UYEE2lJEa7tc5h8DmQEQHNfXg_0pYE9yV7u3lI1ueqxMFP0ulXI6pMzKCo8GzWM_Zag' to authenticate
Sending request headers:
PROPFIND /.well-known/carddav HTTP/1.1
Connection: TE
TE: trailers
Host: www.googleapis.com
Depth: 0
Content-Length: 84
Content-Type: application/xml
User-Agent: SyncEvolution
Authorization: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

Sending request-line and headers:
Doing DNS lookup on proxy.vlan13.01.org...
req: Connecting to 10.0.13.1:3128
Running pre_send hooks
[DEBUG 00:00:00] using OAuth2 token 'ya29.GQHZpQNpDO8UYEE2lJEa7tc5h8DmQEQHNfXg_0pYE9yV7u3lI1ueqxMFP0ulXI6pMzKCo8GzWM_Zag' to authenticate
Sending request headers:
CONNECT www.googleapis.com:443 HTTP/1.1
Connection: TE
TE: trailers
Host: www.googleapis.com
User-Agent: SyncEvolution
Authorization: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

Sending request-line and headers:
Request sent; retry is 0.
[status-line] < HTTP/1.1 200 Connection established
[hdr] 
End of headers.
Running post_headers hooks
Running post_send hooks
Request ends, status 200 class 2xx, error line:
200 Connection established
Running destroy hooks.
Request ends.
Sending request body:
Body block (84 bytes):
[<?xml version="1.0" encoding="utf-8"?>
<propfind xmlns="DAV:"><allprop/></propfind>
]
Request sent; retry is 0.
[status-line] < HTTP/1.1 403 Forbidden
[hdr] Vary: X-Origin
Header Name: [vary], Value: [X-Origin]
[hdr] WWW-Authenticate: Bearer realm="https://accounts.google.com/AuthSubRequest", error=insufficient_scope, scope="https://www.googleapis.com/auth/carddav"
Header Name: [www-authenticate], Value: [Bearer realm="https://accounts.google.com/AuthSubRequest", error=insufficient_scope, scope="https://www.googleapis.com/auth/carddav"]
[hdr] Content-Type: application/vnd.google.gdata.error+xml; charset=UTF-8
Header Name: [content-type], Value: [application/vnd.google.gdata.error+xml; charset=UTF-8]
[hdr] Date: Fri, 13 Feb 2015 15:30:56 GMT
Header Name: [date], Value: [Fri, 13 Feb 2015 15:30:56 GMT]
[hdr] Expires: Fri, 13 Feb 2015 15:30:56 GMT
Header Name: [expires], Value: [Fri, 13 Feb 2015 15:30:56 GMT]
[hdr] Cache-Control: private, max-age=0
Header Name: [cache-control], Value: [private, max-age=0]
[hdr] X-Content-Type-Options: nosniff
Header Name: [x-content-type-options], Value: [nosniff]
[hdr] X-Frame-Options: SAMEORIGIN
Header Name: [x-frame-options], Value: [SAMEORIGIN]
[hdr] X-XSS-Protection: 1; mode=block
Header Name: [x-xss-protection], Value: [1; mode=block]
[hdr] Server: GSE
Header Name: [server], Value: [GSE]
[hdr] Alternate-Protocol: 443:quic,p=0.08
Header Name: [alternate-protocol], Value: [443:quic,p=0.08]
[hdr] Accept-Ranges: none
Header Name: [accept-ranges], Value: [none]
[hdr] Vary: Origin,Accept-Encoding
Header Name: [vary], Value: [Origin,Accept-Encoding]
[hdr] Transfer-Encoding: chunked
Header Name: [transfer-encoding], Value: [chunked]
[hdr] 
End of headers.
Running post_headers hooks
[chunk] < f1
Got chunk size: 241
Reading 241 bytes of response body.
Got 241 bytes.
Read block (241 bytes):
[<?xml version="1.0" encoding="UTF-8"?>
<errors xmlns="http://schemas.google.com/g/2005">
 <error>
  <domain>GData</domain>
  <code>insufficientPermissions</code>
  <internalReason>Insufficient Permission</internalReason>
 </error>
</errors>
]
[chunk] < 0
Got chunk size: 0
[hdr] 
End of headers.
Running post_send hooks
ah_post_send (#0), code is 403 (want 401), WWW-Authenticate is Bearer realm="https://accounts.google.com/AuthSubRequest", error=insufficient_scope, scope="https://www.googleapis.com/auth/carddav"
Request ends, status 403 class 4xx, error line:
403 Forbidden
[DEBUG 00:00:00] discarding used and rejected OAuth2 token 'ya29.GQHZpQNpDO8UYEE2lJEa7tc5h8DmQEQHNfXg_0pYE9yV7u3lI1ueqxMFP0ulXI6pMzKCo8GzWM_Zag'
[DEBUG 00:00:00] credential error, no success with them before => report it
[DEBUG 00:00:00] PROPFIND: Neon error code 3 = NE_AUTH, HTTP status 401: 403 Forbidden, might retry
[DEBUG 00:00:00] retrying not allowed for PROPFIND (no deadline)
[DEBUG 00:00:00] credentials rejected
Running destroy hooks.
Request ends.
[DEBUG 00:00:00] exception thrown at /data/runtests/work/sources/syncevolution/src/backends/webdav/NeonCXX.cpp:794
[DEBUG 00:00:00] error code from SyncEvolution authorization failed (remote, status 401): PROPFIND: Neon error code 3 = NE_AUTH, HTTP status 401: 403 Forbidden
[DEBUG 00:00:00] read relevant properties of https://www.googleapis.com:443/.well-known/carddav
[DEBUG 00:00:00] starting PROPFIND, credentials unverified, deadline in 299.4s
[DEBUG 00:00:00] retrieving OAuth2 token
[DEBUG 00:00:00] asking for authentication with method oauth2, mechanism web_server and parameters {'ForceTokenRefresh': <true>, 'ForceClientAuthViaRequestBody': <true>, 'Host': <'accounts.google.com'>, 'AllowedSchemes': <['https', 'http']>, 'ClientSecret': <'3NbR94RM-DTnA81BWjiJe4TP'>, 'Scope': <['https://www.googleapis.com/auth/userinfo.email', 'https://mail.google.com/', 'https://www.google.com/m8/feeds/', 'https://www.googleapis.com/auth/calendar', 'https://www.googleapis.com/auth/carddav']>, 'ClientId': <'796629365126.apps.googleusercontent.com'>, 'AuthPath': <'o/oauth2/auth?access_type=offline'>, 'ResponseType': <'code'>, 'RedirectUri': <'https://live.gnome.org/Evolution'>, 'TokenPath': <'o/oauth2/token'>}
[DEBUG 00:00:00] signon-identity.c:328: State changed to DATA_UPDATED
[DEBUG 00:00:00] signon-identity.c:1000: 1000 identity_process_updated
[DEBUG 00:00:00] authentication result: {'AccessToken': <'ya29.GQHZpQNpDO8UYEE2lJEa7tc5h8DmQEQHNfXg_0pYE9yV7u3lI1ueqxMFP0ulXI6pMzKCo8GzWM_Zag'>, 'ExpiresIn': <3600>, 'RefreshToken': <''>}, ???
[DEBUG 00:00:00] exception thrown at /data/runtests/work/sources/syncevolution/src/backends/signon/signon-accounts.cpp:152
[ERROR 00:00:00] Got the same invalid AccessToken
[ERROR 00:00:00] logging into remote service failed: Got the same invalid AccessToken


Syslog output from signond:

Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signondaemon.cpp 390 init Failed to SUID root. Secure storage will not be available.
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signondaemon.cpp 529 initExtension Loading plugin  "/usr/lib/x86_64-linux-gnu/signon/extensions/libkeyring.so"
Feb 13 07:30:56 syncev signond[5154]: virtual SignOn::AbstractSecretsStorage* KeyringPlugin::secretsStorage(QObject*) const
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 45 SecretsStorage : Constructed
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsaccessmanager.cpp 164 finalize Enter
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsaccessmanager.cpp 187 init Initializing CredentialsAccessManager with configuration:  "#012#012====== Credentials Access Manager Configuration ======#012#012Using encryption: true#012Metadata DB path: /data/runtests/work/downstream-vivid-amd64/home/googlecontacts/config/signond/signon.db#012Cryptomanager name: #012ACL manager name: #012Secrets storage name: #012======================================================#012#012"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsaccessmanager.cpp 210 init No AccessControlManager set, using default (dummy)
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsaccessmanager.cpp 225 init No CryptoManager set, using default (dummy)
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsaccessmanager.cpp 653 onEncryptedFSMounted
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsaccessmanager.cpp 239 init No key authorizer set, using default
Feb 13 07:30:56 syncev signond[5154]: /build/buildd/signon-8.57+15.04.20150204.1/lib/signond/SignOn/key-handler.cpp 89 initialize No key manager has been registered
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsaccessmanager.cpp 267 init CredentialsAccessManager successfully initialized...
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 133 SqlDatabase Supported Drivers: ("QSQLITE")
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 134 SqlDatabase DATABASE NAME [ "/data/runtests/work/downstream-vivid-amd64/home/googlecontacts/config/signond/signon.db" ]
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 150 init Database connection succeeded.
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 161 init SQL table structure already created...
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsaccessmanager.cpp 399 openSecretsDB Database name: [ "/data/runtests/work/downstream-vivid-amd64/home/googlecontacts/config/signond/signon-secrets.db" ]
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 60 initialize : Using keyring: "default"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signondaemon.cpp 502 init Signond SUCCESSFULLY initialized.
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 81 isPeerAllowedToUseIdentity "Access control list of identity: 13: [*].Tokens count: 1#011"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signondaemon.cpp 626 getIdentity Registering identity: 13
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: false
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signondaemon.cpp 652 getIdentity DONE REGISTERING IDENTITY
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 81 isPeerAllowedToUseIdentity "Access control list of identity: 13: [*].Tokens count: 1#011"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signondaemonadaptor.cpp 188 getAuthSessionObjectPath ACM passed, creating AuthSession object
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonauthsession.cpp 60 createAuthSession
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonauthsession.cpp 37 SignonAuthSession
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonauthsession.cpp 44 SignonAuthSession "/com/google/code/AccountsSSO/SingleSignOn/AuthSession_0"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 75 PluginProxy
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/main.cpp 71 main handler: 0x405480
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/main.cpp 87 main "oauth2"
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 186 setupProxySettings
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 90 loadPlugin  loading auth library for  "oauth2"
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 100 loadPlugin library loaded
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 112 loadPlugin constructor resolved
Feb 13 07:30:56 syncev signonpluginprocess[5156]: plugin.cpp 44 Plugin :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 143 loadPlugin plugin is fully initialized
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 149 setupDataStreams
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 165 setupDataStreams cancel thread created
Feb 13 07:30:56 syncev signonpluginprocess[5156]: plugin.cpp 56 type :
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 474 queryType
Feb 13 07:30:56 syncev signonpluginprocess[5156]: plugin.cpp 56 type :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 496 queryMechanisms
Feb 13 07:30:56 syncev signonpluginprocess[5156]: plugin.cpp 62 mechanisms :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 519 queryMechanisms ("HMAC-SHA1", "PLAINTEXT", "web_server", "user_agent")
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 172 createNewPluginProxy The process is started
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 135 sessionCore The new session is created : "13+oauth2"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonauthsession.cpp 75 createAuthSession SignonAuthSession created successfully: "/com/google/code/AccountsSSO/SingleSignOn/AuthSession_0"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonauthsessionadaptor.cpp 76 process "web_server"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: false
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 919 startNewRequest Starting the authentication process
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 330 startProcess the number of requests is 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 168 isPeerAllowedToAccess "*"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1466 loadData Loading: 13 , "oauth2"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 3 method: 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonauthsession.cpp 142 stateChangedSlot
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 372 sessionDataReceived The cancel thread is started
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 85 OAuth2PluginPrivate :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 111 OAuth2Plugin :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 206 respondWithStoredToken : Stored token is expired
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 586 refreshOAuth2Token : "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT"
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 598 sendOAuth2PostRequest :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 623 sendOAuth2PostRequest : Query string =   QUrl( "?grant_type=refresh_token&refresh_token=1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT&client_id=796629365126.apps.googleusercontent.com&client_secret=3NbR94RM-DTnA81BWjiJe4TP" )
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 13 07:30:56 syncev signonpluginprocess[5156]: base-plugin.cpp 133 onPostFinished : Finished signal received
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 478 serverReply : "{#012  "access_token" : "ya29.GQHZpQNpDO8UYEE2lJEa7tc5h8DmQEQHNfXg_0pYE9yV7u3lI1ueqxMFP0ulXI6pMzKCo8GzWM_Zag",#012  "token_type" : "Bearer",#012  "expires_in" : 3600,#012  "id_token" : "eyJhbGciOiJSUzI1NiIsImtpZCI6ImIxZTMxM2NjYjcxMGZkYzE0MThmYTQyNjJmNzAwZjg5MTU4Y2E5MzYifQ.eyJpc3MiOiJhY2NvdW50cy5nb29nbGUuY29tIiwiaWQiOiIxMTE3MjE4NDQ0MTIzNDc1Nzc5MzYiLCJzdWIiOiIxMTE3MjE4NDQ0MTIzNDc1Nzc5MzYiLCJhenAiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJlbWFpbCI6InN5bmNldm9sdXRpb24ubGlzdEBnbWFpbC5jb20iLCJhdF9oYXNoIjoiTGYyWUk2UzV6MkVnZFNWdW4wMnlUZyIsImVtYWlsX3ZlcmlmaWVkIjp0cnVlLCJhdWQiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJ0b2tlbl9oYXNoIjoiTGYyWUk2UzV6MkVnZFNWdW4wMnlUZyIsInZlcmlmaWVkX2VtYWlsIjp0cnVlLCJjaWQiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJpYXQiOjE0MjM4NDExNTYsImV4cCI6MTQyMzg0NTA1Nn0.qUwb9D6GduyrNJMTLcnbNBDgcGgzcB_WOETLcDL7oYgt-6Eb66fUeLH6idLrFm6XWy0xKBSVYIRq90SC4OohDN2kHMIB3Qx-u8EVwK1ieh_xfDpsJ9156u37IrkSia2zrFyDGj731aCdEkw4hX3w1pGsq_IvKq7QW06TN3a9TvE"#012}"
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 482 serverReply : QVariant(int, 200)
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 444 parseReply : application/json content received
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 667 parseJSONReply :
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 2
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 2247
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 2
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 357 handlePluginResponse PLUGIN_RESPONSE_STORE
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 629 processStore
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 525 processStoreOperation Processing --- StoreOperation::Blob
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1485 storeData Storing: 13 , "oauth2"
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 662 storeResponse : QMap(("759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com", QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  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")) ) ( "Token" ,  QVariant(QString, "ya29.GQGgoVYW-1MfSW6z2DXHlsMuJdUfaM1V44Sn0BTxgp-fnAPiGFQqhZV0Ij1Ic-g1XJiNSDJgC6vRZQ") ) ( "refresh_token" ,  QVariant(QString, "1/AtmKZaNz_kk0Bu3X7zInJsIN9zp7BTaQ_FgdC_ng954MEudVrK5jSpoR30zcRFq6") ) ( "timestamp" ,  QVariant(uint, 1423829484) ) ) ) ) ( "796629365126.apps.googleusercontent.com" ,  QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  QVariant(QStringList, ("https://www.googleapis.com/auth/userinfo.email", "https://mail.google.com/", "https://www.google.com/m8/feeds/", "https://www.googleapis.com/auth/calendar", "https://www.googleapis.com/auth/carddav")) ) ( "Token" ,  QVariant(QString, "ya29.GQHZpQNpDO8UYEE2lJEa7tc5h8DmQEQHNfXg_0pYE9yV7u3lI1ueqxMFP0ulXI6pMzKCo8GzWM_Zag") ) ( "refresh_token" ,  QVariant(QString, "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT") ) ( "timestamp" ,  QVariant(uint, 1423841456) ) ) ) ) )
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 425 disableCancelThread Before the isFinished loop
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 3 method: 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 273
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 346 handlePluginResponse PLUGIN_RESPONSE_RESULT
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 544 processResultReply
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1197 updateCredentials UPDATE: 13
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 1 method: 0
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonidentity.cpp 447 onCredentialsUpdated 13
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 902 startNewRequest No more requests to process
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonauthsessionadaptor.cpp 76 process "web_server"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: false
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 919 startNewRequest Starting the authentication process
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 330 startProcess the number of requests is 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 168 isPeerAllowedToAccess "*"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1466 loadData Loading: 13 , "oauth2"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 3 method: 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonauthsession.cpp 142 stateChangedSlot
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 372 sessionDataReceived The cancel thread is started
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 116 ~OAuth2Plugin :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 93 ~OAuth2PluginPrivate :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 85 OAuth2PluginPrivate :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 111 OAuth2Plugin :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 276 process : Clearing access token QMap(("759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com", QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  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")) ) ( "Token" ,  QVariant(QString, "ya29.GQGgoVYW-1MfSW6z2DXHlsMuJdUfaM1V44Sn0BTxgp-fnAPiGFQqhZV0Ij1Ic-g1XJiNSDJgC6vRZQ") ) ( "refresh_token" ,  QVariant(QString, "1/AtmKZaNz_kk0Bu3X7zInJsIN9zp7BTaQ_FgdC_ng954MEudVrK5jSpoR30zcRFq6") ) ( "timestamp" ,  QVariant(uint, 1423829484) ) ) ) ) ( "796629365126.apps.googleusercontent.com" ,  QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  QVariant(QStringList, ("https://www.googleapis.com/auth/userinfo.email", "https://mail.google.com/", "https://www.google.com/m8/feeds/", "https://www.googleapis.com/auth/calendar", "https://www.googleapis.com/auth/carddav")) ) ( "refresh_token" ,  QVariant(QString, "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT") ) ( "timestamp" ,  QVariant(uint, 1423841456) ) ) ) ) )
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 586 refreshOAuth2Token : "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT"
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 598 sendOAuth2PostRequest :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 623 sendOAuth2PostRequest : Query string =   QUrl( "?grant_type=refresh_token&refresh_token=1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT&client_id=796629365126.apps.googleusercontent.com&client_secret=3NbR94RM-DTnA81BWjiJe4TP" )
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 2
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 2058
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 2
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 357 handlePluginResponse PLUGIN_RESPONSE_STORE
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 629 processStore
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 525 processStoreOperation Processing --- StoreOperation::Blob
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1485 storeData Storing: 13 , "oauth2"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 3 method: 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 13 07:30:56 syncev signonpluginprocess[5156]: base-plugin.cpp 133 onPostFinished : Finished signal received
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 478 serverReply : "{#012  "access_token" : "ya29.GQHZpQNpDO8UYEE2lJEa7tc5h8DmQEQHNfXg_0pYE9yV7u3lI1ueqxMFP0ulXI6pMzKCo8GzWM_Zag",#012  "token_type" : "Bearer",#012  "expires_in" : 3600,#012  "id_token" : "eyJhbGciOiJSUzI1NiIsImtpZCI6ImIxZTMxM2NjYjcxMGZkYzE0MThmYTQyNjJmNzAwZjg5MTU4Y2E5MzYifQ.eyJpc3MiOiJhY2NvdW50cy5nb29nbGUuY29tIiwiaWQiOiIxMTE3MjE4NDQ0MTIzNDc1Nzc5MzYiLCJzdWIiOiIxMTE3MjE4NDQ0MTIzNDc1Nzc5MzYiLCJhenAiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJlbWFpbCI6InN5bmNldm9sdXRpb24ubGlzdEBnbWFpbC5jb20iLCJhdF9oYXNoIjoiTGYyWUk2UzV6MkVnZFNWdW4wMnlUZyIsImVtYWlsX3ZlcmlmaWVkIjp0cnVlLCJhdWQiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJ0b2tlbl9oYXNoIjoiTGYyWUk2UzV6MkVnZFNWdW4wMnlUZyIsInZlcmlmaWVkX2VtYWlsIjp0cnVlLCJjaWQiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJpYXQiOjE0MjM4NDExNTYsImV4cCI6MTQyMzg0NTA1Nn0.qUwb9D6GduyrNJMTLcnbNBDgcGgzcB_WOETLcDL7oYgt-6Eb66fUeLH6idLrFm6XWy0xKBSVYIRq90SC4OohDN2kHMIB3Qx-u8EVwK1ieh_xfDpsJ9156u37IrkSia2zrFyDGj731aCdEkw4hX3w1pGsq_IvKq7QW06TN3a9TvE"#012}"
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 482 serverReply : QVariant(int, 200)
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 444 parseReply : application/json content received
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 667 parseJSONReply :
Feb 13 07:30:56 syncev signonpluginprocess[5156]: oauth2plugin.cpp 662 storeResponse : QMap(("759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com", QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  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")) ) ( "Token" ,  QVariant(QString, "ya29.GQGgoVYW-1MfSW6z2DXHlsMuJdUfaM1V44Sn0BTxgp-fnAPiGFQqhZV0Ij1Ic-g1XJiNSDJgC6vRZQ") ) ( "refresh_token" ,  QVariant(QString, "1/AtmKZaNz_kk0Bu3X7zInJsIN9zp7BTaQ_FgdC_ng954MEudVrK5jSpoR30zcRFq6") ) ( "timestamp" ,  QVariant(uint, 1423829484) ) ) ) ) ( "796629365126.apps.googleusercontent.com" ,  QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  QVariant(QStringList, ("https://www.googleapis.com/auth/userinfo.email", "https://mail.google.com/", "https://www.google.com/m8/feeds/", "https://www.googleapis.com/auth/calendar", "https://www.googleapis.com/auth/carddav")) ) ( "Token" ,  QVariant(QString, "ya29.GQHZpQNpDO8UYEE2lJEa7tc5h8DmQEQHNfXg_0pYE9yV7u3lI1ueqxMFP0ulXI6pMzKCo8GzWM_Zag") ) ( "refresh_token" ,  QVariant(QString, "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT") ) ( "timestamp" ,  QVariant(uint, 1423841456) ) ) ) ) )
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 425 disableCancelThread Before the isFinished loop
Feb 13 07:30:56 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 430 disableCancelThread Internal iteration  0
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 2
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 2247
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 2
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 357 handlePluginResponse PLUGIN_RESPONSE_STORE
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 629 processStore
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 525 processStoreOperation Processing --- StoreOperation::Blob
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1485 storeData Storing: 13 , "oauth2"
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 3 method: 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 273
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 1
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 346 handlePluginResponse PLUGIN_RESPONSE_RESULT
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 544 processResultReply
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1197 updateCredentials UPDATE: 13
Feb 13 07:30:56 syncev signond[5154]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 1 method: 0
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonidentity.cpp 447 onCredentialsUpdated 13
Feb 13 07:30:56 syncev signond[5154]: ../../../../src/signond/signonsessioncore.cpp 902 startNewRequest No more requests to process
Feb 13 07:31:01 syncev sudo:    pohly : TTY=pts/2 ; PWD=/home/pohly ; USER=root ; COMMAND=/usr/bin/less /var/log/messages
Feb 13 07:31:01 syncev sudo: pam_systemd(sudo:session): pam_putenv: delete non-existent entry; XDG_RUNTIME_DIR
Feb 13 07:31:29 syncev signond[5154]: ../../../../src/signond/signondisposable.cpp 121 destroyUnused Object unused, deleting:  SignonDaemonNS::SignonIdentity(0x1f24a10, name = "/com/google/code/AccountsSSO/SingleSignOn/Identity_0")
Feb 13 07:31:29 syncev signond[5154]: QObject::disconnect: Unexpected null parameter
Feb 13 07:31:29 syncev signond[5154]: ../../../../src/signond/signondisposable.cpp 121 destroyUnused Object unused, deleting:  SignonDaemonNS::SignonSessionCore(0x1f24560)
Feb 13 07:31:29 syncev signond[5154]: ../../../../src/signond/signonauthsession.cpp 52 ~SignonAuthSession
Feb 13 07:31:29 syncev signond[5154]: ../../../../src/signond/signondisposable.cpp 121 destroyUnused Object unused, deleting:  SignonDaemonNS::SignonSessionCore(0x1f24560)
Feb 13 07:31:29 syncev signond[5154]: ../../../../src/signond/signondisposable.cpp 128 destroyUnused No disposable objects, starting notification timer
Feb 13 07:31:29 syncev signond[5154]: message repeated 2 times: [ ../../../../src/signond/signondisposable.cpp 128 destroyUnused No disposable objects, starting notification timer]
Feb 13 07:31:29 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 241 stop
Feb 13 07:31:29 syncev signonpluginprocess[5156]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 13 07:31:29 syncev signonpluginprocess[5156]: plugin.cpp 49 ~Plugin :
Feb 13 07:31:29 syncev signonpluginprocess[5156]: oauth2plugin.cpp 116 ~OAuth2Plugin :
Feb 13 07:31:29 syncev signonpluginprocess[5156]: oauth2plugin.cpp 93 ~OAuth2PluginPrivate :
Feb 13 07:31:29 syncev signond[5154]: ../../../../src/signond/pluginproxy.cpp 452 onExit Plugin process exit with code  0  :  0
Feb 13 07:31:34 syncev signond[5154]: ../../../../src/signond/credentialsaccessmanager.cpp 669 onEncryptedFSUnmounting
Feb 13 07:31:34 syncev signond[5154]: ../../../../src/signond/credentialsdb.cpp 1303 ~CredentialsDB
Feb 13 07:31:34 syncev signond[5154]: secrets-storage.cpp 50 ~SecretsStorage : Destroyed
Feb 13 07:31:34 syncev signond[5154]: ../../../../src/signond/signondaemon.cpp 86 ~SignonDaemonConfiguration
Comment 12 Patrick Ohly 2015-02-13 15:57:00 UTC
Created attachment 113466 [details] [review]
fix memory leak
Comment 13 Patrick Ohly 2015-02-13 15:57:30 UTC
Created attachment 113467 [details] [review]
address minor performance issue
Comment 14 Patrick Ohly 2015-02-13 15:57:55 UTC
Created attachment 113468 [details] [review]
fix incorrect GVariant usage
Comment 15 Patrick Ohly 2015-02-13 15:58:30 UTC
Created attachment 113469 [details] [review]
unrelated cleanup of username sanity check
Comment 16 Patrick Ohly 2015-02-13 15:58:55 UTC
Created attachment 113470 [details] [review]
handle 403 error
Comment 17 Patrick Ohly 2015-02-16 08:04:45 UTC
In the Google account settings, I revoked access for "Ubuntu". Running the SyncEvolution command still fails:

[DEBUG 00:00:00] using username 'uoa:2,google-contacts' from context for WebDAV, password not set
[DEBUG 00:00:00] looking for identity provider for uoa:2,google-contacts
[DEBUG 00:00:00] looking up account ID 2 and service 'google-contacts'
[DEBUG 00:00:00] enabled service: google-calendar
[DEBUG 00:00:00] enabled service: google-contacts
[DEBUG 00:00:00] signon-identity.c:559: signon_identity_new_from_db 559: 13
[DEBUG 00:00:00] using signond identity 13
[DEBUG 00:00:00] signon-identity.c:627: signon_identity_create_session 627
[DEBUG 00:00:00] signon-identity.c:662: signon_identity_create_session 662
[DEBUG 00:00:00] timout 300s, retry 5s => resending allowed
HTTP session to https://www.googleapis.com:443 begins.
[DEBUG 00:00:00] client cert is missing
[INFO 00:00:00] start database search at https://www.googleapis.com/.well-known/carddav, from sync config '@default', syncURL='https://www.googleapis.com/.well-known/carddav'
[DEBUG 00:00:00] testing https://www.googleapis.com:443/.well-known/carddav
[DEBUG 00:00:00] debugging: read all WebDAV properties of https://www.googleapis.com:443/.well-known/carddav
[DEBUG 00:00:00] starting PROPFIND, credentials unverified, no deadline
[DEBUG 00:00:00] retrieving OAuth2 token
[DEBUG 00:00:00] asking for authentication with method oauth2, mechanism web_server and parameters {'ForceClientAuthViaRequestBody': <true>, 'Host': <'accounts.google.com'>, 'AllowedSchemes': <['https', 'http']>, 'ClientSecret': <'3NbR94RM-DTnA81BWjiJe4TP'>, 'Scope': <['https://www.googleapis.com/auth/userinfo.email', 'https://mail.google.com/', 'https://www.google.com/m8/feeds/', 'https://www.googleapis.com/auth/calendar', 'https://www.googleapis.com/auth/carddav']>, 'ClientId': <'796629365126.apps.googleusercontent.com'>, 'AuthPath': <'o/oauth2/auth?access_type=offline'>, 'ResponseType': <'code'>, 'RedirectUri': <'https://live.gnome.org/Evolution'>, 'TokenPath': <'o/oauth2/token'>}
[DEBUG 00:00:00] signon-identity.c:508: identity_new_from_db_cb
[DEBUG 00:00:00] signon-identity.c:393: identity_registered: /com/google/code/AccountsSSO/SingleSignOn/Identity_0
[DEBUG 00:00:00] signon-identity.c:432: identity_registered: 
[DEBUG 00:00:00] signon-identity-info.c:99: signon_identity_info_new_from_variant: 
[DEBUG 00:00:00] signon-auth-session.c:740: Object path received: /com/google/code/AccountsSSO/SingleSignOn/AuthSession_0
[DEBUG 00:00:00] signon-identity.c:328: State changed to DATA_UPDATED
[DEBUG 00:00:00] signon-identity.c:1000: 1000 identity_process_updated
[DEBUG 00:00:00] authentication result: {'AccessToken': <'ya29.HAE2-D4oehXl9ovlfqoK9jMC7Q7CxD9h293SRW5u4Fhu3c-Xaq3pu3jCpoxm0jyxQK0euunc1bmyiA'>, 'ExpiresIn': <3485>, 'RefreshToken': <'1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT'>}, ???
[DEBUG 00:00:00] got new OAuth2 token 'ya29.HAE2-D4oehXl9ovlfqoK9jMC7Q7CxD9h293SRW5u4Fhu3c-Xaq3pu3jCpoxm0jyxQK0euunc1bmyiA' for next request
ah_create, for WWW-Authenticate
Running pre_send hooks
[DEBUG 00:00:00] using OAuth2 token 'ya29.HAE2-D4oehXl9ovlfqoK9jMC7Q7CxD9h293SRW5u4Fhu3c-Xaq3pu3jCpoxm0jyxQK0euunc1bmyiA' to authenticate
Sending request headers:
PROPFIND /.well-known/carddav HTTP/1.1
Connection: TE
TE: trailers
Host: www.googleapis.com
Depth: 0
Content-Length: 84
Content-Type: application/xml
User-Agent: SyncEvolution
Authorization: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

Sending request-line and headers:
Doing DNS lookup on proxy.vlan13.01.org...
req: Connecting to 10.0.13.1:3128
Running pre_send hooks
[DEBUG 00:00:00] using OAuth2 token 'ya29.HAE2-D4oehXl9ovlfqoK9jMC7Q7CxD9h293SRW5u4Fhu3c-Xaq3pu3jCpoxm0jyxQK0euunc1bmyiA' to authenticate
Sending request headers:
CONNECT www.googleapis.com:443 HTTP/1.1
Connection: TE
TE: trailers
Host: www.googleapis.com
User-Agent: SyncEvolution
Authorization: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

Sending request-line and headers:
Request sent; retry is 0.
[status-line] < HTTP/1.1 200 Connection established
[hdr] 
End of headers.
Running post_headers hooks
Running post_send hooks
Request ends, status 200 class 2xx, error line:
200 Connection established
Running destroy hooks.
Request ends.
Sending request body:
Body block (84 bytes):
[<?xml version="1.0" encoding="utf-8"?>
<propfind xmlns="DAV:"><allprop/></propfind>
]
Request sent; retry is 0.
[status-line] < HTTP/1.1 403 Forbidden
[hdr] Vary: X-Origin
Header Name: [vary], Value: [X-Origin]
[hdr] WWW-Authenticate: Bearer realm="https://accounts.google.com/AuthSubRequest", error=insufficient_scope, scope="https://www.googleapis.com/auth/carddav"
Header Name: [www-authenticate], Value: [Bearer realm="https://accounts.google.com/AuthSubRequest", error=insufficient_scope, scope="https://www.googleapis.com/auth/carddav"]
...
ah_post_send (#0), code is 403 (want 401), WWW-Authenticate is Bearer realm="https://accounts.google.com/AuthSubRequest", error=insufficient_scope, scope="https://www.googleapis.com/auth/carddav"
Request ends, status 403 class 4xx, error line:
403 Forbidden
[DEBUG 00:00:00] discarding used and rejected OAuth2 token 'ya29.HAE2-D4oehXl9ovlfqoK9jMC7Q7CxD9h293SRW5u4Fhu3c-Xaq3pu3jCpoxm0jyxQK0euunc1bmyiA'
[DEBUG 00:00:00] credential error, no success with them before => report it
[DEBUG 00:00:00] PROPFIND: Neon error code 3 = NE_AUTH, HTTP status 401: 403 Forbidden, might retry
[DEBUG 00:00:00] retrying not allowed for PROPFIND (no deadline)
[DEBUG 00:00:00] credentials rejected
Running destroy hooks.
Request ends.
[DEBUG 00:00:00] exception thrown at /data/runtests/work/sources/syncevolution/src/backends/webdav/NeonCXX.cpp:794
[DEBUG 00:00:00] error code from SyncEvolution authorization failed (remote, status 401): PROPFIND: Neon error code 3 = NE_AUTH, HTTP status 401: 403 Forbidden
[DEBUG 00:00:00] read relevant properties of https://www.googleapis.com:443/.well-known/carddav
[DEBUG 00:00:00] starting PROPFIND, credentials unverified, deadline in 299.8s
[DEBUG 00:00:00] retrieving OAuth2 token
[DEBUG 00:00:00] asking for authentication with method oauth2, mechanism web_server and parameters {'ForceTokenRefresh': <true>, 'ForceClientAuthViaRequestBody': <true>, 'Host': <'accounts.google.com'>, 'AllowedSchemes': <['https', 'http']>, 'ClientSecret': <'3NbR94RM-DTnA81BWjiJe4TP'>, 'Scope': <['https://www.googleapis.com/auth/userinfo.email', 'https://mail.google.com/', 'https://www.google.com/m8/feeds/', 'https://www.googleapis.com/auth/calendar', 'https://www.googleapis.com/auth/carddav']>, 'ClientId': <'796629365126.apps.googleusercontent.com'>, 'AuthPath': <'o/oauth2/auth?access_type=offline'>, 'ResponseType': <'code'>, 'RedirectUri': <'https://live.gnome.org/Evolution'>, 'TokenPath': <'o/oauth2/token'>}
[DEBUG 00:00:00] signon-identity.c:328: State changed to DATA_UPDATED
[DEBUG 00:00:00] signon-identity.c:1000: 1000 identity_process_updated
[DEBUG 00:00:00] authentication result: {'AccessToken': <'ya29.HAE6fY_Mm0rD_SidkwygBV8DR7W0vAFSWwfztuSFFoY9EUZDu1DozPmjEQf-X14Z9zoQP8446qy6Ag'>, 'ExpiresIn': <3600>, 'RefreshToken': <''>}, ???
[DEBUG 00:00:00] got new OAuth2 token 'ya29.HAE6fY_Mm0rD_SidkwygBV8DR7W0vAFSWwfztuSFFoY9EUZDu1DozPmjEQf-X14Z9zoQP8446qy6Ag' for next request
ah_create, for WWW-Authenticate
Running pre_send hooks
[DEBUG 00:00:00] using OAuth2 token 'ya29.HAE6fY_Mm0rD_SidkwygBV8DR7W0vAFSWwfztuSFFoY9EUZDu1DozPmjEQf-X14Z9zoQP8446qy6Ag' to authenticate
...

SyncEvolution continues to ask for new access tokens and gets new ones each time. This is different from before, where the same token was returned again and SyncEvolution aborted because of that.

It is a bit strange that signond is able to return new access tokens. Shouldn't it detect that access was revoked?

Here is the corresponding syslog output:

Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signondaemon.cpp 390 init Failed to SUID root. Secure storage will not be available.
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signondaemon.cpp 529 initExtension Loading plugin  "/usr/lib/x86_64-linux-gnu/signon/extensions/libkeyring.so"
Feb 15 23:51:27 syncev signond[156]: virtual SignOn::AbstractSecretsStorage* KeyringPlugin::secretsStorage(QObject*) const
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 45 SecretsStorage : Constructed
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsaccessmanager.cpp 164 finalize Enter
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsaccessmanager.cpp 187 init Initializing CredentialsAccessManager with configuration:  "#012#012====== Credentials Access Manager Configuration ======#012#012Using encryption: true#012Metadata DB path: /data/runtests/work/downstream-vivid-amd64/home/googlecontacts/config/signond/signon.db#012Cryptomanager name: #012ACL manager name: #012Secrets storage name: #012======================================================#012#012"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsaccessmanager.cpp 210 init No AccessControlManager set, using default (dummy)
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsaccessmanager.cpp 225 init No CryptoManager set, using default (dummy)
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsaccessmanager.cpp 653 onEncryptedFSMounted
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsaccessmanager.cpp 239 init No key authorizer set, using default
Feb 15 23:51:27 syncev signond[156]: /build/buildd/signon-8.57+15.04.20150204.1/lib/signond/SignOn/key-handler.cpp 89 initialize No key manager has been registered
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsaccessmanager.cpp 267 init CredentialsAccessManager successfully initialized...
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 133 SqlDatabase Supported Drivers: ("QSQLITE")
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 134 SqlDatabase DATABASE NAME [ "/data/runtests/work/downstream-vivid-amd64/home/googlecontacts/config/signond/signon.db" ]
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 150 init Database connection succeeded.
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 161 init SQL table structure already created...
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 60 initialize : Using keyring: "default"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signondaemon.cpp 502 init Signond SUCCESSFULLY initialized.
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 81 isPeerAllowedToUseIdentity "Access control list of identity: 13: [*].Tokens count: 1#011"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signondaemon.cpp 626 getIdentity Registering identity: 13
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: false
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signondaemon.cpp 652 getIdentity DONE REGISTERING IDENTITY
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 81 isPeerAllowedToUseIdentity "Access control list of identity: 13: [*].Tokens count: 1#011"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signondaemonadaptor.cpp 188 getAuthSessionObjectPath ACM passed, creating AuthSession object
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonauthsession.cpp 60 createAuthSession
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonauthsession.cpp 37 SignonAuthSession
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonauthsession.cpp 44 SignonAuthSession "/com/google/code/AccountsSSO/SingleSignOn/AuthSession_0"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 75 PluginProxy
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/main.cpp 71 main handler: 0x405480
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/main.cpp 87 main "oauth2"
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 186 setupProxySettings
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 90 loadPlugin  loading auth library for  "oauth2"
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 100 loadPlugin library loaded
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 112 loadPlugin constructor resolved
Feb 15 23:51:27 syncev signonpluginprocess[158]: plugin.cpp 44 Plugin :
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 143 loadPlugin plugin is fully initialized
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 149 setupDataStreams
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 165 setupDataStreams cancel thread created
Feb 15 23:51:27 syncev signonpluginprocess[158]: plugin.cpp 56 type :
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 474 queryType
Feb 15 23:51:27 syncev signonpluginprocess[158]: plugin.cpp 56 type :
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 496 queryMechanisms
Feb 15 23:51:27 syncev signonpluginprocess[158]: plugin.cpp 62 mechanisms :
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 519 queryMechanisms ("HMAC-SHA1", "PLAINTEXT", "web_server", "user_agent")
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 172 createNewPluginProxy The process is started
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 135 sessionCore The new session is created : "13+oauth2"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonauthsession.cpp 75 createAuthSession SignonAuthSession created successfully: "/com/google/code/AccountsSSO/SingleSignOn/AuthSession_0"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonauthsessionadaptor.cpp 76 process "web_server"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: false
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 919 startNewRequest Starting the authentication process
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 330 startProcess the number of requests is 1
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 168 isPeerAllowedToAccess "*"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1466 loadData Loading: 13 , "oauth2"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 3 method: 1
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonauthsession.cpp 142 stateChangedSlot
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 372 sessionDataReceived The cancel thread is started
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 85 OAuth2PluginPrivate :
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 111 OAuth2Plugin :
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 229 respondWithStoredToken : Responding with stored token
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 425 disableCancelThread Before the isFinished loop
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 430 disableCancelThread Internal iteration  0
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 1
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 405
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 1
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 346 handlePluginResponse PLUGIN_RESPONSE_RESULT
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 544 processResultReply
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1197 updateCredentials UPDATE: 13
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 1 method: 0
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonidentity.cpp 447 onCredentialsUpdated 13
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 902 startNewRequest No more requests to process
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonauthsessionadaptor.cpp 76 process "web_server"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: false
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 919 startNewRequest Starting the authentication process
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 330 startProcess the number of requests is 1
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 168 isPeerAllowedToAccess "*"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1466 loadData Loading: 13 , "oauth2"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 3 method: 1
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonauthsession.cpp 142 stateChangedSlot
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 372 sessionDataReceived The cancel thread is started
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 116 ~OAuth2Plugin :
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 93 ~OAuth2PluginPrivate :
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 85 OAuth2PluginPrivate :
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 111 OAuth2Plugin :
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 276 process : Clearing access token QMap(("759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com", QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  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")) ) ( "Token" ,  QVariant(QString, "ya29.GQGgoVYW-1MfSW6z2DXHlsMuJdUfaM1V44Sn0BTxgp-fnAPiGFQqhZV0Ij1Ic-g1XJiNSDJgC6vRZQ") ) ( "refresh_token" ,  QVariant(QString, "1/AtmKZaNz_kk0Bu3X7zInJsIN9zp7BTaQ_FgdC_ng954MEudVrK5jSpoR30zcRFq6") ) ( "timestamp" ,  QVariant(uint, 1423829484) ) ) ) ) ( "796629365126.apps.googleusercontent.com" ,  QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  QVariant(QStringList, ("https://www.googleapis.com/auth/userinfo.email", "https://mail.google.com/", "https://www.google.com/m8/feeds/", "https://www.googleapis.com/auth/calendar", "https://www.googleapis.com/auth/carddav")) ) ( "refresh_token" ,  QVariant(QString, "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT") ) ( "timestamp" ,  QVariant(uint, 1424072972) ) ) ) ) )
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 586 refreshOAuth2Token : "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT"
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 598 sendOAuth2PostRequest :
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 623 sendOAuth2PostRequest : Query string =   QUrl( "?grant_type=refresh_token&refresh_token=1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT&client_id=796629365126.apps.googleusercontent.com&client_secret=3NbR94RM-DTnA81BWjiJe4TP" )
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 2
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 2058
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 2
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 357 handlePluginResponse PLUGIN_RESPONSE_STORE
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 629 processStore
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 525 processStoreOperation Processing --- StoreOperation::Blob
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1485 storeData Storing: 13 , "oauth2"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 3 method: 1
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:27 syncev signonpluginprocess[158]: base-plugin.cpp 133 onPostFinished : Finished signal received
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 478 serverReply : "{#012  "access_token" : "ya29.HAE6fY_Mm0rD_SidkwygBV8DR7W0vAFSWwfztuSFFoY9EUZDu1DozPmjEQf-X14Z9zoQP8446qy6Ag",#012  "token_type" : "Bearer",#012  "expires_in" : 3600,#012  "id_token" : "eyJhbGciOiJSUzI1NiIsImtpZCI6Ijk5MjFkYjdhZjZhY2FiZjY0MWNhNDM3YzA0OTJlM2NkOGJiZGE4YTgifQ.eyJpc3MiOiJhY2NvdW50cy5nb29nbGUuY29tIiwiaWQiOiIxMTE3MjE4NDQ0MTIzNDc1Nzc5MzYiLCJzdWIiOiIxMTE3MjE4NDQ0MTIzNDc1Nzc5MzYiLCJhenAiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJlbWFpbCI6InN5bmNldm9sdXRpb24ubGlzdEBnbWFpbC5jb20iLCJhdF9oYXNoIjoidi1Gc2tpcFQ5Y3RrVkxrTnNPMEg5dyIsImVtYWlsX3ZlcmlmaWVkIjp0cnVlLCJhdWQiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJ0b2tlbl9oYXNoIjoidi1Gc2tpcFQ5Y3RrVkxrTnNPMEg5dyIsInZlcmlmaWVkX2VtYWlsIjp0cnVlLCJjaWQiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJpYXQiOjE0MjQwNzI3ODcsImV4cCI6MTQyNDA3NjY4N30.nc8Mo7ZFIP8IAY835lWDrFpyLlklHsDsTH0jABtB0kAjZcgZ4QMwRoE_A7GX_ng087rKkREYSEOupiupmEZKXU7VH_lbLZaPEzgFZ8a17fgg9EFaXySI42zjwsOolqxkP7VGQ_fovv7R9nKdmmPLxf51l14ZWmrXo-KrWRK4Mxg"#012}"
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 482 serverReply : QVariant(int, 200)
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 444 parseReply : application/json content received
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 667 parseJSONReply :
Feb 15 23:51:27 syncev signonpluginprocess[158]: oauth2plugin.cpp 662 storeResponse : QMap(("759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com", QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  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")) ) ( "Token" ,  QVariant(QString, "ya29.GQGgoVYW-1MfSW6z2DXHlsMuJdUfaM1V44Sn0BTxgp-fnAPiGFQqhZV0Ij1Ic-g1XJiNSDJgC6vRZQ") ) ( "refresh_token" ,  QVariant(QString, "1/AtmKZaNz_kk0Bu3X7zInJsIN9zp7BTaQ_FgdC_ng954MEudVrK5jSpoR30zcRFq6") ) ( "timestamp" ,  QVariant(uint, 1423829484) ) ) ) ) ( "796629365126.apps.googleusercontent.com" ,  QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  QVariant(QStringList, ("https://www.googleapis.com/auth/userinfo.email", "https://mail.google.com/", "https://www.google.com/m8/feeds/", "https://www.googleapis.com/auth/calendar", "https://www.googleapis.com/auth/carddav")) ) ( "Token" ,  QVariant(QString, "ya29.HAE6fY_Mm0rD_SidkwygBV8DR7W0vAFSWwfztuSFFoY9EUZDu1DozPmjEQf-X14Z9zoQP8446qy6Ag") ) ( "refresh_token" ,  QVariant(QString, "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT") ) ( "timestamp" ,  QVariant(uint, 1424073087) ) ) ) ) )
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 425 disableCancelThread Before the isFinished loop
Feb 15 23:51:27 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 430 disableCancelThread Internal iteration  0
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 2
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 2247
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 2
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 357 handlePluginResponse PLUGIN_RESPONSE_STORE
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 629 processStore
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 525 processStoreOperation Processing --- StoreOperation::Blob
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1485 storeData Storing: 13 , "oauth2"
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 3 method: 1
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 1
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 273
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 1
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 346 handlePluginResponse PLUGIN_RESPONSE_RESULT
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 544 processResultReply
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1197 updateCredentials UPDATE: 13
Feb 15 23:51:27 syncev signond[156]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 1 method: 0
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonidentity.cpp 447 onCredentialsUpdated 13
Feb 15 23:51:27 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 902 startNewRequest No more requests to process
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/signonauthsessionadaptor.cpp 76 process "web_server"
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: false
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 919 startNewRequest Starting the authentication process
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 330 startProcess the number of requests is 1
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:32 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:32 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 168 isPeerAllowedToAccess "*"
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1466 loadData Loading: 13 , "oauth2"
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 15 23:51:32 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 3 method: 1
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/signonauthsession.cpp 142 stateChangedSlot
Feb 15 23:51:32 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 372 sessionDataReceived The cancel thread is started
Feb 15 23:51:32 syncev signonpluginprocess[158]: oauth2plugin.cpp 116 ~OAuth2Plugin :
Feb 15 23:51:32 syncev signonpluginprocess[158]: oauth2plugin.cpp 93 ~OAuth2PluginPrivate :
Feb 15 23:51:32 syncev signonpluginprocess[158]: oauth2plugin.cpp 85 OAuth2PluginPrivate :
Feb 15 23:51:32 syncev signonpluginprocess[158]: oauth2plugin.cpp 111 OAuth2Plugin :
Feb 15 23:51:32 syncev signonpluginprocess[158]: oauth2plugin.cpp 276 process : Clearing access token QMap(("759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com", QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  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")) ) ( "Token" ,  QVariant(QString, "ya29.GQGgoVYW-1MfSW6z2DXHlsMuJdUfaM1V44Sn0BTxgp-fnAPiGFQqhZV0Ij1Ic-g1XJiNSDJgC6vRZQ") ) ( "refresh_token" ,  QVariant(QString, "1/AtmKZaNz_kk0Bu3X7zInJsIN9zp7BTaQ_FgdC_ng954MEudVrK5jSpoR30zcRFq6") ) ( "timestamp" ,  QVariant(uint, 1423829484) ) ) ) ) ( "796629365126.apps.googleusercontent.com" ,  QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  QVariant(QStringList, ("https://www.googleapis.com/auth/userinfo.email", "https://mail.google.com/", "https://www.google.com/m8/feeds/", "https://www.googleapis.com/auth/calendar", "https://www.googleapis.com/auth/carddav")) ) ( "refresh_token" ,  QVariant(QString, "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT") ) ( "timestamp" ,  QVariant(uint, 1424073087) ) ) ) ) )
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 2
Feb 15 23:51:32 syncev signonpluginprocess[158]: oauth2plugin.cpp 586 refreshOAuth2Token : "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT"
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 2058
Feb 15 23:51:32 syncev signonpluginprocess[158]: oauth2plugin.cpp 598 sendOAuth2PostRequest :
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 2
Feb 15 23:51:32 syncev signonpluginprocess[158]: oauth2plugin.cpp 623 sendOAuth2PostRequest : Query string =   QUrl( "?grant_type=refresh_token&refresh_token=1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT&client_id=796629365126.apps.googleusercontent.com&client_secret=3NbR94RM-DTnA81BWjiJe4TP" )
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 357 handlePluginResponse PLUGIN_RESPONSE_STORE
Feb 15 23:51:32 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 629 processStore
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 525 processStoreOperation Processing --- StoreOperation::Blob
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1485 storeData Storing: 13 , "oauth2"
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 15 23:51:32 syncev signond[156]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 3 method: 1
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:32 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:32 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:32 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:32 syncev signonpluginprocess[158]: base-plugin.cpp 133 onPostFinished : Finished signal received
Feb 15 23:51:32 syncev signonpluginprocess[158]: oauth2plugin.cpp 478 serverReply : "{#012  "access_token" : "ya29.HAEBW13ydDUgnkd6OVd1qy8urPAnoAU9dUE7gZQmOH4UZ6F9TA36XFkGLCWurVHx8GPbOdyHO2Z5gQ",#012  "token_type" : "Bearer",#012  "expires_in" : 3600,#012  "id_token" : "eyJhbGciOiJSUzI1NiIsImtpZCI6Ijk5MjFkYjdhZjZhY2FiZjY0MWNhNDM3YzA0OTJlM2NkOGJiZGE4YTgifQ.eyJpc3MiOiJhY2NvdW50cy5nb29nbGUuY29tIiwiaWQiOiIxMTE3MjE4NDQ0MTIzNDc1Nzc5MzYiLCJzdWIiOiIxMTE3MjE4NDQ0MTIzNDc1Nzc5MzYiLCJhenAiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJlbWFpbCI6InN5bmNldm9sdXRpb24ubGlzdEBnbWFpbC5jb20iLCJhdF9oYXNoIjoiWHJBa2NOZU5ad2lySHNqdW45WnpaQSIsImVtYWlsX3ZlcmlmaWVkIjp0cnVlLCJhdWQiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJ0b2tlbl9oYXNoIjoiWHJBa2NOZU5ad2lySHNqdW45WnpaQSIsInZlcmlmaWVkX2VtYWlsIjp0cnVlLCJjaWQiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJpYXQiOjE0MjQwNzI3OTIsImV4cCI6MTQyNDA3NjY5Mn0.QavcFiV4iEbob7KHjkD9F2beCN_gKC-ktulr3D4duNg34vjhDVztVquiHhgdyieJaEYf-UeGxwu3qGr5F6RQziVJdX8Q0J5Uj5E2Pg7v1Jzxvn212hp3RK806Wu5hfwq0u3xFe67JNLddCuw00OfZXUbqwVy6VpuGxoXqUbAn8Y"#012}"
Feb 15 23:51:33 syncev signonpluginprocess[158]: oauth2plugin.cpp 482 serverReply : QVariant(int, 200)
Feb 15 23:51:33 syncev signonpluginprocess[158]: oauth2plugin.cpp 444 parseReply : application/json content received
Feb 15 23:51:33 syncev signonpluginprocess[158]: oauth2plugin.cpp 667 parseJSONReply :
Feb 15 23:51:33 syncev signonpluginprocess[158]: oauth2plugin.cpp 662 storeResponse : QMap(("759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com", QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  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")) ) ( "Token" ,  QVariant(QString, "ya29.GQGgoVYW-1MfSW6z2DXHlsMuJdUfaM1V44Sn0BTxgp-fnAPiGFQqhZV0Ij1Ic-g1XJiNSDJgC6vRZQ") ) ( "refresh_token" ,  QVariant(QString, "1/AtmKZaNz_kk0Bu3X7zInJsIN9zp7BTaQ_FgdC_ng954MEudVrK5jSpoR30zcRFq6") ) ( "timestamp" ,  QVariant(uint, 1423829484) ) ) ) ) ( "796629365126.apps.googleusercontent.com" ,  QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  QVariant(QStringList, ("https://www.googleapis.com/auth/userinfo.email", "https://mail.google.com/", "https://www.google.com/m8/feeds/", "https://www.googleapis.com/auth/calendar", "https://www.googleapis.com/auth/carddav")) ) ( "Token" ,  QVariant(QString, "ya29.HAEBW13ydDUgnkd6OVd1qy8urPAnoAU9dUE7gZQmOH4UZ6F9TA36XFkGLCWurVHx8GPbOdyHO2Z5gQ") ) ( "refresh_token" ,  QVariant(QString, "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT") ) ( "timestamp" ,  QVariant(uint, 1424073092) ) ) ) ) )
Feb 15 23:51:33 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 425 disableCancelThread Before the isFinished loop
Feb 15 23:51:33 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 430 disableCancelThread Internal iteration  0
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 2
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 2247
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 2
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 357 handlePluginResponse PLUGIN_RESPONSE_STORE
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 629 processStore
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 525 processStoreOperation Processing --- StoreOperation::Blob
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1485 storeData Storing: 13 , "oauth2"
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 15 23:51:33 syncev signond[156]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 3 method: 1
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:33 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:33 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 1
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 273
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 1
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 346 handlePluginResponse PLUGIN_RESPONSE_RESULT
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 544 processResultReply
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:33 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:33 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1197 updateCredentials UPDATE: 13
Feb 15 23:51:33 syncev signond[156]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 1 method: 0
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/signonidentity.cpp 447 onCredentialsUpdated 13
Feb 15 23:51:33 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 902 startNewRequest No more requests to process
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonauthsessionadaptor.cpp 76 process "web_server"
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: false
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 919 startNewRequest Starting the authentication process
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 330 startProcess the number of requests is 1
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 168 isPeerAllowedToAccess "*"
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1466 loadData Loading: 13 , "oauth2"
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 3 method: 1
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonauthsession.cpp 142 stateChangedSlot
Feb 15 23:51:43 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 372 sessionDataReceived The cancel thread is started
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 116 ~OAuth2Plugin :
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 93 ~OAuth2PluginPrivate :
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 85 OAuth2PluginPrivate :
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 111 OAuth2Plugin :
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 276 process : Clearing access token QMap(("759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com", QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  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")) ) ( "Token" ,  QVariant(QString, "ya29.GQGgoVYW-1MfSW6z2DXHlsMuJdUfaM1V44Sn0BTxgp-fnAPiGFQqhZV0Ij1Ic-g1XJiNSDJgC6vRZQ") ) ( "refresh_token" ,  QVariant(QString, "1/AtmKZaNz_kk0Bu3X7zInJsIN9zp7BTaQ_FgdC_ng954MEudVrK5jSpoR30zcRFq6") ) ( "timestamp" ,  QVariant(uint, 1423829484) ) ) ) ) ( "796629365126.apps.googleusercontent.com" ,  QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  QVariant(QStringList, ("https://www.googleapis.com/auth/userinfo.email", "https://mail.google.com/", "https://www.google.com/m8/feeds/", "https://www.googleapis.com/auth/calendar", "https://www.googleapis.com/auth/carddav")) ) ( "refresh_token" ,  QVariant(QString, "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT") ) ( "timestamp" ,  QVariant(uint, 1424073092) ) ) ) ) )
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 586 refreshOAuth2Token : "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT"
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 598 sendOAuth2PostRequest :
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 2
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 623 sendOAuth2PostRequest : Query string =   QUrl( "?grant_type=refresh_token&refresh_token=1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT&client_id=796629365126.apps.googleusercontent.com&client_secret=3NbR94RM-DTnA81BWjiJe4TP" )
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 2058
Feb 15 23:51:43 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 2
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 357 handlePluginResponse PLUGIN_RESPONSE_STORE
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 629 processStore
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 525 processStoreOperation Processing --- StoreOperation::Blob
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1485 storeData Storing: 13 , "oauth2"
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 3 method: 1
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:43 syncev signonpluginprocess[158]: base-plugin.cpp 133 onPostFinished : Finished signal received
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 478 serverReply : "{#012  "access_token" : "ya29.HAGH0BTET6FYQKZiUA8DnN561-buRtyhqwJ0JOKB8jRTqLcE-tP6SqT31LKdBh_Yene7-ZAGw7wfQw",#012  "token_type" : "Bearer",#012  "expires_in" : 3600,#012  "id_token" : "eyJhbGciOiJSUzI1NiIsImtpZCI6Ijk5MjFkYjdhZjZhY2FiZjY0MWNhNDM3YzA0OTJlM2NkOGJiZGE4YTgifQ.eyJpc3MiOiJhY2NvdW50cy5nb29nbGUuY29tIiwiaWQiOiIxMTE3MjE4NDQ0MTIzNDc1Nzc5MzYiLCJzdWIiOiIxMTE3MjE4NDQ0MTIzNDc1Nzc5MzYiLCJhenAiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJlbWFpbCI6InN5bmNldm9sdXRpb24ubGlzdEBnbWFpbC5jb20iLCJhdF9oYXNoIjoiRzk2cFJNcEkxMk5fYW5sMDRRbjNadyIsImVtYWlsX3ZlcmlmaWVkIjp0cnVlLCJhdWQiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJ0b2tlbl9oYXNoIjoiRzk2cFJNcEkxMk5fYW5sMDRRbjNadyIsInZlcmlmaWVkX2VtYWlsIjp0cnVlLCJjaWQiOiI3OTY2MjkzNjUxMjYuYXBwcy5nb29nbGV1c2VyY29udGVudC5jb20iLCJpYXQiOjE0MjQwNzI4MDMsImV4cCI6MTQyNDA3NjcwM30.ex0WaLvoNdv1yoxvFfi2w2vyR9UhLU5UaLExesgL9iXbW7PzKKtMKPI3SI4mInWCOpy9_t01HpYIuAirEwQqxyS9W2XMFBsHcgoKNj97T-9hcZdaBhZqw49yRSf0GeSGuLEST9PH2GmBCIa8V6NSutppg31HV2cxJHkvIyiaWDg"#012}"
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 482 serverReply : QVariant(int, 200)
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 444 parseReply : application/json content received
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 667 parseJSONReply :
Feb 15 23:51:43 syncev signonpluginprocess[158]: oauth2plugin.cpp 662 storeResponse : QMap(("759250720802-4sii0me9963n9fdqdmi7cepn6ub8luoh.apps.googleusercontent.com", QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  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")) ) ( "Token" ,  QVariant(QString, "ya29.GQGgoVYW-1MfSW6z2DXHlsMuJdUfaM1V44Sn0BTxgp-fnAPiGFQqhZV0Ij1Ic-g1XJiNSDJgC6vRZQ") ) ( "refresh_token" ,  QVariant(QString, "1/AtmKZaNz_kk0Bu3X7zInJsIN9zp7BTaQ_FgdC_ng954MEudVrK5jSpoR30zcRFq6") ) ( "timestamp" ,  QVariant(uint, 1423829484) ) ) ) ) ( "796629365126.apps.googleusercontent.com" ,  QVariant(QVariantMap, QMap(("Expiry", QVariant(int, 3600) ) ( "Scopes" ,  QVariant(QStringList, ("https://www.googleapis.com/auth/userinfo.email", "https://mail.google.com/", "https://www.google.com/m8/feeds/", "https://www.googleapis.com/auth/calendar", "https://www.googleapis.com/auth/carddav")) ) ( "Token" ,  QVariant(QString, "ya29.HAGH0BTET6FYQKZiUA8DnN561-buRtyhqwJ0JOKB8jRTqLcE-tP6SqT31LKdBh_Yene7-ZAGw7wfQw") ) ( "refresh_token" ,  QVariant(QString, "1/gX5Mzu-8lxBnWQJC8SUFx7gCOLgG3dsZ4EOZW9jauDx90RDknAdJa_sgfheVM0XT") ) ( "timestamp" ,  QVariant(uint, 1424073103) ) ) ) ) )
Feb 15 23:51:43 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 425 disableCancelThread Before the isFinished loop
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 2
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 2247
Feb 15 23:51:43 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 430 disableCancelThread Internal iteration  0
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 2
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 357 handlePluginResponse PLUGIN_RESPONSE_STORE
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 629 processStore
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 525 processStoreOperation Processing --- StoreOperation::Blob
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1485 storeData Storing: 13 , "oauth2"
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 3 method: 1
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 1
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 273
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 1
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 346 handlePluginResponse PLUGIN_RESPONSE_RESULT
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 544 processResultReply
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 13 queryPassword: true
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 2 method: 0
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 197 loadSecret : id: 13 type: 1 method: 0
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 516 processStoreOperation Processing store operation.
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1197 updateCredentials UPDATE: 13
Feb 15 23:51:43 syncev signond[156]: secrets-storage.cpp 159 storeSecret : Storing secret: 13 type: 1 method: 0
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonidentity.cpp 447 onCredentialsUpdated 13
Feb 15 23:51:43 syncev signond[156]: ../../../../src/signond/signonsessioncore.cpp 902 startNewRequest No more requests to process
Feb 15 23:52:14 syncev signond[156]: ../../../../src/signond/signondisposable.cpp 121 destroyUnused Object unused, deleting:  SignonDaemonNS::SignonIdentity(0x22f9dd0, name = "/com/google/code/AccountsSSO/SingleSignOn/Identity_0")
Feb 15 23:52:14 syncev signond[156]: QObject::disconnect: Unexpected null parameter
Feb 15 23:52:14 syncev signond[156]: ../../../../src/signond/signondisposable.cpp 121 destroyUnused Object unused, deleting:  SignonDaemonNS::SignonSessionCore(0x22d3ac0)
Feb 15 23:52:14 syncev signond[156]: ../../../../src/signond/signonauthsession.cpp 52 ~SignonAuthSession
Feb 15 23:52:14 syncev signond[156]: ../../../../src/signond/signondisposable.cpp 121 destroyUnused Object unused, deleting:  SignonDaemonNS::SignonSessionCore(0x22d3ac0)
Feb 15 23:52:14 syncev signond[156]: ../../../../src/signond/signondisposable.cpp 128 destroyUnused No disposable objects, starting notification timer
Feb 15 23:52:14 syncev signond[156]: message repeated 2 times: [ ../../../../src/signond/signondisposable.cpp 128 destroyUnused No disposable objects, starting notification timer]
Feb 15 23:52:14 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 241 stop
Feb 15 23:52:14 syncev signonpluginprocess[158]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 15 23:52:14 syncev signonpluginprocess[158]: plugin.cpp 49 ~Plugin :
Feb 15 23:52:14 syncev signonpluginprocess[158]: oauth2plugin.cpp 116 ~OAuth2Plugin :
Feb 15 23:52:14 syncev signonpluginprocess[158]: oauth2plugin.cpp 93 ~OAuth2PluginPrivate :
Feb 15 23:52:14 syncev signond[156]: ../../../../src/signond/pluginproxy.cpp 452 onExit Plugin process exit with code  0  :  0
Feb 15 23:52:19 syncev signond[156]: ../../../../src/signond/credentialsaccessmanager.cpp 669 onEncryptedFSUnmounting
Feb 15 23:52:19 syncev signond[156]: ../../../../src/signond/credentialsdb.cpp 1303 ~CredentialsDB
Feb 15 23:52:19 syncev signond[156]: secrets-storage.cpp 50 ~SecretsStorage : Destroyed
Feb 15 23:52:19 syncev signond[156]: ../../../../src/signond/signondaemon.cpp 86 ~SignonDaemonConfiguration
Comment 18 Patrick Ohly 2015-02-16 08:17:25 UTC
I deleted the "broken" account and re-created it. Now SyncEvolution fails differently, with "userActionFinished error: 10". What does that mean?

[DEBUG 00:00:00] using username 'uoa:3,google-contacts' from context for WebDAV, password not set
[DEBUG 00:00:00] looking for identity provider for uoa:3,google-contacts
[DEBUG 00:00:00] looking up account ID 3 and service 'google-contacts'
[DEBUG 00:00:00] enabled service: google-calendar
[DEBUG 00:00:00] enabled service: google-contacts
[DEBUG 00:00:00] signon-identity.c:559: signon_identity_new_from_db 559: 14
[DEBUG 00:00:00] using signond identity 14
[DEBUG 00:00:00] signon-identity.c:627: signon_identity_create_session 627
[DEBUG 00:00:00] signon-identity.c:662: signon_identity_create_session 662
[DEBUG 00:00:00] timout 300s, retry 5s => resending allowed
HTTP session to https://www.googleapis.com:443 begins.
[DEBUG 00:00:00] client cert is missing
[INFO 00:00:00] start database search at https://www.googleapis.com/.well-known/carddav, from sync config '@default', syncURL='https://www.googleapis.com/.well-known/carddav'
[DEBUG 00:00:00] testing https://www.googleapis.com:443/.well-known/carddav
[DEBUG 00:00:00] debugging: read all WebDAV properties of https://www.googleapis.com:443/.well-known/carddav
[DEBUG 00:00:00] starting PROPFIND, credentials unverified, no deadline
[DEBUG 00:00:00] retrieving OAuth2 token
[DEBUG 00:00:00] asking for authentication with method oauth2, mechanism web_server and parameters {'ForceClientAuthViaRequestBody': <true>, 'Host': <'accounts.google.com'>, 'AllowedSchemes': <['https', 'http']>, 'ClientSecret': <'3NbR94RM-DTnA81BWjiJe4TP'>, 'Scope': <['https://www.googleapis.com/auth/userinfo.email', 'https://mail.google.com/', 'https://www.google.com/m8/feeds/', 'https://www.googleapis.com/auth/calendar', 'https://www.googleapis.com/auth/carddav']>, 'ClientId': <'796629365126.apps.googleusercontent.com'>, 'AuthPath': <'o/oauth2/auth?access_type=offline'>, 'ResponseType': <'code'>, 'RedirectUri': <'https://live.gnome.org/Evolution'>, 'TokenPath': <'o/oauth2/token'>}
[DEBUG 00:00:00] signon-identity.c:508: identity_new_from_db_cb
[DEBUG 00:00:00] signon-identity.c:393: identity_registered: /com/google/code/AccountsSSO/SingleSignOn/Identity_0
[DEBUG 00:00:00] signon-identity.c:432: identity_registered: 
[DEBUG 00:00:00] signon-identity-info.c:99: signon_identity_info_new_from_variant: 
[DEBUG 00:00:00] signon-auth-session.c:740: Object path received: /com/google/code/AccountsSSO/SingleSignOn/AuthSession_0
[DEBUG 00:00:00] authentication result: <<null>>, GDBus.Error:com.google.code.AccountsSSO.SingleSignOn.Error.UserInteraction: userActionFinished error: 10
[DEBUG 00:00:00] exception thrown at /data/runtests/work/sources/syncevolution/src/backends/signon/signon-accounts.cpp:186
[ERROR 00:00:00] error code from SyncEvolution access denied (remote, status 403): could not authenticate: GDBus.Error:com.google.code.AccountsSSO.SingleSignOn.Error.UserInteraction: userActionFinished error: 10
[ERROR 00:00:00] logging into remote service failed: error code from SyncEvolution access denied (remote, status 403): could not authenticate: GDBus.Error:com.google.code.AccountsSSO.SingleSignOn.Error.UserInteraction: userActionFinished error: 10


syslog:

Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signondaemon.cpp 390 init Failed to SUID root. Secure storage will not be available.
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signondaemon.cpp 529 initExtension Loading plugin  "/usr/lib/x86_64-linux-gnu/signon/extensions/libkeyring.so"
Feb 16 00:11:58 syncev signond[372]: virtual SignOn::AbstractSecretsStorage* KeyringPlugin::secretsStorage(QObject*) const
Feb 16 00:11:58 syncev signond[372]: secrets-storage.cpp 45 SecretsStorage : Constructed
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsaccessmanager.cpp 164 finalize Enter
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsaccessmanager.cpp 187 init Initializing CredentialsAccessManager with configuration:  "#012#012====== Credentials Access Manager Configuration ======#012#012Using encryption: true#012Metadata DB path: /data/runtests/work/downstream-vivid-amd64/home/googlecontacts/config/signond/signon.db#012Cryptomanager name: #012ACL manager name: #012Secrets storage name: #012======================================================#012#012"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsaccessmanager.cpp 210 init No AccessControlManager set, using default (dummy)
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsaccessmanager.cpp 225 init No CryptoManager set, using default (dummy)
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsaccessmanager.cpp 653 onEncryptedFSMounted
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsaccessmanager.cpp 239 init No key authorizer set, using default
Feb 16 00:11:58 syncev signond[372]: /build/buildd/signon-8.57+15.04.20150204.1/lib/signond/SignOn/key-handler.cpp 89 initialize No key manager has been registered
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsaccessmanager.cpp 267 init CredentialsAccessManager successfully initialized...
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 133 SqlDatabase Supported Drivers: ("QSQLITE")
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 134 SqlDatabase DATABASE NAME [ "/data/runtests/work/downstream-vivid-amd64/home/googlecontacts/config/signond/signon.db" ]
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 150 init Database connection succeeded.
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 161 init SQL table structure already created...
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsaccessmanager.cpp 399 openSecretsDB Database name: [ "/data/runtests/work/downstream-vivid-amd64/home/googlecontacts/config/signond/signon-secrets.db" ]
Feb 16 00:11:58 syncev signond[372]: secrets-storage.cpp 60 initialize : Using keyring: "default"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signondaemon.cpp 502 init Signond SUCCESSFULLY initialized.
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 81 isPeerAllowedToUseIdentity "Access control list of identity: 14: [*].Tokens count: 1#011"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signondaemon.cpp 626 getIdentity Registering identity: 14
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 14 queryPassword: false
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signondaemon.cpp 652 getIdentity DONE REGISTERING IDENTITY
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 81 isPeerAllowedToUseIdentity "Access control list of identity: 14: [*].Tokens count: 1#011"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signondaemonadaptor.cpp 188 getAuthSessionObjectPath ACM passed, creating AuthSession object
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonauthsession.cpp 60 createAuthSession
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonauthsession.cpp 37 SignonAuthSession
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonauthsession.cpp 44 SignonAuthSession "/com/google/code/AccountsSSO/SingleSignOn/AuthSession_0"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 75 PluginProxy
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/main.cpp 71 main handler: 0x405480
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/main.cpp 87 main "oauth2"
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 186 setupProxySettings
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 90 loadPlugin  loading auth library for  "oauth2"
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 100 loadPlugin library loaded
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 112 loadPlugin constructor resolved
Feb 16 00:11:58 syncev signonpluginprocess[374]: plugin.cpp 44 Plugin :
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 143 loadPlugin plugin is fully initialized
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 149 setupDataStreams
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 165 setupDataStreams cancel thread created
Feb 16 00:11:58 syncev signonpluginprocess[374]: plugin.cpp 56 type :
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 474 queryType
Feb 16 00:11:58 syncev signonpluginprocess[374]: plugin.cpp 56 type :
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 496 queryMechanisms
Feb 16 00:11:58 syncev signonpluginprocess[374]: plugin.cpp 62 mechanisms :
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 519 queryMechanisms ("HMAC-SHA1", "PLAINTEXT", "web_server", "user_agent")
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 172 createNewPluginProxy The process is started
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonsessioncore.cpp 135 sessionCore The new session is created : "14+oauth2"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonauthsession.cpp 75 createAuthSession SignonAuthSession created successfully: "/com/google/code/AccountsSSO/SingleSignOn/AuthSession_0"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonauthsessionadaptor.cpp 76 process "web_server"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 14 queryPassword: false
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonsessioncore.cpp 919 startNewRequest Starting the authentication process
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonsessioncore.cpp 330 startProcess the number of requests is 1
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 14 queryPassword: true
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 16 00:11:58 syncev signond[372]: secrets-storage.cpp 197 loadSecret : id: 14 type: 2 method: 0
Feb 16 00:11:58 syncev signond[372]: secrets-storage.cpp 197 loadSecret : id: 14 type: 1 method: 0
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 168 isPeerAllowedToAccess "*"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 1466 loadData Loading: 14 , "oauth2"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 703 methodId method: "oauth2"
Feb 16 00:11:58 syncev signond[372]: secrets-storage.cpp 197 loadSecret : id: 14 type: 3 method: 1
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonauthsession.cpp 142 stateChangedSlot
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 372 sessionDataReceived The cancel thread is started
Feb 16 00:11:58 syncev signonpluginprocess[374]: oauth2plugin.cpp 85 OAuth2PluginPrivate :
Feb 16 00:11:58 syncev signonpluginprocess[374]: oauth2plugin.cpp 111 OAuth2Plugin :
Feb 16 00:11:58 syncev signonpluginprocess[374]: oauth2plugin.cpp 159 sendOAuth2AuthRequest : Url =  "https://accounts.google.com/o/oauth2/auth?access_type=offline&client_id=796629365126.apps.googleusercontent.com&redirect_uri=https://live.gnome.org/Evolution&response_type=code&type=web_server&scope=https://www.googleapis.com/auth/userinfo.email https://mail.google.com/ https://www.google.com/m8/feeds/ https://www.googleapis.com/auth/calendar https://www.googleapis.com/auth/carddav"
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 254 userActionRequired
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 425 disableCancelThread Before the isFinished loop
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 5
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 327 onReadStandardOutput PROXY EXPECTED DATA SIZE: 1028
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 5
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 365 handlePluginResponse PLUGIN_RESPONSE_UI
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 394 handlePluginResponse open ui
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonsessioncore.cpp 681 processUiRequest
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/accesscontrolmanagerhelper.cpp 141 appIdOfPeer ""
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonsessioncore.cpp 723 processUiRequest Caption missing
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 1374 credentials id: 14 queryPassword: true
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/credentialsdb.cpp 1380 credentials Loading credentials from DB.
Feb 16 00:11:58 syncev signond[372]: secrets-storage.cpp 197 loadSecret : id: 14 type: 2 method: 0
Feb 16 00:11:58 syncev signond[372]: secrets-storage.cpp 197 loadSecret : id: 14 type: 1 method: 0
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonsessioncore.cpp 727 processUiRequest Got caption:  "Google"
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 198 processUi
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 372 sessionDataReceived The cancel thread is started
Feb 16 00:11:58 syncev signonpluginprocess[374]: plugin.cpp 128 userActionFinished :
Feb 16 00:11:58 syncev signonpluginprocess[374]: oauth2plugin.cpp 338 userActionFinished :
Feb 16 00:11:58 syncev signonpluginprocess[374]: oauth2plugin.cpp 341 userActionFinished : userActionFinished with error:  10
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 425 disableCancelThread Before the isFinished loop
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 430 disableCancelThread Internal iteration  0
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 306 onReadStandardOutput PROXY RESULT OPERATION: 3
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 343 handlePluginResponse 3
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/pluginproxy.cpp 408 handlePluginResponse PLUGIN_RESPONSE_ERROR
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonsessioncore.cpp 781 processError
Feb 16 00:11:58 syncev signond[372]: ../../../../src/signond/signonsessioncore.cpp 902 startNewRequest No more requests to process
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 249 error error is sent 313   "userActionFinished error: 10"
Feb 16 00:11:58 syncev signonpluginprocess[374]: ../../../../src/remotepluginprocess/remotepluginprocess.cpp 496 startTask operation is completed

Starting signon-ui manually made no difference.

Starting /usr/bin/online-accounts-preferences shows that additional access must be granted for the account. Google reports that "GNOME Evolution (developer: marty.tardi...)" wants to access contacts via CardDAV and asks for confirmation.

Granting that and re-running SyncEvolution leads to a different failure:

[<?xml version="1.0" encoding="UTF-8"?>
<errors xmlns="http://schemas.google.com/g/2005">
 <error>
  <domain>usageLimits</domain>
  <code>accessNotConfigured</code>
  <internalReason>Access Not Configured. The API (CardDAV API) is not enabled for your project. Please use the Google Developers Console to update your configuration.</internalReason>
  <extendedHelp>https://console.developers.google.com</extendedHelp>
 </error>
</errors>
]
Comment 19 Patrick Ohly 2015-02-16 08:22:31 UTC
Mardy, can you ensure that the Ubuntu desktop configuration for "google-contacts" includes CardDAV? It would make the default system usable for SyncEvolution, which is at least useful for testing.

To be fixed:
- /usr/share/accounts/services/google-contacts.service must include 'https://www.googleapis.com/auth/carddav' in 'Scope'
- Google console must have CardDAV enabled

I could patch my local Vivid installation further such that it uses my own developer account, but I think it would be better to fix this for everyone in Ubuntu. It certainly would be easier for me ;-}

Once you have the console settings changed, I can continue testing and integrating these patches.
Comment 20 Patrick Ohly 2015-02-23 14:07:05 UTC
(In reply to Patrick Ohly from comment #17)
> In the Google account settings, I revoked access for "Ubuntu". Running the
> SyncEvolution command still fails:
[...]
> SyncEvolution continues to ask for new access tokens and gets new ones each
> time. This is different from before, where the same token was returned again
> and SyncEvolution aborted because of that.
> 
> It is a bit strange that signond is able to return new access tokens.
> Shouldn't it detect that access was revoked?

That's because "google-contacts.service" is not using the "Ubuntu" key for which I had revoked access. I should have revoked access for "Evolution" key used by google-contacts.service.
Comment 21 Patrick Ohly 2015-03-03 09:49:54 UTC
Created attachment 113939 [details] [review]
signon: move libaccounts-based plugins into their own source file
Comment 22 Patrick Ohly 2015-03-03 09:50:15 UTC
Created attachment 113940 [details] [review]
AuthProvider: removed failure count
Comment 23 Patrick Ohly 2015-03-03 09:50:30 UTC
Created attachment 113941 [details] [review]
signon-accounts: do not create identities on the fly
Comment 24 Patrick Ohly 2015-03-03 09:51:02 UTC
Created attachment 113942 [details] [review]
signon-accounts: pass the AgAuthData to the SignonAuthProvider
Comment 25 Patrick Ohly 2015-03-03 09:51:27 UTC
Created attachment 113943 [details] [review]
signon-accounts: implement getCredentials
Comment 26 Patrick Ohly 2015-03-03 09:51:50 UTC
Created attachment 113944 [details] [review]
signon: ensure consistent use of "username" provider prefix
Comment 27 Patrick Ohly 2015-03-03 09:52:10 UTC
Created attachment 113945 [details] [review]
WebDAV: handle 403 during Google OAuth authentication
Comment 28 Patrick Ohly 2015-03-03 09:55:53 UTC
Alberto, I am done with testing and cleaning up the patches. I squashed my fixes into your commits, with small comments in the commit message explaining how they differ from the original ones.

I also re-uploaded the unrelated "username" error message cleanup and the Google 403 workaround.

Can you check the patches one last time on your side and give me your heads up for merging them into master?
Comment 29 Alberto Mardegan 2015-04-01 11:30:49 UTC
Thanks Patrick for the thorough review. I've reviewed your changes and they are all correct. The last two new commits are also good to go.
Comment 30 Patrick Ohly 2015-04-01 13:16:01 UTC
Merged into master branch.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.