By: Benedikt Riedel user 20 Feb 2019 at 12:30 p.m. CST

14 Responses
Benedikt Riedel gravatar
Hi All, I have been trying to add CILogon as a external ID provider using passport. They have a an OpenID Connect compliant endpoint, see https://www.cilogon.org/oidc I added all the required details from their https://cilogon.org/.well-known/openid-configuration into the Configuration -> Manage Authentication -> Passport Authenication Method fields, i.e. clientID clientSecret issuer authorizationURL tokenURL userInfoURL After I am getting errors that the resources does not exist. I am running a custom auth script (passport/server/auth/cilogon.js) that was a copy of the openid-connect.js in that directory with the callbackURL changed. The logs are not super enlightening, I am getting: 2019-02-20T11:44:31-0600 [INFO] getRPT. RPT contents parsed 2019-02-20T11:44:31-0600 [INFO] getStrategies. Passport strategies were received 2019-02-20T11:44:31-0600 [INFO] CILogon Strategy details received 2019-02-20T11:44:31-0600 [INFO] Credential data received was {"userInfoURL":"https://cilogon.org/oauth2/userinfo","clientID":"XXX","tokenURL":"https://cilogon.org/oauth2/token","authorizationURL":"https://cilogon.org/authorize","clientSecret":"XXX","issuer":"https://cilogon.org","callbackURL":"https://gluu-testing.icecube.wisc.edu/passport/auth/cilogon/callback","scope":"profile user_name email"}: 2019-02-20T11:44:31-0600 [INFO] reloadConfiguration. Passport strategies have been parsed 2019-02-20T11:44:31-0600 [INFO] /opt/gluu/node/passport/server/idp-metadata/your_idp_name1.xml saved successfully 2019-02-20T11:44:31-0600 [INFO] /opt/gluu/node/passport/server/idp-metadata/your_idp_name2.xml saved successfully 2019-02-20T11:45:04-0600 [INFO] ::ffff:127.0.0.1 - - [20/Feb/2019:17:45:04 +0000] "GET /passport/passportstrategies HTTP/1.1" 200 373 "https://gluu-testing.icecube.wisc.edu/oxauth/auth/passport/passportlogin.htm" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:65.0) Gecko/20100101 Firefox/65.0" 2019-02-20T11:45:05-0600 [INFO] ::ffff:127.0.0.1 - - [20/Feb/2019:17:45:05 +0000] "GET /passport/token HTTP/1.1" 200 201 "-" "Apache-HttpClient/4.5.3 (Java/1.8.0_181)" 2019-02-20T11:45:05-0600 [INFO] ::ffff:127.0.0.1 - - [20/Feb/2019:17:45:05 +0000] "GET /passport/auth/cilogonXXX HTTP/1.1" 302 312 "https://gluu-testing.icecube.wisc.edu/oxauth/auth/passport/passportlogin.htm" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:65.0) Gecko/20100101 Firefox/65.0" 2019-02-20T11:45:05-0600 [INFO] ::ffff:127.0.0.1 - - [20/Feb/2019:17:45:05 +0000] "GET /passport/passportstrategies HTTP/1.1" 200 373 "https://gluu-testing.icecube.wisc.edu/oxauth/auth/passport/passportlogin.htm?failure=The%20requested%20resource%20does%20not%20exists!" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:65.0) Gecko/20100101 Firefox/65.0" 2019-02-20T11:45:10-0600 [INFO] ::ffff:127.0.0.1 - - [20/Feb/2019:17:45:10 +0000] "GET /passport/token HTTP/1.1" 200 201 "-" "Apache-HttpClient/4.5.3 (Java/1.8.0_181)" 2019-02-20T11:45:10-0600 [INFO] ::ffff:127.0.0.1 - - [20/Feb/2019:17:45:10 +0000] "GET /passport/auth/cilogon/XXX HTTP/1.1" 302 312 "https://gluu-testing.icecube.wisc.edu/oxauth/auth/passport/passport-login" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:65.0) Gecko/20100101 Firefox/65.0" 2019-02-20T11:45:11-0600 [INFO] ::ffff:127.0.0.1 - - [20/Feb/2019:17:45:11 +0000] "GET /passport/passportstrategies HTTP/1.1" 200 373 "https://gluu-testing.icecube.wisc.edu/oxauth/auth/passport/passportlogin.htm?failure=The%20requested%20resource%20does%20not%20exists!" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:65.0) Gecko/20100101 Firefox/65.0" It appears to break when it calls passport.use(new OIDCStrategy(credentials, function(iss, sub, profile, accessToken, refreshToken, done) { logger.log2('info', 'Profile data received was %s:', JSON.stringify(profile)) var userProfile = { id: profile.id || "", name: profile.displayName || "", username: profile._json.user_name || profile.id || "", email: profile._json.email || "", givenName: profile.name.givenName || "", familyName: profile.name.familyName || "", provider: "openidconnect" } logger.log2('info', 'Profile data received was %s:', JSON.stringify(profile)) return done(null, userProfile) } )) What am I missing or where should I add extra logging? Thanks, Benedikt

By Mohammad Abudayyeh staff 20 Feb 2019 at 3:07 p.m. CST

Mohammad Abudayyeh gravatar
Hi Benedikt, Could you check and send in your oxauth.log, oxtrust.log, ldap.log and idp-process log. your fields might not be mapping right

By Benedikt Riedel user 20 Feb 2019 at 3:27 p.m. CST

Benedikt Riedel gravatar
oxauth.log 2019-02-20 12:47:38,041 ERROR [qtp1094834071-18] [org.xdi.oxauth.exception.GlobalExceptionHandler] (GlobalExceptionHandler.java:59) - Can't perform redirect to viewId: /error_service.htm java.lang.IllegalStateException: Committed at org.eclipse.jetty.server.HttpChannel.resetBuffer(HttpChannel.java:894) ~[jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.HttpOutput.resetBuffer(HttpOutput.java:959) ~[jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.Response.resetBuffer(Response.java:1312) ~[jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.Response.sendRedirect(Response.java:720) ~[jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.Response.sendRedirect(Response.java:729) ~[jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at com.sun.faces.context.ExternalContextImpl.redirect(ExternalContextImpl.java:678) ~[javax.faces-2.2.16.jar:2.2.16] at javax.faces.context.ExternalContextWrapper.redirect(ExternalContextWrapper.java:578) ~[javax.faces-2.2.16.jar:2.2.16] at org.xdi.oxauth.exception.GlobalExceptionHandler.performRedirect(GlobalExceptionHandler.java:57) [classes/:?] at org.xdi.oxauth.exception.GlobalExceptionHandler.handle(GlobalExceptionHandler.java:46) [classes/:?] at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:119) [javax.faces-2.2.16.jar:2.2.16] at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:198) [javax.faces-2.2.16.jar:2.2.16] at javax.faces.webapp.FacesServlet.service(FacesServlet.java:658) [javax.faces-2.2.16.jar:2.2.16] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865) [jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1655) [jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:215) [websocket-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1642) [jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830] at org.xdi.oxauth.audit.debug.ServletLoggingFilter.doFilter(ServletLoggingFilter.java:55) [classes/:?] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1634) [jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533) [jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [jetty-security-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1340) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) [jetty-servlet-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1242) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:220) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.Server.handle(Server.java:503) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260) [jetty-server-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) [jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) [jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765) [jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) [jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181] 2019-02-20 12:48:34,472 INFO [qtp1094834071-17] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:262) - Authentication success for Client: '@!A03B.1A40.9686.9847!0001!6973.1501!0008!50C6.91AD' ... 2019-02-20 15:15:25,590 INFO [qtp1094834071-15] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:330) - Created ldapEntryManager:org.gluu.site.ldap.persistence.LdapEntryManager@3bc11910 with provider org.xdi.service.ldap.LdapConnectionService@4acca937 2019-02-20 15:15:30,293 INFO [qtp1094834071-10] [org.xdi.oxauth.auth.Authenticator] (Authenticator.java:345) - Authentication reset to step : '1' 2019-02-20 15:15:30,324 INFO [qtp1094834071-10] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:330) - Created ldapEntryManager:org.gluu.site.ldap.persistence.LdapEntryManager@3b5bc502 with provider org.xdi.service.ldap.LdapConnectionService@4acca937 2019-02-20 15:15:30,426 INFO [qtp1094834071-17] [org.xdi.oxauth.service.AppInitializer] (AppInitializer.java:330) - Created ldapEntryManager:org.gluu.site.ldap.persistence.LdapEntryManager@c283a16 with provider org.xdi.service.ldap.LdapConnectionService@4acca937 oxtrust.log 2019-02-20 14:44:34,598 INFO [qtp1094834071-17] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:78) - Path is protected, proceeding with authorization processing... 2019-02-20 14:44:34,612 ERROR [qtp1094834071-17] [org.gluu.oxtrust.service.uma.UmaPermissionService] (UmaPermissionService.java:116) - Status response for RPT token: 'c7fa21e6-49cd-4375-9fc2-1388042493e8_8F13.6867.3F44.597F.49CC.2CE2.F53C.ADAE' is invalid 2019-02-20 14:44:34,686 INFO [qtp1094834071-10] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:78) - Path is protected, proceeding with authorization processing... 2019-02-20 14:44:34,705 INFO [qtp1094834071-10] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:82) - Authorization passed ... 2019-02-20 15:13:34,609 INFO [qtp1094834071-14] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:78) - Path is protected, proceeding with authorization processing... 2019-02-20 15:13:34,684 INFO [qtp1094834071-14] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:82) - Authorization passed 2019-02-20 15:14:34,610 INFO [qtp1094834071-18] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:78) - Path is protected, proceeding with authorization processing... 2019-02-20 15:14:34,624 INFO [qtp1094834071-18] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:82) - Authorization passed 2019-02-20 15:15:34,611 INFO [qtp1094834071-14] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:78) - Path is protected, proceeding with authorization processing... 2019-02-20 15:15:34,625 INFO [qtp1094834071-14] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:82) - Authorization passed 2019-02-20 15:16:34,611 INFO [qtp1094834071-17] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:78) - Path is protected, proceeding with authorization processing... 2019-02-20 15:16:34,627 INFO [qtp1094834071-17] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:82) - Authorization passed 2019-02-20 15:17:34,614 INFO [qtp1094834071-16] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:78) - Path is protected, proceeding with authorization processing... 2019-02-20 15:17:34,635 INFO [qtp1094834071-16] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:82) - Authorization passed 2019-02-20 15:18:34,617 INFO [qtp1094834071-12] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:78) - Path is protected, proceeding with authorization processing... 2019-02-20 15:18:34,694 INFO [qtp1094834071-12] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:82) - Authorization passed 2019-02-20 15:19:34,612 INFO [qtp1094834071-70] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:78) - Path is protected, proceeding with authorization processing... 2019-02-20 15:19:34,626 INFO [qtp1094834071-70] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:82) - Authorization passed 2019-02-20 15:20:34,613 INFO [qtp1094834071-12] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:78) - Path is protected, proceeding with authorization processing... 2019-02-20 15:20:34,628 INFO [qtp1094834071-12] [org.gluu.oxtrust.service.filter.AuthorizationProcessingFilter] (AuthorizationProcessingFilter.java:82) - Authorization passed idp-process.log 2019-02-19 16:35:59,625 - INFO [net.shibboleth.idp.log.LogbackLoggingService:240] - Shibboleth IdP Version 3.3.3 2019-02-19 16:35:59,633 - INFO [net.shibboleth.idp.log.LogbackLoggingService:241] - Java version='1.8.0_181' vendor='Oracle Corporation' 2019-02-19 16:35:59,657 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.LoggingService': Reload time set to: 300000, starting refresh thread 2019-02-19 16:35:59,754 - INFO [org.opensaml.core.config.InitializationService:48] - Initializing OpenSAML using the Java Services API 2019-02-19 16:36:01,072 - INFO [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:206] - Algorithm failed runtime support check, will not be usable: http://www.w3.org/2001/04/xmlenc#ripemd160 2019-02-19 16:36:01,081 - INFO [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:206] - Algorithm failed runtime support check, will not be usable: http://www.w3.org/2001/04/xmldsig-more#hmac-ripemd160 2019-02-19 16:36:01,097 - INFO [org.opensaml.xmlsec.algorithm.AlgorithmRegistry:206] - Algorithm failed runtime support check, will not be usable: http://www.w3.org/2001/04/xmldsig-more#rsa-ripemd160 2019-02-19 16:36:01,719 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.AttributeFilterService': Performing initial load 2019-02-19 16:36:01,719 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.AttributeFilterService': Reloading service configuration 2019-02-19 16:36:01,741 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/attribute-filter.xml] 2019-02-19 16:36:01,804 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.AttributeFilterService: startup date [Tue Feb 19 16:36:01 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:36:01,822 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.AttributeFilterService': Completed reload and swapped in latest configuration for service 'shibboleth.AttributeFilterService' 2019-02-19 16:36:01,822 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.AttributeFilterService': Reload complete 2019-02-19 16:36:01,842 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.AttributeFilterService': Reload time set to: 900000, starting refresh thread 2019-02-19 16:36:01,851 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.AttributeResolverService': Performing initial load 2019-02-19 16:36:01,852 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.AttributeResolverService': Reloading service configuration 2019-02-19 16:36:01,863 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/attribute-resolver.xml] 2019-02-19 16:36:01,946 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for DataConnector plugin with id: siteLDAP 2019-02-19 16:36:01,946 - WARN [net.shibboleth.idp.attribute.resolver.spring.dc.AbstractDataConnectorParser:117] - Data Connector 'siteLDAP': Configuration contains at least one element in the deprecated 'urn:mace:shibboleth:2.0:resolver:dc' namespace. 2019-02-19 16:36:01,996 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.AttributeResolverService: startup date [Tue Feb 19 16:36:01 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:36:02,781 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.AttributeResolverService': Completed reload and swapped in latest configuration for service 'shibboleth.AttributeResolverService' 2019-02-19 16:36:02,782 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.AttributeResolverService': Reload complete 2019-02-19 16:36:02,827 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.AttributeResolverService': Reload time set to: 900000, starting refresh thread 2019-02-19 16:36:02,870 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.NameIdentifierGenerationService': Performing initial load 2019-02-19 16:36:02,870 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.NameIdentifierGenerationService': Reloading service configuration 2019-02-19 16:36:02,872 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/saml-nameid.xml] 2019-02-19 16:36:02,905 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/conf/saml-nameid-system.xml] 2019-02-19 16:36:02,958 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.NameIdentifierGenerationService: startup date [Tue Feb 19 16:36:02 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:36:03,142 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.NameIdentifierGenerationService': Completed reload and swapped in latest configuration for service 'shibboleth.NameIdentifierGenerationService' 2019-02-19 16:36:03,143 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.NameIdentifierGenerationService': Reload complete 2019-02-19 16:36:03,164 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.NameIdentifierGenerationService': Reload time set to: 900000, starting refresh thread 2019-02-19 16:36:03,173 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.RelyingPartyResolverService': Performing initial load 2019-02-19 16:36:03,173 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.RelyingPartyResolverService': Reloading service configuration 2019-02-19 16:36:03,174 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/relying-party.xml] 2019-02-19 16:36:03,198 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/credentials.xml] 2019-02-19 16:36:03,269 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/conf/relying-party-system.xml] 2019-02-19 16:36:03,279 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.RelyingPartyResolverService: startup date [Tue Feb 19 16:36:03 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:36:04,139 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.MetadataResolverService': Performing initial load 2019-02-19 16:36:04,140 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.MetadataResolverService': Reloading service configuration 2019-02-19 16:36:04,141 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/metadata-providers.xml] 2019-02-19 16:36:04,218 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/conf/metadata-providers-system.xml] 2019-02-19 16:36:04,223 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.MetadataResolverService: startup date [Tue Feb 19 16:36:04 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:36:04,268 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.MetadataResolverService': Completed reload and swapped in latest configuration for service 'shibboleth.MetadataResolverService' 2019-02-19 16:36:04,269 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.MetadataResolverService': Reload complete 2019-02-19 16:36:04,284 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.MetadataResolverService': Reload time set to: 60000, starting refresh thread 2019-02-19 16:36:04,481 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.RelyingPartyResolverService': Completed reload and swapped in latest configuration for service 'shibboleth.RelyingPartyResolverService' 2019-02-19 16:36:04,482 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.RelyingPartyResolverService': Reload complete 2019-02-19 16:36:04,493 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.RelyingPartyResolverService': Reload time set to: 900000, starting refresh thread 2019-02-19 16:36:04,502 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.ReloadableAccessControlService': Performing initial load 2019-02-19 16:36:04,502 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.ReloadableAccessControlService': Reloading service configuration 2019-02-19 16:36:04,503 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/access-control.xml] 2019-02-19 16:36:04,529 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/conf/access-control-system.xml] 2019-02-19 16:36:04,538 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.ReloadableAccessControlService: startup date [Tue Feb 19 16:36:04 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:36:04,595 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.ReloadableAccessControlService': Completed reload and swapped in latest configuration for service 'shibboleth.ReloadableAccessControlService' 2019-02-19 16:36:04,595 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.ReloadableAccessControlService': Reload complete 2019-02-19 16:36:04,619 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.ReloadableAccessControlService': Reload time set to: 300000, starting refresh thread 2019-02-19 16:36:04,626 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.ReloadableCASServiceRegistry': Performing initial load 2019-02-19 16:36:04,627 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.ReloadableCASServiceRegistry': Reloading service configuration 2019-02-19 16:36:04,628 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/cas-protocol.xml] 2019-02-19 16:36:04,639 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.ReloadableCASServiceRegistry: startup date [Tue Feb 19 16:36:04 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:36:04,681 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.ReloadableCASServiceRegistry': Completed reload and swapped in latest configuration for service 'shibboleth.ReloadableCASServiceRegistry' 2019-02-19 16:36:04,681 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.ReloadableCASServiceRegistry': Reload complete 2019-02-19 16:36:04,693 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:199] - Service 'shibboleth.ReloadableCASServiceRegistry': Reload time set to: 900000, starting refresh thread 2019-02-19 16:36:07,668 - INFO [net.shibboleth.ext.spring.context.DelimiterAwareApplicationContext:583] - Refreshing WebApplicationContext for namespace 'idp-servlet': startup date [Tue Feb 19 16:36:07 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:36:08,372 - INFO [net.shibboleth.idp.authn.impl.RemoteUserAuthServlet:193] - RemoteUserAuthServlet will process REMOTE_USER, along with attributes [] and headers [] 2019-02-19 16:37:04,286 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.MetadataResolverService': Reloading service configuration 2019-02-19 16:37:04,292 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/metadata-providers.xml] 2019-02-19 16:37:04,315 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/conf/metadata-providers-system.xml] 2019-02-19 16:37:04,319 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.MetadataResolverService: startup date [Tue Feb 19 16:37:04 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:37:04,344 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.MetadataResolverService': Completed reload and swapped in latest configuration for service 'shibboleth.MetadataResolverService' 2019-02-19 16:37:04,345 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:984] - Closing ApplicationContext:shibboleth.MetadataResolverService: startup date [Tue Feb 19 16:36:04 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:37:04,346 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.MetadataResolverService': Reload complete 2019-02-19 16:51:01,843 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.AttributeFilterService': Reloading service configuration 2019-02-19 16:51:01,844 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/attribute-filter.xml] 2019-02-19 16:51:01,857 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.AttributeFilterService: startup date [Tue Feb 19 16:51:01 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:51:01,863 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.AttributeFilterService': Completed reload and swapped in latest configuration for service 'shibboleth.AttributeFilterService' 2019-02-19 16:51:01,863 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:984] - Closing ApplicationContext:shibboleth.AttributeFilterService: startup date [Tue Feb 19 16:36:01 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:51:01,864 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.AttributeFilterService': Reload complete 2019-02-19 16:51:02,829 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.AttributeResolverService': Reloading service configuration 2019-02-19 16:51:02,830 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/attribute-resolver.xml] 2019-02-19 16:51:02,846 - INFO [net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] - Parsing configuration for DataConnector plugin with id: siteLDAP 2019-02-19 16:51:02,847 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.AttributeResolverService: startup date [Tue Feb 19 16:51:02 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:51:02,958 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.AttributeResolverService': Completed reload and swapped in latest configuration for service 'shibboleth.AttributeResolverService' 2019-02-19 16:51:02,958 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:984] - Closing ApplicationContext:shibboleth.AttributeResolverService: startup date [Tue Feb 19 16:36:01 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:51:02,960 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.AttributeResolverService': Reload complete 2019-02-19 16:51:03,165 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.NameIdentifierGenerationService': Reloading service configuration 2019-02-19 16:51:03,167 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/saml-nameid.xml] 2019-02-19 16:51:03,175 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/conf/saml-nameid-system.xml] 2019-02-19 16:51:03,180 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.NameIdentifierGenerationService: startup date [Tue Feb 19 16:51:03 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:51:03,202 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.NameIdentifierGenerationService': Completed reload and swapped in latest configuration for service 'shibboleth.NameIdentifierGenerationService' 2019-02-19 16:51:03,202 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:984] - Closing ApplicationContext:shibboleth.NameIdentifierGenerationService: startup date [Tue Feb 19 16:36:02 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:51:03,203 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.NameIdentifierGenerationService': Reload complete 2019-02-19 16:51:04,494 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.RelyingPartyResolverService': Reloading service configuration 2019-02-19 16:51:04,495 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/relying-party.xml] 2019-02-19 16:51:04,506 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/credentials.xml] 2019-02-19 16:51:04,517 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/system/conf/relying-party-system.xml] 2019-02-19 16:51:04,535 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.RelyingPartyResolverService: startup date [Tue Feb 19 16:51:04 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:51:04,693 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.ReloadableCASServiceRegistry': Reloading service configuration 2019-02-19 16:51:04,694 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/cas-protocol.xml] 2019-02-19 16:51:04,702 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:583] - Refreshing ApplicationContext:shibboleth.ReloadableCASServiceRegistry: startup date [Tue Feb 19 16:51:04 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:51:04,703 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.RelyingPartyResolverService': Completed reload and swapped in latest configuration for service 'shibboleth.RelyingPartyResolverService' 2019-02-19 16:51:04,703 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:984] - Closing ApplicationContext:shibboleth.RelyingPartyResolverService: startup date [Tue Feb 19 16:36:03 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:51:04,707 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.RelyingPartyResolverService': Reload complete 2019-02-19 16:51:04,714 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service 'shibboleth.ReloadableCASServiceRegistry': Completed reload and swapped in latest configuration for service 'shibboleth.ReloadableCASServiceRegistry' 2019-02-19 16:51:04,714 - INFO [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:984] - Closing ApplicationContext:shibboleth.ReloadableCASServiceRegistry: startup date [Tue Feb 19 16:36:04 CST 2019]; parent: Root WebApplicationContext 2019-02-19 16:51:04,715 - INFO [net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service 'shibboleth.ReloadableCASServiceRegistry': Reload complete I can't find a ldap.log

By Mohammad Abudayyeh staff 21 Feb 2019 at 1:54 a.m. CST

Mohammad Abudayyeh gravatar
Thanks! Taking a look at this ```bash 2019-02-20T11:45:11-0600 [INFO] ::ffff:127.0.0.1 - - [20/Feb/2019:17:45:11 +0000] "GET /passport/passportstrategies HTTP/1.1" 200 373 "https://gluu-testing.icecube.wisc.edu/oxauth/auth/passport/passportlogin.htm?failure=The%20requested%20resource%20does%20not%20exists!" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:65.0) Gecko/20100101 Firefox/65.0" ``` It seems like the issue is here . Please make sure you have defined the values in Gluu exactly like what you have above. ```bash ERROR [qtp1094834071-18] [org.xdi.oxauth.exception.GlobalExceptionHandler] (GlobalExceptionHandler.java:59) - Can't perform redirect to viewId: /error_service.htm java.lang.IllegalStateException: Committed ``` This error does not seem like its related or impacting anything in anyway. Your authentication is passing. Lets move to the next step. Location of ldap log in OpenLDAP ```bash /var/log/openldap/ldap.log ``` in OpenDJ check errors log and send it ```bash /opt/opendj/logs/errors ```

By Jose Gonzalez staff 21 Feb 2019 at 8:24 a.m. CST

Jose Gonzalez gravatar
Benedikt , Can you be more specific about the point you are getting the error at? I suppose you can see "cilogon" appearing in the login page, are you being redirected to cilogon site for authorization? From the log, I guess you added a route `/auth/cilogon/:token` to index.js, can you show the code of the other route? the one ending with `.../callback`

By Benedikt Riedel user 22 Feb 2019 at 3:34 p.m. CST

Benedikt Riedel gravatar
Hi, The Gluu version is 3.1.5 and the OS is Centos 7.6 The call back URL is passport/auth/cilogon/callback OpenDJ log [19/Feb/2019:16:30:55 -0600] category=EXTENSIONS severity=NOTICE msgID=org.opends.messages.extension.221 msg=DIGEST-MD5 SASL mechanism using a server fully qualified domain name of: localhost [19/Feb/2019:16:30:56 -0600] category=PROTOCOL severity=NOTICE msgID=org.opends.messages.protocol.276 msg=Started listening for new connections on Administration Connector 127.0.0.1 port 4444 [19/Feb/2019:16:30:56 -0600] category=PROTOCOL severity=NOTICE msgID=org.opends.messages.protocol.276 msg=Started listening for new connections on LDAPS Connection Handler 127.0.0.1 port 1636 [19/Feb/2019:16:30:56 -0600] category=CORE severity=NOTICE msgID=org.opends.messages.core.135 msg=The Directory Server has started successfully [19/Feb/2019:16:30:56 -0600] category=CORE severity=NOTICE msgID=org.opends.messages.core.139 msg=The Directory Server has sent an notification generated by class org.opends.server.core.DirectoryServer ( type org.opends.server.DirectoryServerStarted, ID org.opends.messages.core-135): The Directory Server has started successfully [19/Feb/2019:16:34:44 -0600] category=CORE severity=NOTICE msgID=org.opends.messages.core.139 msg=The Directory Server has sent an notification generated by class org.opends.server.core.DirectoryServer ( type org.opends.server.DirectoryServerShutdown, ID org.opends.messages.core-141): The Directory Server has started the shutdown process. The shutdown was initiated by an instance of class org.opends.server.core.DirectoryServerShutdownHook and the reason provided for the shutdown was The Directory Server shutdown hook detected that the JVM is shutting down. This generally indicates that JVM received an external request to stop (e.g., through a kill signal) [19/Feb/2019:16:34:49 -0600] category=PLUGGABLE severity=NOTICE msgID=org.opends.messages.backend.370 msg=The backend metric is now taken offline [19/Feb/2019:16:34:49 -0600] category=PLUGGABLE severity=NOTICE msgID=org.opends.messages.backend.370 msg=The backend site is now taken offline [19/Feb/2019:16:34:49 -0600] category=PLUGGABLE severity=NOTICE msgID=org.opends.messages.backend.370 msg=The backend userRoot is now taken offline [19/Feb/2019:16:34:49 -0600] category=CORE severity=NOTICE msgID=org.opends.messages.core.203 msg=The Directory Server is now stopped [19/Feb/2019:16:35:24 -0600] category=UTIL severity=NOTICE msgID=org.opends.messages.runtime.21 msg=Installation Directory: /opt/opendj [19/Feb/2019:16:35:24 -0600] category=UTIL severity=NOTICE msgID=org.opends.messages.runtime.23 msg=Instance Directory: /opt/opendj [19/Feb/2019:16:35:24 -0600] category=UTIL severity=NOTICE msgID=org.opends.messages.runtime.17 msg=JVM Information: 1.8.0_181-b13 by Oracle Corporation, 64-bit architecture, 1819803648 bytes heap size [19/Feb/2019:16:35:24 -0600] category=UTIL severity=NOTICE msgID=org.opends.messages.runtime.18 msg=JVM Host: localhost, running Linux 3.10.0-957.5.1.el7.x86_64 amd64, 8182054912 bytes physical memory size, number of processors available 2 [19/Feb/2019:16:35:24 -0600] category=UTIL severity=NOTICE msgID=org.opends.messages.runtime.19 msg=JVM Arguments: "-Dorg.opends.server.scriptName=start-ds" [19/Feb/2019:16:35:25 -0600] category=PLUGGABLE severity=NOTICE msgID=org.opends.messages.backend.513 msg=The database backend site containing 2 entries has started [19/Feb/2019:16:35:25 -0600] category=PLUGGABLE severity=NOTICE msgID=org.opends.messages.backend.513 msg=The database backend metric containing 5 entries has started [19/Feb/2019:16:35:25 -0600] category=PLUGGABLE severity=NOTICE msgID=org.opends.messages.backend.513 msg=The database backend userRoot containing 168 entries has started [19/Feb/2019:16:35:25 -0600] category=EXTENSIONS severity=NOTICE msgID=org.opends.messages.extension.221 msg=DIGEST-MD5 SASL mechanism using a server fully qualified domain name of: localhost [19/Feb/2019:16:35:26 -0600] category=PROTOCOL severity=NOTICE msgID=org.opends.messages.protocol.276 msg=Started listening for new connections on Administration Connector 127.0.0.1 port 4444 [19/Feb/2019:16:35:26 -0600] category=PROTOCOL severity=NOTICE msgID=org.opends.messages.protocol.276 msg=Started listening for new connections on LDAPS Connection Handler 127.0.0.1 port 1636 [19/Feb/2019:16:35:26 -0600] category=CORE severity=NOTICE msgID=org.opends.messages.core.135 msg=The Directory Server has started successfully [19/Feb/2019:16:35:26 -0600] category=CORE severity=NOTICE msgID=org.opends.messages.core.139 msg=The Directory Server has sent an notification generated by class org.opends.server.core.DirectoryServer ( type org.opends.server.DirectoryServerStarted, ID org.opends.messages.core-135): The Directory Server has started successfully Benedikt

By Mohammad Abudayyeh staff 23 Feb 2019 at 12:15 p.m. CST

Mohammad Abudayyeh gravatar
Hi Benedikt , Can you confirm where exactly you see the error? A screen shot will help. There seems to be an error in your code , could you send that so we can help detect it . You can also try to return the error instead of null.

By Benedikt Riedel user 25 Feb 2019 at 8:52 a.m. CST

Benedikt Riedel gravatar
Screenshot added

By Mohammad Abudayyeh staff 26 Feb 2019 at 3:33 a.m. CST

Mohammad Abudayyeh gravatar
Try the following and report back. : ``` passport.use(new OIDCStrategy(credentials, function(iss, sub, profile, accessToken, refreshToken, done) { logger.log2('info', 'Profile data received was %s:', JSON.stringify(profile)) var userProfile = { id: profile.id || "", name: profile.displayName || "", username: profile._json.user_name || profile.id || "", email: profile._json.email || "", givenName: profile.name.givenName || "", familyName: profile.name.familyName || "", provider: "openidconnect", } if (!profile.id) { return done(new Error("No valid user auth ID"), null); } logger.log2('info', 'Profile data received was %s:', JSON.stringify(profile)); return done(null, userProfile); } )) ```

By Benedikt Riedel user 26 Feb 2019 at 12:11 p.m. CST

Benedikt Riedel gravatar
Hi, I worked through a couple things 1. I added CILogon as a path to `/opt/gluu/node/passport/server/routes/index.js` //=================== CILogon =================== router.get('/auth/cilogon/callback', passportCILogon.authenticate('cilogon', { failureRedirect: '/passport/login' }), callbackResponse); router.get('/auth/cilogon/:token', validateToken, passportCILogon.authenticate('CILogon')) 2. I added the error statement suggested by Mohammad Now I am getting 2019-02-26T12:10:46-0600 [INFO] ::ffff:127.0.0.1 - - [26/Feb/2019:18:10:46 +0000] "GET /passport/passportstrategies HTTP/1.1" 200 373 "https://gluu-testing.icecube.wisc.edu/oxauth/auth/passport/passportlogin.htm" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.119 Safari/537.36" 2019-02-26T12:10:48-0600 [INFO] ::ffff:127.0.0.1 - - [26/Feb/2019:18:10:48 +0000] "GET /passport/token HTTP/1.1" 200 201 "-" "Apache-HttpClient/4.5.3 (Java/1.8.0_181)" 2019-02-26T12:10:48-0600 [ERROR] Unknown Error: {} in the passport log Benedikt

By Jose Gonzalez staff 26 Feb 2019 at 2:54 p.m. CST

Jose Gonzalez gravatar
In the second call to `passportCILogon.authenticate` use 'cilogon' in the first parameter as in your first call. Then restart passport and let us know...

By Benedikt Riedel user 26 Feb 2019 at 3:37 p.m. CST

Benedikt Riedel gravatar
Same result as before. I am wondering whether I should just use an Oauth2 stragtegy, see https://github.com/jaredhanson/passport-oauth2/issues/81

By Jose Gonzalez staff 27 Feb 2019 at 8:11 a.m. CST

Jose Gonzalez gravatar
Benedikt, The openidconnect should work out of the box. Our customers are already using it... Maybe you missed some detail on the way. Why don't you simply use the openidconnect.js and routes provided out of the box instead of creating your own separate stuff? If I were asked to incorporate an OIDC provider with passport, here is what I would do: - Register a client at the external provider (cilogon). Set the redirect uri of the client with `https://your-gluu-host/passport/auth/openidconnect/callback` - In your Gluu server, add a strategy (using oxTrust) with name `openidconnect`. - Supply client ID + password - Add fields providing: issuer, authorizationURL, tokenURL, userInfoURL - Save, wait 1 minute, and test....

By Benedikt Riedel user 27 Feb 2019 at 2:17 p.m. CST

Benedikt Riedel gravatar
Hi Jose, that worked. Thanks! I have a few questions about setting up a registration flow. Where should I file does? Benedikt

By Mohammad Abudayyeh staff 27 Feb 2019 at 3:02 p.m. CST

Mohammad Abudayyeh gravatar
Great to hear that worked Benedikt. We are closing this ticket. Please feel free to open a new ticket clarifying your question a bit more. Thanks!