Fresh IdP - idp-process.log shows 15 min gap

Organic_Iowa spencer.babcock at enseva.com
Wed Mar 7 18:27:05 EST 2018 

Thanks for the reply.

I tried first with real java and the latest jetty, and then downgraded jetty
to 9.3.21, and I am getting the same hanging result.

cat /opt/shibboleth-idp/logs/idp-process.log:

2018-03-07 23:02:55,702 - INFO
[net.shibboleth.idp.log.LogbackLoggingService:240] - Shibboleth IdP Version
3.3.2
2018-03-07 23:02:55,711 - INFO
[net.shibboleth.idp.log.LogbackLoggingService:241] - Java version='9.0.4'
vendor='Oracle Corporation'
2018-03-07 23:02:55,723 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:199]
- Service 'shibboleth.LoggingService': Reload time set to: 300000, starting
refresh thread
2018-03-07 23:02:55,780 - INFO
[org.opensaml.core.config.InitializationService:48] - Initializing OpenSAML
using the Java Services API
2018-03-07 23:02:56,648 - INFO
[org.opensaml.xmlsec.algorithm.AlgorithmRegistry:206] - Algorithm failed
runtime support check, will not be usable:
http://www.w3.org/2001/04/xmlenc#ripemd160
2018-03-07 23:02:56,656 - 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
2018-03-07 23:02:56,666 - 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
2018-03-07 23:02:57,025 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:172]
- Service 'shibboleth.AttributeFilterService': Performing initial load
2018-03-07 23:02:57,026 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:258]
- Service 'shibboleth.AttributeFilterService': Reloading service
configuration
2018-03-07 23:02:57,036 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/conf/attribute-filter.xml]
2018-03-07 23:14:37,864 - INFO
[net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581]
- Refreshing ApplicationContext:shibboleth.AttributeFilterService: startup
date [Wed Mar 07 23:14:37 UTC 2018]; parent: Root WebApplicationContext
2018-03-07 23:14:37,913 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service
'shibboleth.AttributeFilterService': Completed reload and swapped in latest
configuration for service 'shibboleth.AttributeFilterService'
2018-03-07 23:14:37,914 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service
'shibboleth.AttributeFilterService': Reload complete
2018-03-07 23:14:37,918 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:199]
- Service 'shibboleth.AttributeFilterService': Reload time set to: 900000,
starting refresh thread
2018-03-07 23:14:37,937 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:172]
- Service 'shibboleth.AttributeResolverService': Performing initial load
2018-03-07 23:14:37,937 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:258]
- Service 'shibboleth.AttributeResolverService': Reloading service
configuration
2018-03-07 23:14:37,946 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/conf/attribute-resolver.xml]
2018-03-07 23:14:38,036 - INFO
[net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] -
Parsing configuration for AttributeDefinition plugin with id:
eduPersonPrincipalName
2018-03-07 23:14:38,037 - INFO
[net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54]
- Parsing configuration for Dependency with pluginId: uid
2018-03-07 23:14:38,043 - INFO
[net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] -
Parsing configuration for AttributeDefinition plugin with id: uid
2018-03-07 23:14:38,045 - INFO
[net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] -
Parsing configuration for AttributeDefinition plugin with id: mail
2018-03-07 23:14:38,046 - INFO
[net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54]
- Parsing configuration for Dependency with pluginId: uid
2018-03-07 23:14:38,048 - INFO
[net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] -
Parsing configuration for AttributeDefinition plugin with id:
eduPersonScopedAffiliation
2018-03-07 23:14:38,049 - INFO
[net.shibboleth.idp.attribute.resolver.spring.ResolverPluginDependencyParser:54]
- Parsing configuration for Dependency with pluginId: staticAttributes
2018-03-07 23:14:38,051 - INFO
[net.shibboleth.idp.attribute.resolver.spring.BaseResolverPluginParser:60] -
Parsing configuration for DataConnector plugin with id: staticAttributes
2018-03-07 23:14:38,052 - INFO
[net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581]
- Refreshing ApplicationContext:shibboleth.AttributeResolverService: startup
date [Wed Mar 07 23:14:38 UTC 2018]; parent: Root WebApplicationContext
2018-03-07 23:14:38,242 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service
'shibboleth.AttributeResolverService': Completed reload and swapped in
latest configuration for service 'shibboleth.AttributeResolverService'
2018-03-07 23:14:38,242 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service
'shibboleth.AttributeResolverService': Reload complete
2018-03-07 23:14:38,248 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:199]
- Service 'shibboleth.AttributeResolverService': Reload time set to: 900000,
starting refresh thread
2018-03-07 23:14:38,263 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:172]
- Service 'shibboleth.NameIdentifierGenerationService': Performing initial
load
2018-03-07 23:14:38,263 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:258]
- Service 'shibboleth.NameIdentifierGenerationService': Reloading service
configuration
2018-03-07 23:14:38,270 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/conf/saml-nameid.xml]
2018-03-07 23:14:38,292 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/system/conf/saml-nameid-system.xml]
2018-03-07 23:14:38,308 - INFO
[net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581]
- Refreshing ApplicationContext:shibboleth.NameIdentifierGenerationService:
startup date [Wed Mar 07 23:14:38 UTC 2018]; parent: Root
WebApplicationContext
2018-03-07 23:14:38,460 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service
'shibboleth.NameIdentifierGenerationService': Completed reload and swapped
in latest configuration for service
'shibboleth.NameIdentifierGenerationService'
2018-03-07 23:14:38,461 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service
'shibboleth.NameIdentifierGenerationService': Reload complete
2018-03-07 23:14:38,476 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:199]
- Service 'shibboleth.NameIdentifierGenerationService': Reload time set to:
900000, starting refresh thread
2018-03-07 23:14:38,493 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:172]
- Service 'shibboleth.RelyingPartyResolverService': Performing initial load
2018-03-07 23:14:38,494 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:258]
- Service 'shibboleth.RelyingPartyResolverService': Reloading service
configuration
2018-03-07 23:14:38,497 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/conf/relying-party.xml]
2018-03-07 23:14:38,522 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/conf/credentials.xml]
2018-03-07 23:14:38,543 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/system/conf/relying-party-system.xml]
2018-03-07 23:14:38,597 - INFO
[net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581]
- Refreshing ApplicationContext:shibboleth.RelyingPartyResolverService:
startup date [Wed Mar 07 23:14:38 UTC 2018]; parent: Root
WebApplicationContext
2018-03-07 23:14:39,067 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:172]
- Service 'shibboleth.MetadataResolverService': Performing initial load
2018-03-07 23:14:39,068 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:258]
- Service 'shibboleth.MetadataResolverService': Reloading service
configuration
2018-03-07 23:14:39,071 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/conf/metadata-providers.xml]
2018-03-07 23:14:39,125 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/system/conf/metadata-providers-system.xml]
2018-03-07 23:14:39,134 - INFO
[net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581]
- Refreshing ApplicationContext:shibboleth.MetadataResolverService: startup
date [Wed Mar 07 23:14:39 UTC 2018]; parent: Root WebApplicationContext
2018-03-07 23:14:39,163 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service
'shibboleth.MetadataResolverService': Completed reload and swapped in latest
configuration for service 'shibboleth.MetadataResolverService'
2018-03-07 23:14:39,163 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service
'shibboleth.MetadataResolverService': Reload complete
2018-03-07 23:14:39,268 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service
'shibboleth.RelyingPartyResolverService': Completed reload and swapped in
latest configuration for service 'shibboleth.RelyingPartyResolverService'
2018-03-07 23:14:39,268 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service
'shibboleth.RelyingPartyResolverService': Reload complete
2018-03-07 23:14:39,268 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:199]
- Service 'shibboleth.RelyingPartyResolverService': Reload time set to:
900000, starting refresh thread
2018-03-07 23:14:39,278 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:172]
- Service 'shibboleth.ReloadableAccessControlService': Performing initial
load
2018-03-07 23:14:39,278 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:258]
- Service 'shibboleth.ReloadableAccessControlService': Reloading service
configuration
2018-03-07 23:14:39,283 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/conf/access-control.xml]
2018-03-07 23:14:39,302 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/system/conf/access-control-system.xml]
2018-03-07 23:14:39,310 - INFO
[net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581]
- Refreshing ApplicationContext:shibboleth.ReloadableAccessControlService:
startup date [Wed Mar 07 23:14:39 UTC 2018]; parent: Root
WebApplicationContext
2018-03-07 23:14:39,341 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service
'shibboleth.ReloadableAccessControlService': Completed reload and swapped in
latest configuration for service 'shibboleth.ReloadableAccessControlService'
2018-03-07 23:14:39,341 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service
'shibboleth.ReloadableAccessControlService': Reload complete
2018-03-07 23:14:39,343 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:199]
- Service 'shibboleth.ReloadableAccessControlService': Reload time set to:
300000, starting refresh thread
2018-03-07 23:14:39,363 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:172]
- Service 'shibboleth.ReloadableCASServiceRegistry': Performing initial load
2018-03-07 23:14:39,363 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:258]
- Service 'shibboleth.ReloadableCASServiceRegistry': Reloading service
configuration
2018-03-07 23:14:39,366 - INFO
[net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317]
- Loading XML bean definitions from file
[/opt/shibboleth-idp/conf/cas-protocol.xml]
2018-03-07 23:14:39,377 - INFO
[net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:581]
- Refreshing ApplicationContext:shibboleth.ReloadableCASServiceRegistry:
startup date [Wed Mar 07 23:14:39 UTC 2018]; parent: Root
WebApplicationContext
2018-03-07 23:14:39,396 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:380] - Service
'shibboleth.ReloadableCASServiceRegistry': Completed reload and swapped in
latest configuration for service 'shibboleth.ReloadableCASServiceRegistry'
2018-03-07 23:14:39,396 - INFO
[net.shibboleth.ext.spring.service.ReloadableSpringService:387] - Service
'shibboleth.ReloadableCASServiceRegistry': Reload complete
2018-03-07 23:14:39,400 - INFO
[net.shibboleth.utilities.java.support.service.AbstractReloadableService:199]
- Service 'shibboleth.ReloadableCASServiceRegistry': Reload time set to:
900000, starting refresh thread
2018-03-07 23:14:40,092 - INFO
[net.shibboleth.ext.spring.context.DelimiterAwareApplicationContext:581] -
Refreshing WebApplicationContext for namespace 'idp-servlet': startup date
[Wed Mar 07 23:14:40 UTC 2018]; parent: Root WebApplicationContext
2018-03-07 23:14:40,760 - INFO
[net.shibboleth.idp.authn.impl.RemoteUserAuthServlet:193] -
RemoteUserAuthServlet will process REMOTE_USER, along with attributes [] and
headers []


cat /home/idp/logs/2018_03_07.stderrout.log

2018-03-07 23:02:45.483:INFO:oejs.Server:main: jetty-9.3.21.v20170918
2018-03-07 23:02:45.502:INFO:oejs.AbstractNCSARequestLog:main: Opened
/home/idp/logs/2018_03_07.request.log
2018-03-07 23:02:45.505:INFO:oejdp.ScanningAppProvider:main: Deployment
monitor [file:///home/idp/webapps/] at interval 1
2018-03-07 23:02:52.800:INFO:oeja.AnnotationConfiguration:main: Scanning
elapsed time=5599ms
2018-03-07 23:02:52.831:INFO:/idp:main: No Spring WebApplicationInitializer
types detected on classpath
2018-03-07 23:02:53.002:WARN:oejs.SecurityHandler:main:
ServletContext at o.e.j.w.WebAppContext@32b260fa{/idp,[file:///home/idp/temp/jetty-0.0.0.0-8080-idp.war-_idp-any-11710141993611684187.dir/webinf/,
jar:file:///opt/shibboleth-idp/war/idp.war!/],STARTING}{/opt/shibboleth-idp/war/idp.war}
has uncovered http methods for path: /*
2018-03-07 23:02:53.238:INFO:/idp:main: Initializing Spring root
WebApplicationContext
2018-03-07 23:14:40.087:INFO:/idp:main: Initializing Spring FrameworkServlet
'idp'
2018-03-07 23:14:40.762:INFO:oejsh.ContextHandler:main: Started
o.e.j.w.WebAppContext at 32b260fa{/idp,[file:///home/idp/temp/jetty-0.0.0.0-8080-idp.war-_idp-any-11710141993611684187.dir/webinf/,
jar:file:///opt/shibboleth-idp/war/idp.war!/],AVAILABLE}{/opt/shibboleth-idp/war/idp.war}
2018-03-07 23:14:40.778:INFO:oejs.AbstractConnector:main: Started
ServerConnector at 33e6bd36{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}
2018-03-07 23:14:40.779:INFO:oejs.Server:main: Started @716075ms

During this process I did a cat /proc/sys/kernel/random/entropy_avail and it
was at 21, now it is at 105. Not sure if that matters or not.

The VM has 2 VCPU and 4GB RAM.

Thanks!





--
Sent from: http://shibboleth.1660669.n2.nabble.com/Shibboleth-Users-f1660767.html

More information about the users mailing list