search

OpenConext / OpenConext-voot

Retrieve user's groups via the VOOT protocol protected by OAuth
Apache License 2.0
2 stars 2 forks source link

Voot is slow to start #3

Closed baszoetekouw closed 8 years ago

baszoetekouw commented 8 years ago

Voor is very slow to start (typically 90 seconds, but sometimes it takes as long as 500s).
After enabling debugging in the application.properties, I get this in the voot.log:

2016-09-20 10:42:56,814  INFO [localhost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean:258 - Mapping filter: 'characterEncodingFilter' to: [/*]
2016-09-20 10:42:56,815  INFO [localhost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean:258 - Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2016-09-20 10:42:56,815  INFO [localhost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean:258 - Mapping filter: 'httpPutFormContentFilter' to: [/*]
2016-09-20 10:42:56,815  INFO [localhost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean:258 - Mapping filter: 'requestContextFilter' to: [/*]
2016-09-20 10:42:56,817  INFO [localhost-startStop-1] o.s.b.c.e.DelegatingFilterProxyRegistrationBean:258 - Mapping filter: 'springSecurityFilterChain' to: [/*]
2016-09-20 10:42:56,817  INFO [localhost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean:258 - Mapping filter: 'applicationContextIdFilter' to: [/*]
2016-09-20 10:42:56,817  INFO [localhost-startStop-1] o.s.b.c.embedded.ServletRegistrationBean:189 - Mapping servlet: 'dispatcherServlet' to [/]
2016-09-20 10:48:09,587 DEBUG [localhost-startStop-1] o.s.b.c.web.OrderedRequestContextFilter:177 - Initializing filter 'requestContextFilter'
2016-09-20 10:48:09,591 DEBUG [localhost-startStop-1] o.s.b.c.web.OrderedRequestContextFilter:202 - Filter 'requestContextFilter' configured successfully
2016-09-20 10:48:09,593 DEBUG [localhost-startStop-1] o.s.b.a.a.EndpointWebMvcAutoConfiguration$ApplicationContextHeaderFilter:177 - Initializing filter 'applicationContextIdFilter'
2016-09-20 10:48:09,593 DEBUG [localhost-startStop-1] o.s.b.a.a.EndpointWebMvcAutoConfiguration$ApplicationContextHeaderFilter:202 - Filter 'applicationContextIdFilter' configured successfully
2016-09-20 10:48:09,594 DEBUG [localhost-startStop-1] o.s.b.c.w.OrderedHttpPutFormContentFilter:177 - Initializing filter 'httpPutFormContentFilter'
2016-09-20 10:48:09,594 DEBUG [localhost-startStop-1] o.s.b.c.w.OrderedHttpPutFormContentFilter:202 - Filter 'httpPutFormContentFilter' configured successfully
2016-09-20 10:48:09,595 DEBUG [localhost-startStop-1] o.s.b.c.w.OrderedHiddenHttpMethodFilter:177 - Initializing filter 'hiddenHttpMethodFilter'
2016-09-20 10:48:09,595 DEBUG [localhost-startStop-1] o.s.b.c.w.OrderedHiddenHttpMethodFilter:202 - Filter 'hiddenHttpMethodFilter' configured successfully
2016-09-20 10:48:09,596 DEBUG [localhost-startStop-1] o.s.b.c.w.OrderedCharacterEncodingFilter:177 - Initializing filter 'characterEncodingFilter'
2016-09-20 10:48:09,596 DEBUG [localhost-startStop-1] o.s.b.c.w.OrderedCharacterEncodingFilter:202 - Filter 'characterEncodingFilter' configured successfully
2016-09-20 10:48:10,538 DEBUG [localhost-startStop-1] o.s.b.a.s.BootGlobalAuthenticationConfiguration:77 - Eagerly initializing {vootServiceApplication=voot.VootServiceApplication$$EnhancerBySpringCGLIB$$7d80637d@459cf475}

So it hangs in between the call to o.s.b.c.embedded.ServletRegistrationBean:189 and o.s.b.c.web.OrderedRequestContextFilter:177.

Anyone got an idea of what is going on here?

baszoetekouw commented 8 years ago

Enabling some more debugging add the following messages in between the two messages with the delay in between, as shown above:

2016-09-20 10:52:42,431  INFO [localhost-startStop-1] o.s.b.c.embedded.ServletRegistrationBean:189 - Mapping servlet: 'dispatcherServlet' to [/]
2016-09-20 10:52:42,432 DEBUG [localhost-startStop-1] org.apache.catalina.core.ContainerBase:180 - Add child StandardWrapper[dispatcherServlet] StandardEngine[Tomcat].StandardHost[localhost].StandardContext[]
2016-09-20 10:52:42,432 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet]] to [INITIALIZING]
2016-09-20 10:52:42,433 DEBUG [localhost-startStop-1] org.apache.tomcat.util.modeler.Registry:180 - Managed= Tomcat:j2eeType=Servlet,WebModule=//localhost/,name=dispatcherServlet,J2EEApplication=none,J2EEServer=none
2016-09-20 10:52:42,433 DEBUG [localhost-startStop-1] o.a.tomcat.util.modeler.BaseModelMBean:180 - preRegister StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet] Tomcat:j2eeType=Servlet,WebModule=//localhost/,name=dispatcherServlet,J2EEApplication=none,J2EEServer=none
2016-09-20 10:52:42,433 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet]] to [INITIALIZED]
2016-09-20 10:52:42,433 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet]] to [STARTING_PREP]
2016-09-20 10:52:42,434 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet]]] to [INITIALIZING]
2016-09-20 10:52:42,434 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet]]] to [INITIALIZED]
2016-09-20 10:52:42,434 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet]]] to [STARTING_PREP]
2016-09-20 10:52:42,434 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.core.StandardWrapperValve[dispatcherServlet]] to [INITIALIZING]
2016-09-20 10:52:42,435 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.core.StandardWrapperValve[dispatcherServlet]] to [INITIALIZED]
2016-09-20 10:52:42,435 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.core.StandardWrapperValve[dispatcherServlet]] to [STARTING_PREP]
2016-09-20 10:52:42,435 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.core.StandardWrapperValve[dispatcherServlet]] to [STARTING]
2016-09-20 10:52:42,435 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.core.StandardWrapperValve[dispatcherServlet]] to [STARTED]
2016-09-20 10:52:42,436 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet]]] to [STARTING]
2016-09-20 10:52:42,436 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [Pipeline[StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet]]] to [STARTED]
2016-09-20 10:52:42,436 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet]] to [STARTING]
2016-09-20 10:52:42,436 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [StandardEngine[Tomcat].StandardHost[localhost].StandardContext[].StandardWrapper[dispatcherServlet]] to [STARTED]
2016-09-20 10:52:42,438 DEBUG [localhost-startStop-1] org.apache.catalina.core.StandardContext:180 - Configuring application event listeners
2016-09-20 10:52:42,438 DEBUG [localhost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/]:180 -  Configuring event listener class 'org.apache.tomcat.websocket.server.WsContextListener'
2016-09-20 10:52:42,440 DEBUG [localhost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/]:180 - Sending application start events
2016-09-20 10:52:42,465 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.session.StandardManager[]] to [INITIALIZING]
2016-09-20 10:52:42,465 DEBUG [localhost-startStop-1] org.apache.tomcat.util.modeler.Registry:180 - Managed= Tomcat:type=Manager,host=localhost,context=/
2016-09-20 10:52:42,466 DEBUG [localhost-startStop-1] o.a.tomcat.util.modeler.BaseModelMBean:180 - preRegister org.apache.catalina.session.StandardManager[] Tomcat:type=Manager,host=localhost,context=/
2016-09-20 10:52:42,466 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.session.StandardManager[]] to [INITIALIZED]
2016-09-20 10:52:42,466 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.session.StandardManager[]] to [STARTING_PREP]
2016-09-20 10:52:42,466 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.util.StandardSessionIdGenerator@4509c1f6] to [INITIALIZING]
2016-09-20 10:52:42,466 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.util.StandardSessionIdGenerator@4509c1f6] to [INITIALIZED]
2016-09-20 10:52:42,467 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.util.StandardSessionIdGenerator@4509c1f6] to [STARTING_PREP]
2016-09-20 10:53:47,523  INFO [localhost-startStop-1] o.a.catalina.util.SessionIdGeneratorBase:180 - Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [65,051] milliseconds.
2016-09-20 10:53:47,524 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.util.StandardSessionIdGenerator@4509c1f6] to [STARTING]
2016-09-20 10:53:47,524 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.util.StandardSessionIdGenerator@4509c1f6] to [STARTED]
2016-09-20 10:53:47,524 DEBUG [localhost-startStop-1] o.a.catalina.session.StandardManager:180 - Start: Loading persisted sessions
2016-09-20 10:53:47,525 DEBUG [localhost-startStop-1] o.a.catalina.session.StandardManager:180 - Loading persisted sessions from SESSIONS.ser
2016-09-20 10:53:47,526 DEBUG [localhost-startStop-1] o.a.catalina.session.StandardManager:180 - No persisted data file found
2016-09-20 10:53:47,526 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.session.StandardManager[]] to [STARTING]
2016-09-20 10:53:47,526 DEBUG [localhost-startStop-1] org.apache.catalina.util.LifecycleBase:180 - Setting state for [org.apache.catalina.session.StandardManager[]] to [STARTED]
2016-09-20 10:53:47,526 DEBUG [localhost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/]:180 - Starting filters
2016-09-20 10:53:47,527 DEBUG [localhost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/]:180 -  Starting filter 'requestContextFilter'
2016-09-20 10:53:47,530 DEBUG [localhost-startStop-1] o.s.b.c.web.OrderedRequestContextFilter:177 - Initializing filter 'requestContextFilter'

note that the delay is a bit less than before (only 60 seconds). This is consistent with the behaviour I'm observing: at best, startup takes ~80 seconds (of which 60 seconds it's sitting doing nothing), other times it takes ~500 seconds.

baszoetekouw commented 8 years ago

Ah, maybe it has something to with entropy? What does this do, exactly?:

Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [65,051] milliseconds
baszoetekouw commented 8 years ago

Indeed, it seems to be an entorpy issue. If I change the entropy source in /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.102-1.b14.el7_2.x86_64/jre/lib/security/java.security from /dev/random to /dev/urandom, startup becomes quite fast (~10 seconds).

\

baszoetekouw commented 8 years ago

According to http://www.2uo.de/myths-about-urandom/ it should be fine to use /dev/urandom. @pmeulen, what do you think?

thijskh commented 8 years ago

This has been fixed in OpenConext/OpenConext-deploy#98