search

GluuFederation / gluu-passport

Gluu interface to Passport.js to support social login and inbound identity.
Apache License 2.0
6 stars 17 forks source link

4.0 QA - Error first time login with passport social #63

Closed sahilIT2020 closed 5 years ago

sahilIT2020 commented 5 years ago

Description: User gets error when logins for the first time using passport social strategies.

Steps to reproduce:

  1. Enable passport social authentication script, and setup using passport-google-oauth2

image

  1. go to Configuration > Manage Authentication and enable oxtrust default authentication as "passport_social"
  2. Try to login to oxtrust.

User gets following error image

But all subsequent logins are successful, so this happens only when user is created internally.

Environment details Gluu4.0 on centos 7x with couchbase as backend db.

Passport logs

2019-06-17T13:34:50.758Z [INFO] ::ffff:127.0.0.1 - GET /passport/token HTTP/1.1 200 201 - 0.676 ms 2019-06-17T13:34:51.091Z [INFO] ::ffff:127.0.0.1 - GET /passport/auth/googleae8b/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJqd3QiOiJhNjZmNTZhNC1iMjI1LTQ0NGYtYWEwYi03YmNmZjZkMzFmMzUiLCJpYXQiOjE1NjA3Nzg0OTAsImV4cCI6MTU2MDc3ODYxMH0.F55ytIZFRLyjL25i1hfFtBR5eIGuHGetESnhEPVo7NE HTTP/1.1 302 0 - 1.033 ms 2019-06-17T13:35:21.909Z [INFO] Applying mapping 'google' to profile 2019-06-17T13:35:21.910Z [INFO] User 103308851640042732468 authenticated with provider googleae8b 2019-06-17T13:35:21.912Z [INFO] ::ffff:127.0.0.1 - GET /passport/auth/googleae8b/callback?code=4%2FawFzoK_FxWBOEXwqSNZqb2OlbB2C_ceiBQ7uw92A_6Rm4sJ-IAA6LxwJELae376y2SMDxJT1JlLYZZKHyh8QYyU&scope=email+profile+https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fuserinfo.profile+https%3A%2F%2Fwww.googleapis.com%2Fauth%2Fuserinfo.email HTTP/1.1 200 1527 - 127.961 ms 2019-06-17T13:35:29.377Z [INFO] getConfiguration. Passport configs received 2019-06-17T13:35:29.378Z [INFO] Configuration data received 2019-06-17T13:35:29.378Z [INFO] Configuration data has been parsed

oxauth_Script logs 2019-06-17 13:34:46,697 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:277) - Executing python 'getPageForStep' authenticator method 2019-06-17 13:34:46,697 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getPageForStep called 2019-06-17 13:34:47,045 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:384) - Validating acr_values: 'passport_social' 2019-06-17 13:34:47,045 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:151) - Executing python 'isValidAuthenticationMethod' authenticator method 2019-06-17 13:34:47,045 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:249) - Executing python 'prepareForStep' authenticator method 2019-06-17 13:34:47,045 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. prepareForStep called 1 2019-06-17 13:34:47,046 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. parseAllProviders. Adding providers 2019-06-17 13:34:47,146 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. parseProviderConfigs. Configured providers: 2019-06-17 13:34:47,146 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - {u'googleae8b': {'requestForEmail': False, 'displayName': u'google', 'emailLinkingSafe': False, 'type': u'oauth', 'logo_img': None, 'saml': False}, u'myadfs50d7': {'requestForEmail': False, 'displayName': u'My ADFS', 'emailLinkingSafe': False, 'type': u'openidconnect', 'logo_img': None, 'saml': False}} 2019-06-17 13:34:47,147 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. prepareForStep. A page to manually select an identity provider will be shown 2019-06-17 13:34:47,148 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:263) - Executing python 'getExtraParametersForStep' authenticator method 2019-06-17 13:34:47,148 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getExtraParametersForStep called 2019-06-17 13:34:50,138 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:193) - Executing python 'authenticate' authenticator method 2019-06-17 13:34:50,138 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. authenticate for step 1 called 2019-06-17 13:34:50,139 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. authenticate for step 1. Retrying step 1 2019-06-17 13:34:50,140 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:291) - Executing python 'getApiVersion' authenticator method 2019-06-17 13:34:50,141 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:207) - Executing python 'getNextStep' authenticator method 2019-06-17 13:34:50,160 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:263) - Executing python 'getExtraParametersForStep' authenticator method 2019-06-17 13:34:50,161 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getExtraParametersForStep called 2019-06-17 13:34:50,162 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:179) - Executing python 'getCountAuthenticationSteps' authenticator method 2019-06-17 13:34:50,162 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getCountAuthenticationSteps called 2019-06-17 13:34:50,169 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:277) - Executing python 'getPageForStep' authenticator method 2019-06-17 13:34:50,169 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getPageForStep called 2019-06-17 13:34:50,170 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:263) - Executing python 'getExtraParametersForStep' authenticator method 2019-06-17 13:34:50,170 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getExtraParametersForStep called 2019-06-17 13:34:50,535 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:384) - Validating acr_values: 'passport_social' 2019-06-17 13:34:50,536 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:151) - Executing python 'isValidAuthenticationMethod' authenticator method 2019-06-17 13:34:50,536 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:249) - Executing python 'prepareForStep' authenticator method 2019-06-17 13:34:50,536 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. prepareForStep called 1 2019-06-17 13:34:50,537 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. parseAllProviders. Adding providers 2019-06-17 13:34:50,704 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. parseProviderConfigs. Configured providers: 2019-06-17 13:34:50,705 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - {u'googleae8b': {'requestForEmail': False, 'displayName': u'google', 'emailLinkingSafe': False, 'type': u'oauth', 'logo_img': None, 'saml': False}, u'myadfs50d7': {'requestForEmail': False, 'displayName': u'My ADFS', 'emailLinkingSafe': False, 'type': u'openidconnect', 'logo_img': None, 'saml': False}} 2019-06-17 13:34:50,707 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getPassportRedirectUrl. Obtaining token from passport at https://autoqa.gluu.org/passport/token 2019-06-17 13:34:50,759 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getPassportRedirectUrl. Response was 200 2019-06-17 13:34:50,761 DEBUG [qtp985655350-13] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:263) - Executing python 'getExtraParametersForStep' authenticator method 2019-06-17 13:34:50,761 INFO [qtp985655350-13] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. getExtraParametersForStep called 2019-06-17 13:35:04,790 TRACE [oxAuthScheduler_Worker-2] [org.gluu.service.custom.script.CustomScriptManager] (CustomScriptManager.java:126) - Last finished time '2019-06-17T13:35:04.790+0000' 2019-06-17 13:35:22,325 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:193) - Executing python 'authenticate' authenticator method 2019-06-17 13:35:22,325 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. authenticate for step 1 called 2019-06-17 13:35:22,325 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. authenticate for step 1. JWT user profile token found 2019-06-17 13:35:22,326 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. validSignature. Checking JWT token signature 2019-06-17 13:35:22,327 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. validSignature. Validation result was True 2019-06-17 13:35:22,349 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. attemptAuthentication. Creating user passport-googleae8b:103308851640042732468 2019-06-17 13:35:22,349 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - mail = [u'xxxxxx@gmail.com'] 2019-06-17 13:35:22,350 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - cn = [u'sahil S'] 2019-06-17 13:35:22,350 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - uid = [u'103308851640042732468'] 2019-06-17 13:35:22,350 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - givenname = [u'sahil'] 2019-06-17 13:35:22,351 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - displayname = [u'sahil S'] 2019-06-17 13:35:22,351 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - sn = [u's'] 2019-06-17 13:35:22,400 INFO [qtp985655350-19] [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. attemptAuthentication. Authentication for 103308851640042732468 returned False 2019-06-17 13:35:22,402 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:291) - Executing python 'getApiVersion' authenticator method 2019-06-17 13:35:22,402 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.external.ExternalAuthenticationService] (ExternalAuthenticationService.java:207) - Executing python 'getNextStep' authenticator method

oxauth logs 2019-06-17 13:34:50,160 INFO [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:356) - Authentication reset to step : '1' 2019-06-17 13:34:50,161 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:528) - Attempting to store extraParameters: [passport_user_profile] 2019-06-17 13:34:50,161 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:547) - Storing sessionIdAttributes: {auth_external_attributes=[{"externalProviders":"java.lang.String"}], opbs=75d85544-87ff-455e-a685-e0dfc26871de, externalProviders={"googleae8b": {"requestForEmail": false, "displayName": "google", "emailLinkingSafe": false, "type": "oauth", "logo_img": null, "saml": false}, "myadfs50d7": {"requestForEmail": false, "displayName": "My ADFS", "emailLinkingSafe": false, "type": "openidconnect", "logo_img": null, "saml": false}}, response_type=code, nonce=305cf3bc-6c71-4d04-abda-96a3cf0813ee, client_id=0008-fdeb0515-88b3-406c-a2ca-2bce8d98d1d0, auth_step=1, acr=passport_social, remote_ip=76.230.228.76, scope=openid profile email user_name, acr_values=passport_social, redirect_uri=https://autoqa.gluu.org/identity/authcode.htm, state=2315a3f5-8fac-4011-9324-1617fe04dd9e} 2019-06-17 13:34:50,162 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:548) - Storing authExternalAttributes: {externalProviders=java.lang.String} 2019-06-17 13:34:50,163 TRACE [qtp985655350-13] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:283) - Found session_id cookie: '17311bba-2d34-4ae2-94a8-c6afd142f618' 2019-06-17 13:34:50,168 TRACE [qtp985655350-13] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:739) - Try to get session by id: 17311bba-2d34-4ae2-94a8-c6afd142f618 ... 2019-06-17 13:34:50,169 TRACE [qtp985655350-13] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:741) - Session dn: 17311bba-2d34-4ae2-94a8-c6afd142f618 2019-06-17 13:34:50,170 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:528) - Attempting to store extraParameters: [selectedProvider, externalProviders] 2019-06-17 13:34:50,171 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:547) - Storing sessionIdAttributes: {auth_external_attributes=[{"externalProviders":"java.lang.String"},{"selectedProvider":"java.lang.String"}], opbs=75d85544-87ff-455e-a685-e0dfc26871de, externalProviders={"googleae8b": {"requestForEmail": false, "displayName": "google", "emailLinkingSafe": false, "type": "oauth", "logo_img": null, "saml": false}, "myadfs50d7": {"requestForEmail": false, "displayName": "My ADFS", "emailLinkingSafe": false, "type": "openidconnect", "logo_img": null, "saml": false}}, response_type=code, nonce=305cf3bc-6c71-4d04-abda-96a3cf0813ee, selectedProvider=googleae8b, client_id=0008-fdeb0515-88b3-406c-a2ca-2bce8d98d1d0, auth_step=1, acr=passport_social, remote_ip=76.230.228.76, scope=openid profile email user_name, acr_values=passport_social, redirect_uri=https://autoqa.gluu.org/identity/authcode.htm, state=2315a3f5-8fac-4011-9324-1617fe04dd9e} 2019-06-17 13:34:50,171 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:548) - Storing authExternalAttributes: {externalProviders=java.lang.String, selectedProvider=java.lang.String} 2019-06-17 13:34:50,187 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:405) - Redirect to page: '/auth/passport/passportlogin.xhtml' 2019-06-17 13:34:50,187 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:210) - Authentication successfully for '' 2019-06-17 13:34:50,524 TRACE [qtp985655350-13] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:283) - Found session_id cookie: '17311bba-2d34-4ae2-94a8-c6afd142f618' 2019-06-17 13:34:50,535 TRACE [qtp985655350-13] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:739) - Try to get session by id: 17311bba-2d34-4ae2-94a8-c6afd142f618 ... 2019-06-17 13:34:50,535 TRACE [qtp985655350-13] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:741) - Session dn: 17311bba-2d34-4ae2-94a8-c6afd142f618 2019-06-17 13:34:50,697 INFO [qtp985655350-13] [org.gluu.oxauth.service.AppInitializer] (AppInitializer.java:333) - Created persistenceEntryManager: org.gluu.persist.couchbase.impl.CouchbaseEntryManager@25c43060 with operation service: org.gluu.persist.couchbase.operation.impl.CouchbaseOperationsServiceImpl@1f8822f7 2019-06-17 13:34:50,756 DEBUG [qtp985655350-13] [org.apache.http.impl.client.DefaultRequestDirector] (DefaultRequestDirector.java:682) - Attempt 1 to execute request 2019-06-17 13:34:50,761 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:528) - Attempting to store extraParameters: [selectedProvider, externalProviders] 2019-06-17 13:34:50,762 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:547) - Storing sessionIdAttributes: {auth_external_attributes=[{"externalProviders":"java.lang.String"},{}], opbs=75d85544-87ff-455e-a685-e0dfc26871de, externalProviders={"googleae8b": {"requestForEmail": false, "displayName": "google", "emailLinkingSafe": false, "type": "oauth", "logo_img": null, "saml": false}, "myadfs50d7": {"requestForEmail": false, "displayName": "My ADFS", "emailLinkingSafe": false, "type": "openidconnect", "logo_img": null, "saml": false}}, response_type=code, nonce=305cf3bc-6c71-4d04-abda-96a3cf0813ee, selectedProvider=null, client_id=0008-fdeb0515-88b3-406c-a2ca-2bce8d98d1d0, auth_step=1, acr=passport_social, remote_ip=76.230.228.76, scope=openid profile email user_name, acr_values=passport_social, redirect_uri=https://autoqa.gluu.org/identity/authcode.htm, state=2315a3f5-8fac-4011-9324-1617fe04dd9e} 2019-06-17 13:34:50,762 TRACE [qtp985655350-13] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:548) - Storing authExternalAttributes: {externalProviders=java.lang.String, selectedProvider=null} 2019-06-17 13:35:03,206 DEBUG [oxAuthScheduler_Worker-1] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2019-06-17 13:35:03,206 DEBUG [oxAuthScheduler_Worker-1] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.service.cdi.event.ConfigurationEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 2004108748 2019-06-17 13:35:03,207 DEBUG [oxAuthScheduler_Worker-1] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2019-06-17 13:35:03,216 DEBUG [oxAuthScheduler_Worker-5] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2019-06-17 13:35:03,217 DEBUG [oxAuthScheduler_Worker-5] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 463131352 2019-06-17 13:35:03,217 DEBUG [oxAuthScheduler_Worker-5] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2019-06-17 13:35:03,269 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2019-06-17 13:35:03,269 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.oxauth.service.cdi.event.AuthConfigurationEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 1715400696 2019-06-17 13:35:03,269 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2019-06-17 13:35:03,269 TRACE [ForkJoinPool.commonPool-worker-3] [org.gluu.oxauth.service.AppInitializer] (AppInitializer.java:264) - Attempting to use persistenceEntryManager: org.gluu.persist.couchbase.operation.impl.CouchbaseOperationsServiceImpl@27ddc4d3 2019-06-17 13:35:04,519 DEBUG [oxAuthScheduler_Worker-2] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2019-06-17 13:35:04,519 DEBUG [oxAuthScheduler_Worker-2] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.service.cdi.event.UpdateScriptEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 1505612362 2019-06-17 13:35:04,790 DEBUG [oxAuthScheduler_Worker-2] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2019-06-17 13:35:18,213 DEBUG [oxAuthScheduler_Worker-4] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2019-06-17 13:35:18,214 DEBUG [oxAuthScheduler_Worker-4] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 18462411 2019-06-17 13:35:18,214 DEBUG [oxAuthScheduler_Worker-4] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2019-06-17 13:35:22,319 TRACE [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:186) - Authenticating ... (interactive: true, skipPassword: false, credentials.username: null) 2019-06-17 13:35:22,319 TRACE [qtp985655350-19] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:283) - Found session_id cookie: '17311bba-2d34-4ae2-94a8-c6afd142f618' 2019-06-17 13:35:22,324 TRACE [qtp985655350-19] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:739) - Try to get session by id: 17311bba-2d34-4ae2-94a8-c6afd142f618 ... 2019-06-17 13:35:22,324 TRACE [qtp985655350-19] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:741) - Session dn: 17311bba-2d34-4ae2-94a8-c6afd142f618 2019-06-17 13:35:22,328 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.UserService] (UserService.java:192) - Getting user information from LDAP: attributeName = 'oxExternalUid', attributeValue = 'passport-googleae8b:103308851640042732468' 2019-06-17 13:35:22,337 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.UserService] (UserService.java:203) - Found '0' entries 2019-06-17 13:35:22,337 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.UserService] (UserService.java:192) - Getting user information from LDAP: attributeName = 'mail', attributeValue = 'xxxxxxx@gmail.com' 2019-06-17 13:35:22,348 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.UserService] (UserService.java:203) - Found '0' entries 2019-06-17 13:35:22,359 TRACE [qtp985655350-19] [gluu.oxauth.idgen.ws.rs.InumGenerator] (InumGenerator.java:101) - Generated inum: 08e18cae-7964-4331-8c3b-aa914acb95e0!0000!785A.4ABF.43EC.A938 2019-06-17 13:35:22,369 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.AuthenticationService] (AuthenticationService.java:321) - Authenticating user with LDAP: username: '103308851640042732468', credentials: '252784480' 2019-06-17 13:35:22,369 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.UserService] (UserService.java:87) - Getting user information from LDAP: userId = 103308851640042732468 2019-06-17 13:35:22,380 DEBUG [qtp985655350-19] [org.gluu.oxauth.service.UserService] (UserService.java:96) - Found 0 entries for user id = 103308851640042732468 2019-06-17 13:35:22,380 TRACE [qtp985655350-19] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:283) - Found session_id cookie: '17311bba-2d34-4ae2-94a8-c6afd142f618' 2019-06-17 13:35:22,385 TRACE [qtp985655350-19] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:739) - Try to get session by id: 17311bba-2d34-4ae2-94a8-c6afd142f618 ... 2019-06-17 13:35:22,385 TRACE [qtp985655350-19] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:741) - Session dn: 17311bba-2d34-4ae2-94a8-c6afd142f618 2019-06-17 13:35:22,400 DEBUG [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:320) - Authentication result for user 'null'. auth_step: '1', result: 'false', credentials: '252784480' 2019-06-17 13:35:22,400 TRACE [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:326) - ######################################################################### 2019-06-17 13:35:22,401 TRACE [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:327) - ######################################################################### 2019-06-17 13:35:22,401 TRACE [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:328) - ######################################################################### 2019-06-17 13:35:22,401 TRACE [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:329) - ######################################################################### 2019-06-17 13:35:22,401 TRACE [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:330) - ++++++++++++++++++++++++++++++++++++++++++CURRENT ACR:passport_social 2019-06-17 13:35:22,402 TRACE [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:331) - ++++++++++++++++++++++++++++++++++++++++++CURRENT STEP:1 2019-06-17 13:35:22,402 TRACE [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:334) - According to API version script supports steps overriding 2019-06-17 13:35:22,403 DEBUG [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:337) - Get next step from script: '-1' 2019-06-17 13:35:22,422 INFO [qtp985655350-19] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:214) - Authentication failed for 'null' 2019-06-17 13:35:27,276 TRACE [qtp985655350-12] [org.gluu.oxauth.uma.service.UmaValidationService] (UmaValidationService.java:108) - Validate authorization: Bearer 0b13e9ce-3438-4f0c-9e84-7f3673b5df16 2019-06-17 13:35:28,108 DEBUG [qtp985655350-12] [org.gluu.oxauth.service.UserService] (UserService.java:87) - Getting user information from LDAP: userId = null 2019-06-17 13:35:28,117 DEBUG [qtp985655350-12] [org.gluu.oxauth.service.ClientService] (ClientService.java:131) - Found 1 entries for client id = 0008-d2f76dc4-f4df-4131-94be-5fdee2ff6de2 2019-06-17 13:35:33,205 DEBUG [oxAuthScheduler_Worker-1] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started

jgomer2001 commented 5 years ago

@sahiliamsso I was unable to replicate. I tried with Google as in your example. Only difference is that I used default opendj installation, not couchbase. I'm also using Gluu 4 on centos 7. Maybe @yurem can give some idea?

The thing is failing here https://github.com/GluuFederation/community-edition-setup/blob/master/static/extension/person_authentication/PassportExternalAuthenticator.py#L550 (just after the user entry is effectively added)

Below my log excerpts of successful login:

oxauth_script

54,581 INFO  [qtp1191747167-18] (PythonService.java:240) - Passport. parseProviderConfigs. Configured providers:
54,581 INFO  [qtp1191747167-18] (PythonService.java:240) -  {u'gugol768e': {'requestForEmail': False, 'displayName': u'Gugol', 'emailLinkingSafe': False, 'type': u'oauth', 'logo_img': None, 'saml': False}, u'tuiter5828': {'requestForEmail': False, 'displayName': u'Tutuiter', 'emailLinkingSafe': False, 'type': u'oauth', 'logo_img': None, 'saml': False}}
54,583 INFO  [qtp1191747167-18] (PythonService.java:240) - Passport. prepareForStep. A page to manually select an identity provider will be shown
54,583 INFO  [qtp1191747167-18] (PythonService.java:240) - Passport. getExtraParametersForStep called
58,247 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. authenticate for step 1 called
58,248 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. authenticate for step 1. Retrying step 1
58,252 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. getExtraParametersForStep called
58,252 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. getCountAuthenticationSteps called
58,253 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. getPageForStep called
58,253 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. getExtraParametersForStep called
58,273 INFO  [qtp1191747167-10] (PythonService.java:240) - Passport. prepareForStep called 1
58,274 INFO  [qtp1191747167-10] (PythonService.java:240) - Passport. parseAllProviders. Adding providers
58,571 INFO  [qtp1191747167-10] (PythonService.java:240) - Passport. parseProviderConfigs. Configured providers:
58,582 INFO  [qtp1191747167-10] (PythonService.java:240) -  {u'gugol768e': {'requestForEmail': False, 'displayName': u'Gugol', 'emailLinkingSafe': False, 'type': u'oauth', 'logo_img': None, 'saml': False}, u'tuiter5828': {'requestForEmail': False, 'displayName': u'Tutuiter', 'emailLinkingSafe': False, 'type': u'oauth', 'logo_img': None, 'saml': False}}
58,602 INFO  [qtp1191747167-10] (PythonService.java:240) - Passport. getPassportRedirectUrl. Obtaining token from passport at https://some.gluu.info/passport/token
58,692 INFO  [qtp1191747167-10] (PythonService.java:240) - Passport. getPassportRedirectUrl. Response was 200
58,696 INFO  [qtp1191747167-10] (PythonService.java:240) - Passport. getExtraParametersForStep called
59,276 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. authenticate for step 1 called
59,278 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. authenticate for step 1. JWT user profile token found
59,279 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. validSignature. Checking JWT token signature
59,287 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. validSignature. Validation result was True
59,302 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. attemptAuthentication. Creating user passport-gugol768e:101815203978147491121
59,303 INFO  [qtp1191747167-14] (PythonService.java:240) - mail = [u'dontspamme@gmail.com']
59,304 INFO  [qtp1191747167-14] (PythonService.java:240) - cn = [u'Jose Gonzalez']
59,304 INFO  [qtp1191747167-14] (PythonService.java:240) - uid = [u'101815203978147491121']
59,304 INFO  [qtp1191747167-14] (PythonService.java:240) - givenname = [u'Jose']
59,305 INFO  [qtp1191747167-14] (PythonService.java:240) - displayname = [u'Jose Gonzalez']
59,305 INFO  [qtp1191747167-14] (PythonService.java:240) - sn = [u'Gonzalez']
59,368 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. attemptAuthentication. Authentication for 101815203978147491121 returned True
59,371 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. getExtraParametersForStep called
59,372 INFO  [qtp1191747167-14] (PythonService.java:240) - Passport. getCountAuthenticationSteps called

oxauth.log

58,249 INFO  [qtp1191747167-14] (Authenticator.java:357) - Authentication reset to step : '1'
58,566 INFO  [qtp1191747167-10] (AppInitializer.java:334) - Created persistenceEntryManager: org.gluu.persist.ldap.impl.LdapEntryManager@595c06ef with operation service: org.gluu.persist.ldap.operation.impl.LdapOperationsServiceImpl@3b6d4e30
59,373 INFO  [qtp1191747167-14] (AuthenticationService.java:551) - Attempting to redirect user: SessionUser: SessionState {dn='97d042e6-6c20-43a1-b194-c055e89255c5', id='97d042e6-6c20-43a1-b194-c055e89255c5', lastUsedAt=Tue Jun 18 12:44:59 EDT 2019, userDn='inum=675cf500-025d-4043-bf0b-60b1e53215cd!0000!2C54.BBB0.868D.D708,ou=people,o=gluu', authenticationTime=Tue Jun 18 12:44:59 EDT 2019, state=authenticated, sessionState='dbeddcff30ce3861265b3510768de3abd601d2b7b9e3de08ac691c22b17e9466.108b3bc3-19b9-463a-ae6a-e2e9cd1142fa', permissionGranted=null, isJwt=false, jwt=null, permissionGrantedMap=org.gluu.oxauth.model.common.SessionIdAccessMap@4883d49c, involvedClients=null, sessionAttributes={auth_external_attributes=[{"externalProviders":"java.lang.String"}], opbs=b302e0c2-8f2b-4d68-9bdb-50bd5162d33a, externalProviders={"gugol768e": {"requestForEmail": false, "displayName": "Gugol", "emailLinkingSafe": false, "type": "oauth", "logo_img": null, "saml": false}, "tuiter5828": {"requestForEmail": false, "displayName": "Tutuiter", "emailLinkingSafe": false, "type": "oauth", "logo_img": null, "saml": false}}, response_type=code, nonce=3e5cc2f8-2d4e-4ac6-bdba-d96e6ff7c2c8, selectedProvider=null, client_id=0008-ce15f3b0-561a-4d61-8f80-51f0fbb1afcc, auth_step=1, acr=passport_social, remote_ip=fe80::216:3eff:fe4a:d89a, auth_user=101815203978147491121, scope=openid profile email user_name, acr_values=passport_social, redirect_uri=https://some.gluu.info/identity/authcode.htm, state=fd3a0b07-3124-446f-a30b-5358cd18e2a2}, persisted=true}
59,375 INFO  [qtp1191747167-14] (AuthenticationService.java:559) - Attempting to redirect user: User: org.gluu.oxauth.model.common.User@6af74647
59,376 INFO  [qtp1191747167-14] (Authenticator.java:421) - Authentication success for User: '101815203978147491121'
59,656 INFO  [qtp1191747167-10] (Authenticator.java:271) - Authentication success for Client: '0008-ce15f3b0-561a-4d61-8f80-51f0fbb1afcc'
jgomer2001 commented 5 years ago

gugol

jgomer2001 commented 5 years ago

In passport script, we create the user entry, and then try to authenticate the created user. In couchbase, the authentication is not successful because couchbase is not able to find the recently created user.

@yurem how do we troubleshoot this, here are the logs:

Insertion effectively takes place just after 02:33,025 and see what happens at 02:33,063

oxauth_script.log

02:33,007 INFO  [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. attemptAuthentication. Creating user passport-github:jgomer2001
02:33,008 INFO  [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - mail = [u'bonustrack310@gmail.com']
02:33,008 INFO  [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - cn = [u'Jose']
02:33,009 INFO  [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - uid = [u'jgomer2001']
02:33,009 INFO  [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - givenname = []
02:33,009 INFO  [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - displayname = [u'Jose']
02:33,010 INFO  [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - sn = []
02:33,109 INFO  [org.gluu.service.PythonService$PythonLoggerOutputStream] (PythonService.java:240) - Passport. attemptAuthentication. Authentication for jgomer2001 returned False

oxauth.log

02:33,021 TRACE [gluu.oxauth.idgen.ws.rs.InumGenerator] (InumGenerator.java:101) - Generated inum: a5f59110-b5cc-4870-b5ae-5f07f9ebda2b!0000!DC64.8A48.7FA3.D35F
02:33,032 DEBUG [org.gluu.oxauth.service.AuthenticationService] (AuthenticationService.java:321) - Authenticating user with LDAP: username: 'jgomer2001', credentials: '666828052'
02:33,032 DEBUG [org.gluu.oxauth.service.UserService] (UserService.java:87) - Getting user information from LDAP: userId = jgomer2001
02:33,063 DEBUG [org.gluu.oxauth.service.UserService] (UserService.java:96) - Found 0 entries for user id = jgomer2001
02:33,063 TRACE [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:301) - Found session_id cookie: 'aa771a86-b64d-4357-b7d1-5e007e2b4751'
02:33,077 TRACE [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:766) - Try to get session by id: aa771a86-b64d-4357-b7d1-5e007e2b4751 ...
02:33,077 TRACE [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:768) - Session dn: aa771a86-b64d-4357-b7d1-5e007e2b4751
02:33,110 DEBUG [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:329) - Authentication result for user 'null'. auth_step: '1', result: 'false', credentials: '666828052'

persistence.log

02:33,025 DEBUG [org.gluu.persist.impl.BaseEntryManager] (BaseEntryManager.java:96) - LDAP attributes for persist: [Attribute [name=oxExternalUid, values=[passport-github:jgomer2001]], Attribute [name=mail, values=[bonustrack310@gmail.com]], Attribute [name=oxTrustEmail, values=[{"value":"bonustrack310@gmail.com","primary":false}]], Attribute [name=cn, values=[Jose]], Attribute [name=uid, values=[jgomer2001]], Attribute [name=givenname, values=[]], Attribute [name=displayname, values=[Jose]], Attribute [name=sn, values=[]], Attribute [name=inum, values=[a5f59110-b5cc-4870-b5ae-5f07f9ebda2b!0000!DC64.8A48.7FA3.D35F]], Attribute [name=gluuStatus, values=[active]], Attribute [name=objectClass, values=[gluuPerson, gluuCustomPerson]]]
02:33,029 DEBUG [org.gluu.persist.impl.BaseEntryManager] (BaseEntryManager.java:1405) - LdapProperty: userId, AttributeName: uid, AttributeValue: [jgomer2001]
02:33,029 DEBUG [org.gluu.persist.impl.BaseEntryManager] (BaseEntryManager.java:1405) - LdapProperty: customAttributes, AttributeName: mail, AttributeValue: [bonustrack310@gmail.com]
02:33,029 DEBUG [org.gluu.persist.impl.BaseEntryManager] (BaseEntryManager.java:1405) - LdapProperty: customAttributes, AttributeName: displayname, AttributeValue: [Jose]
02:33,030 DEBUG [org.gluu.persist.impl.BaseEntryManager] (BaseEntryManager.java:1405) - LdapProperty: customAttributes, AttributeName: oxExternalUid, AttributeValue: [passport-github:jgomer2001]
02:33,030 DEBUG [org.gluu.persist.impl.BaseEntryManager] (BaseEntryManager.java:1405) - LdapProperty: customAttributes, AttributeName: oxTrustEmail, AttributeValue: [{"value":"bonustrack310@gmail.com","primary":false}]
02:33,030 DEBUG [org.gluu.persist.impl.BaseEntryManager] (BaseEntryManager.java:1405) - LdapProperty: customAttributes, AttributeName: dn, AttributeValue: [inum=a5f59110-b5cc-4870-b5ae-5f07f9ebda2b!0000!DC64.8A48.7FA3.D35F,ou=people,o=gluu]
02:33,031 DEBUG [org.gluu.persist.impl.BaseEntryManager] (BaseEntryManager.java:1405) - LdapProperty: customAttributes, AttributeName: cn, AttributeValue: [Jose]
02:33,031 DEBUG [org.gluu.persist.impl.BaseEntryManager] (BaseEntryManager.java:1405) - LdapProperty: customAttributes, AttributeName: gluuStatus, AttributeValue: [active]
02:33,031 DEBUG [org.gluu.persist.impl.BaseEntryManager] (BaseEntryManager.java:1405) - LdapProperty: customAttributes, AttributeName: inum, AttributeValue: [a5f59110-b5cc-4870-b5ae-5f07f9ebda2b!0000!DC64.8A48.7FA3.D35F]
02:33,033 TRACE [org.gluu.persist.couchbase.impl.CouchbaseEntryManager] (CouchbaseEntryManager.java:352) - -------------------------------------------------------
02:33,033 TRACE [org.gluu.persist.couchbase.impl.CouchbaseEntryManager] (CouchbaseEntryManager.java:353) - Filter: (uid=jgomer2001)
02:33,033 TRACE [org.gluu.persist.couchbase.impl.CouchbaseEntryManager] (CouchbaseEntryManager.java:354) - objectClasses count: 1 
02:33,034 TRACE [org.gluu.persist.couchbase.impl.CouchbaseEntryManager] (CouchbaseEntryManager.java:355) - objectClasses: [Ljava.lang.String;@3ef77d0f
02:33,034 TRACE [org.gluu.persist.couchbase.impl.CouchbaseEntryManager] (CouchbaseEntryManager.java:359) - Filter: (uid=jgomer2001)
02:33,034 TRACE [org.gluu.persist.couchbase.impl.CouchbaseEntryManager] (CouchbaseEntryManager.java:364) - Search filter: (&(&(objectClass=gluuPerson))(uid=jgomer2001))
02:33,035 DEBUG [gluu.persist.couchbase.operation.impl.CouchbaseOperationsServiceImpl] (CouchbaseOperationsServiceImpl.java:523) - Execution query: 'SELECT gluu_doc.*, dn FROM `gluu_user` AS gluu_doc WHERE META().id LIKE "people%" AND ( ( objectClass = "gluuPerson" ) AND uid = "jgomer2001" )'
yurem commented 5 years ago

It's very small period 02:33,025-02:33,063 for Couchbase. It requires 200 ms to update indexes. Do you know which Entry class are we trying to find? We can add consistency=true to uid attribute annotation. This will build query with condition to wait indexes update.

jgomer2001 commented 5 years ago

https://github.com/GluuFederation/oxCore/commit/cf12fadab70da99a9bb943cd26238b4dc33b62cc

jgomer2001 commented 5 years ago

It worked