Shibboleth IDPv4 on Windows (New Install)

Fri Jul 15 10:10:48 UTC 2022

Thanks for the response Rod. I stopped the service, cleared out the logs
completely, restarted the service. When it came back up there were no
errors or warnings in the log, just Info entries. So I then changed my
Website to point to it for authentication and I see the message on the
browser window say An error occurred: FlowExecutionException and then I
have the errors in the log. I am including the full log as of this time
from a clean start of the IDP service. This is the first time of setting
up Shibboleth IdP, have had no problem setting up ADFS, Azure SAML
application, Okta SAML application, and usually no problems setting up
Shibboleth SP connecting any IdP that is working. Maybe the "No Plugins
Loaded" or the "Algorithm failed" Info messages have something to do with
it?

2022-07-15 06:01:42,899 -  - INFO
[net.shibboleth.idp.log.LogbackLoggingService:245] - Shibboleth IdP
Version 4.2.1
2022-07-15 06:01:42,899 -  - INFO
[net.shibboleth.idp.log.LogbackLoggingService:246] - Java version='17'
vendor='Amazon.com Inc.'
2022-07-15 06:01:42,899 -  - INFO
[net.shibboleth.idp.log.LogbackLoggingService:259] - No Plugins Loaded
2022-07-15 06:01:42,945 -  - INFO
[net.shibboleth.idp.log.LogbackLoggingService:292] - Enabled Modules:
2022-07-15 06:01:42,945 -  - INFO
[net.shibboleth.idp.log.LogbackLoggingService:294] - 		Password
Authentication
2022-07-15 06:01:42,945 -  - INFO
[net.shibboleth.idp.log.LogbackLoggingService:294] - 		Hello
World
2022-07-15 06:01:42,961 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
00] - Service 'shibboleth.LoggingService': Reload interval set to: PT5M,
starting refresh thread
2022-07-15 06:01:43,055 -  - INFO
[net.shibboleth.utilities.java.support.xml.BasicParserPool:648] -
XMLSecurityManager of type
'com.sun.org.apache.xerces.internal.utils.XMLSecurityManager' is installed
2022-07-15 06:01:43,055 -  - INFO
[org.opensaml.core.config.InitializationService:49] - Initializing
OpenSAML using the Java Services API
2022-07-15 06:01:45,041 -  - INFO
[org.opensaml.xmlsec.algorithm.AlgorithmRegistry:256] - Algorithm failed
runtime support check, will not be usable:
http://www.w3.org/2001/04/xmlenc#ripemd160
2022-07-15 06:01:45,065 -  - INFO
[org.opensaml.xmlsec.algorithm.AlgorithmRegistry:256] - Algorithm failed
runtime support check, will not be usable:
http://www.w3.org/2001/04/xmldsig-more#hmac-ripemd160
2022-07-15 06:01:45,084 -  - INFO
[org.opensaml.xmlsec.algorithm.AlgorithmRegistry:256] - Algorithm failed
runtime support check, will not be usable:
http://www.w3.org/2001/04/xmldsig-more#rsa-ripemd160
2022-07-15 06:01:45,391 -  - INFO
[net.shibboleth.utilities.java.support.security.impl.BasicKeystoreKeyStrat
egy:377] - Loading initial default key: secret1
2022-07-15 06:01:45,632 -  - INFO
[net.shibboleth.utilities.java.support.security.impl.BasicKeystoreKeyStrat
egy:389] - Default key updated to secret1
2022-07-15 06:01:46,081 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:1
73] - Service 'shibboleth.AttributeRegistryService': Performing initial
load
2022-07-15 06:01:46,081 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
59] - Service 'shibboleth.AttributeRegistryService': Reloading service
configuration
2022-07-15 06:01:46,426 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:421] - Service
'shibboleth.AttributeRegistryService': Completed reload and swapped in
latest configuration for service 'shibboleth.AttributeRegistryService'
2022-07-15 06:01:46,426 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:428] - Service
'shibboleth.AttributeRegistryService': Reload complete
2022-07-15 06:01:46,427 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
00] - Service 'shibboleth.AttributeRegistryService': Reload interval set
to: PT15M, starting refresh thread
2022-07-15 06:01:46,436 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:1
73] - Service 'shibboleth.MetadataResolverService': Performing initial
load
2022-07-15 06:01:46,437 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
59] - Service 'shibboleth.MetadataResolverService': Reloading service
configuration
2022-07-15 06:01:46,702 -  - INFO
[org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolve
r:591] - Metadata Resolver FilesystemMetadataResolver LocalMetadata: New
metadata successfully loaded for 'C:\Program Files
(x86)\Shibboleth\IdP\metadata\sp\sprt-sql_Metadata.xml'
2022-07-15 06:01:46,703 -  - INFO
[org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolve
r:396] - Metadata Resolver FilesystemMetadataResolver LocalMetadata: Next
refresh cycle for metadata provider 'C:\Program Files
(x86)\Shibboleth\IdP\metadata\sp\sprt-sql_Metadata.xml' will occur on
'2022-07-15T13:01:46.674175800Z'
('2022-07-15T09:01:46.674175800-04:00[America/New_York]' local time)
2022-07-15 06:01:46,713 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:421] - Service
'shibboleth.MetadataResolverService': Completed reload and swapped in
latest configuration for service 'shibboleth.MetadataResolverService'
2022-07-15 06:01:46,713 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:428] - Service
'shibboleth.MetadataResolverService': Reload complete
2022-07-15 06:01:46,900 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:1
73] - Service 'shibboleth.AttributeFilterService': Performing initial load
2022-07-15 06:01:46,901 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
59] - Service 'shibboleth.AttributeFilterService': Reloading service
configuration
2022-07-15 06:01:47,056 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:421] - Service
'shibboleth.AttributeFilterService': Completed reload and swapped in
latest configuration for service 'shibboleth.AttributeFilterService'
2022-07-15 06:01:47,057 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:428] - Service
'shibboleth.AttributeFilterService': Reload complete
2022-07-15 06:01:47,057 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
00] - Service 'shibboleth.AttributeFilterService': Reload interval set to:
PT15M, starting refresh thread
2022-07-15 06:01:47,067 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:1
73] - Service 'shibboleth.AttributeResolverService': Performing initial
load
2022-07-15 06:01:47,067 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
59] - Service 'shibboleth.AttributeResolverService': Reloading service
configuration
2022-07-15 06:01:47,172 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:421] - Service
'shibboleth.AttributeResolverService': Completed reload and swapped in
latest configuration for service 'shibboleth.AttributeResolverService'
2022-07-15 06:01:47,172 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:428] - Service
'shibboleth.AttributeResolverService': Reload complete
2022-07-15 06:01:47,172 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
00] - Service 'shibboleth.AttributeResolverService': Reload interval set
to: PT15M, starting refresh thread
2022-07-15 06:01:47,180 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:1
73] - Service 'shibboleth.NameIdentifierGenerationService': Performing
initial load
2022-07-15 06:01:47,180 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
59] - Service 'shibboleth.NameIdentifierGenerationService': Reloading
service configuration
2022-07-15 06:01:47,276 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:421] - Service
'shibboleth.NameIdentifierGenerationService': Completed reload and swapped
in latest configuration for service
'shibboleth.NameIdentifierGenerationService'
2022-07-15 06:01:47,277 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:428] - Service
'shibboleth.NameIdentifierGenerationService': Reload complete
2022-07-15 06:01:47,277 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
00] - Service 'shibboleth.NameIdentifierGenerationService': Reload
interval set to: PT15M, starting refresh thread
2022-07-15 06:01:47,286 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:1
73] - Service 'shibboleth.RelyingPartyResolverService': Performing initial
load
2022-07-15 06:01:47,287 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
59] - Service 'shibboleth.RelyingPartyResolverService': Reloading service
configuration
2022-07-15 06:01:47,859 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:421] - Service
'shibboleth.RelyingPartyResolverService': Completed reload and swapped in
latest configuration for service 'shibboleth.RelyingPartyResolverService'
2022-07-15 06:01:47,859 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:428] - Service
'shibboleth.RelyingPartyResolverService': Reload complete
2022-07-15 06:01:47,860 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
00] - Service 'shibboleth.RelyingPartyResolverService': Reload interval
set to: PT15M, starting refresh thread
2022-07-15 06:01:47,865 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:1
73] - Service 'shibboleth.ReloadableAccessControlService': Performing
initial load
2022-07-15 06:01:47,866 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
59] - Service 'shibboleth.ReloadableAccessControlService': Reloading
service configuration
2022-07-15 06:01:47,905 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:421] - Service
'shibboleth.ReloadableAccessControlService': Completed reload and swapped
in latest configuration for service
'shibboleth.ReloadableAccessControlService'
2022-07-15 06:01:47,905 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:428] - Service
'shibboleth.ReloadableAccessControlService': Reload complete
2022-07-15 06:01:47,906 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
00] - Service 'shibboleth.ReloadableAccessControlService': Reload interval
set to: PT5M, starting refresh thread
2022-07-15 06:01:47,922 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:1
73] - Service 'shibboleth.ReloadableCASServiceRegistry': Performing
initial load
2022-07-15 06:01:47,922 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
59] - Service 'shibboleth.ReloadableCASServiceRegistry': Reloading service
configuration
2022-07-15 06:01:47,933 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:421] - Service
'shibboleth.ReloadableCASServiceRegistry': Completed reload and swapped in
latest configuration for service 'shibboleth.ReloadableCASServiceRegistry'
2022-07-15 06:01:47,934 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:428] - Service
'shibboleth.ReloadableCASServiceRegistry': Reload complete
2022-07-15 06:01:47,934 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
00] - Service 'shibboleth.ReloadableCASServiceRegistry': Reload interval
set to: PT15M, starting refresh thread
2022-07-15 06:01:47,940 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:1
73] - Service 'shibboleth.ManagedBeanService': Performing initial load
2022-07-15 06:01:47,941 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
59] - Service 'shibboleth.ManagedBeanService': Reloading service
configuration
2022-07-15 06:01:47,943 -  - INFO
[net.shibboleth.ext.spring.util.ApplicationContextBuilder:346] - Skipping
non-existent resource: ServletContext resource [/C:/Program Files
(x86)/Shibboleth/IdP/conf/managed-beans.xml]
2022-07-15 06:01:47,944 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:421] - Service
'shibboleth.ManagedBeanService': Completed reload and swapped in latest
configuration for service 'shibboleth.ManagedBeanService'
2022-07-15 06:01:47,944 -  - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:428] - Service
'shibboleth.ManagedBeanService': Reload complete
2022-07-15 06:01:47,945 -  - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:2
00] - Service 'shibboleth.ManagedBeanService': Reload interval set to:
PT15M, starting refresh thread
2022-07-15 06:01:50,031 -  - INFO
[net.shibboleth.idp.authn.impl.RemoteUserAuthServlet:214] -
RemoteUserAuthServlet will process REMOTE_USER, along with attributes []
and headers []
2022-07-15 06:03:12,747 - 192.168.0.241 - WARN
[net.shibboleth.ext.spring.context.FilesystemGenericWebApplicationContext:
591] - Exception encountered during context initialization - cancelling
refresh attempt: org.springframework.beans.factory.BeanCreationException:
Error creating bean with name 'shibboleth.authn.Password.Validators':
Cannot resolve reference to bean 'shibboleth.LDAPValidator' while setting
bean property 'sourceList' with key [0]; nested exception is
org.springframework.beans.factory.BeanCreationException: Error creating
bean with name 'ValidateUsernamePasswordAgainstLDAP' defined in class path
resource [net/shibboleth/idp/flows/authn/password-authn-beans.xml]: Cannot
resolve reference to bean 'shibboleth.authn.LDAP.authenticator' while
setting bean property 'authenticator'; nested exception is
org.springframework.beans.factory.BeanCreationException: Error creating
bean with name 'shibboleth.authn.LDAP.authenticator' defined in class path
resource [net/shibboleth/idp/flows/authn/password-authn-beans.xml]:
Invocation of init method failed; nested exception is
java.lang.IllegalArgumentException:
java.security.GeneralSecurityException: java.io.FileNotFoundException:
ServletContext resource [/undefined] cannot be resolved to absolute file
path - web application archive not expanded?
2022-07-15 06:03:12,755 - 192.168.0.241 - ERROR
[org.springframework.webflow.execution.FlowExecutionException:91] -
org.springframework.webflow.execution.FlowExecutionException: Exception
thrown in state 'CallAuthenticationFlow' of flow 'authn'
	at
org.springframework.webflow.engine.impl.FlowExecutionImpl.wrap(FlowExecuti
onImpl.java:573)
Caused by: org.springframework.beans.factory.BeanCreationException: Error
creating bean with name 'shibboleth.authn.Password.Validators': Cannot
resolve reference to bean 'shibboleth.LDAPValidator' while setting bean
property 'sourceList' with key [0]; nested exception is
org.springframework.beans.factory.BeanCreationException: Error creating
bean with name 'ValidateUsernamePasswordAgainstLDAP' defined in class path
resource [net/shibboleth/idp/flows/authn/password-authn-beans.xml]: Cannot
resolve reference to bean 'shibboleth.authn.LDAP.authenticator' while
setting bean property 'authenticator'; nested exception is
org.springframework.beans.factory.BeanCreationException: Error creating
bean with name 'shibboleth.authn.LDAP.authenticator' defined in class path
resource [net/shibboleth/idp/flows/authn/password-authn-beans.xml]:
Invocation of init method failed; nested exception is
java.lang.IllegalArgumentException:
java.security.GeneralSecurityException: java.io.FileNotFoundException:
ServletContext resource [/undefined] cannot be resolved to absolute file
path - web application archive not expanded?
	at
org.springframework.beans.factory.support.BeanDefinitionValueResolver.reso
lveReference(BeanDefinitionValueResolver.java:342)
Caused by: org.springframework.beans.factory.BeanCreationException: Error
creating bean with name 'ValidateUsernamePasswordAgainstLDAP' defined in
class path resource
[net/shibboleth/idp/flows/authn/password-authn-beans.xml]: Cannot resolve
reference to bean 'shibboleth.authn.LDAP.authenticator' while setting bean
property 'authenticator'; nested exception is
org.springframework.beans.factory.BeanCreationException: Error creating
bean with name 'shibboleth.authn.LDAP.authenticator' defined in class path
resource [net/shibboleth/idp/flows/authn/password-authn-beans.xml]:
Invocation of init method failed; nested exception is
java.lang.IllegalArgumentException:
java.security.GeneralSecurityException: java.io.FileNotFoundException:
ServletContext resource [/undefined] cannot be resolved to absolute file
path - web application archive not expanded?
	at
org.springframework.beans.factory.support.BeanDefinitionValueResolver.reso
lveReference(BeanDefinitionValueResolver.java:342)
Caused by: org.springframework.beans.factory.BeanCreationException: Error
creating bean with name 'shibboleth.authn.LDAP.authenticator' defined in
class path resource
[net/shibboleth/idp/flows/authn/password-authn-beans.xml]: Invocation of
init method failed; nested exception is
java.lang.IllegalArgumentException:
java.security.GeneralSecurityException: java.io.FileNotFoundException:
ServletContext resource [/undefined] cannot be resolved to absolute file
path - web application archive not expanded?
	at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFacto
ry.initializeBean(AbstractAutowireCapableBeanFactory.java:1804)
Caused by: java.lang.IllegalArgumentException:
java.security.GeneralSecurityException: java.io.FileNotFoundException:
ServletContext resource [/undefined] cannot be resolved to absolute file
path - web application archive not expanded?
	at
org.ldaptive.provider.unboundid.UnboundIDProvider.getConnectionFactory(Unb
oundIDProvider.java:51)
Caused by: java.security.GeneralSecurityException:
java.io.FileNotFoundException: ServletContext resource [/undefined] cannot
be resolved to absolute file path - web application archive not expanded?
	at
net.shibboleth.idp.authn.impl.X509ResourceCredentialConfig.createSSLContex
tInitializer(X509ResourceCredentialConfig.java:107)
Caused by: java.io.FileNotFoundException: ServletContext resource
[/undefined] cannot be resolved to absolute file path - web application
archive not expanded?
	at
org.springframework.web.util.WebUtils.getRealPath(WebUtils.java:344)

Rick Hoodenpyle
DevOps Specialist
Residential Management Systems, Inc.

-----Original Message-----
From: users <users-bounces at shibboleth.net> On Behalf Of Rod Widdowson
Sent: 15 July 2022 10:58
To: 'Shib Users' <users at shibboleth.net>
Subject: RE: Shibboleth IDPv4 on Windows (New Install)

That error of itself makes little sense "something went wrong because
things were already broken"

> Can you assist me in finding where to look for this issue?

Your first stage should be to look further up in the log for the first
error and fix that.    It may have something to do with
"shibboleth.LDAPValidator" or there may be other errors even earlier.

	/Rod

-- 
For Consortium Member technical support, see
https://shibboleth.atlassian.net/wiki/x/ZYEpPw
To unsubscribe from this list send an email to
users-unsubscribe at shibboleth.net
-------------- next part --------------
A non-text attachment was scrubbed...
Name: idp-process.log
Type: application/octet-stream
Size: 17646 bytes
Desc: not available
URL: <http://shibboleth.net/pipermail/users/attachments/20220715/7ec7ba70/attachment.obj>