Invalid stream headers After update

By: Michael Evanson user 03 Mar 2016 at 12:17 p.m. CST

7 Responses
Michael Evanson gravatar
We have migrated our user base from gluu 2.4 to gluu 2.4.1 and now we are experiencing outages roughly every hour with a tomcat 500 error indicating that it came across an invalid stream header after a user clicks on login. When that first starts happening the system does not recover and necessitates a restart of the tomcat service within gluu. ie: GLUU.[root@auth ~]# service tomcat restart That does fix the issue, and as a temporary workaround we are running that command through cron every half hour When that error occurs, this is the full output in the wrapper.log in /opt/tomcat/logs/wrapper.log. This also includes a few lines prior to get an idea of when it occurs: INFO | jvm 1 | 2016/03/03 14:56:23 | 2016-03-03 14:56:22,964 DEBUG [org.gluu.oxtrust.ldap.service.MetadataValidationTimer] Metadata validation finished with result: 'false' INFO | jvm 1 | 2016/03/03 14:56:44 | 2016-03-03 14:56:44,748 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'getPageForStep' authenticator method INFO | jvm 1 | 2016/03/03 14:56:44 | 2016-03-03 14:56:44,749 TRACE [org.xdi.oxauth.service.SessionStateService] Generated new session, id = '891a1eb6-898b-4217-9724-f1932aec5cc4', state = 'unauthenticated', persisted = 'false' INFO | jvm 1 | 2016/03/03 14:56:44 | 2016-03-03 14:56:44,755 TRACE [xdi.oxauth.authorize.ws.rs.AuthorizeAction] Session '891a1eb6-898b-4217-9724-f1932aec5cc4' persisted to LDAP INFO | jvm 1 | 2016/03/03 14:56:44 | 2016-03-03 14:56:44,848 TRACE [org.xdi.oxauth.service.SessionStateService] Found session_state cookie: '891a1eb6-898b-4217-9724-f1932aec5cc4' INFO | jvm 1 | 2016/03/03 14:56:44 | 2016-03-03 14:56:44,852 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 891a1eb6-898b-4217-9724-f1932aec5cc4 ... INFO | jvm 1 | 2016/03/03 14:56:44 | 2016-03-03 14:56:44,852 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=891a1eb6-898b-4217-9724-f1932aec5cc4,ou=session,o=@!F98A.6DA6.8D60.675C!0001!1764.CB2E,o=gluu INFO | jvm 1 | 2016/03/03 14:56:44 | 2016-03-03 14:56:44,853 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Validating auth_mode: 'internal' INFO | jvm 1 | 2016/03/03 14:56:44 | 2016-03-03 14:56:44,853 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'isValidAuthenticationMethod' authenticator method INFO | jvm 1 | 2016/03/03 14:56:44 | 2016-03-03 14:56:44,853 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'prepareForStep' authenticator method INFO | jvm 1 | 2016/03/03 14:56:45 | 2016-03-03 14:56:45,399 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'getPageForStep' authenticator method INFO | jvm 1 | 2016/03/03 14:56:45 | 2016-03-03 14:56:45,401 TRACE [org.xdi.oxauth.service.SessionStateService] Generated new session, id = 'ee6b76ae-07ff-4dcc-b481-cf8da8fe7358', state = 'unauthenticated', persisted = 'false' INFO | jvm 1 | 2016/03/03 14:56:45 | 2016-03-03 14:56:45,410 TRACE [xdi.oxauth.authorize.ws.rs.AuthorizeAction] Session 'ee6b76ae-07ff-4dcc-b481-cf8da8fe7358' persisted to LDAP INFO | jvm 1 | 2016/03/03 14:56:45 | 2016-03-03 14:56:45,569 TRACE [org.xdi.oxauth.service.SessionStateService] Found session_state cookie: 'ee6b76ae-07ff-4dcc-b481-cf8da8fe7358' INFO | jvm 1 | 2016/03/03 14:56:45 | 2016-03-03 14:56:45,577 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: ee6b76ae-07ff-4dcc-b481-cf8da8fe7358 ... INFO | jvm 1 | 2016/03/03 14:56:45 | 2016-03-03 14:56:45,577 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=ee6b76ae-07ff-4dcc-b481-cf8da8fe7358,ou=session,o=@!F98A.6DA6.8D60.675C!0001!1764.CB2E,o=gluu INFO | jvm 1 | 2016/03/03 14:56:45 | 2016-03-03 14:56:45,578 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Validating auth_mode: 'internal' INFO | jvm 1 | 2016/03/03 14:56:45 | 2016-03-03 14:56:45,578 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'isValidAuthenticationMethod' authenticator method INFO | jvm 1 | 2016/03/03 14:56:45 | 2016-03-03 14:56:45,578 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'prepareForStep' authenticator method INFO | jvm 1 | 2016/03/03 14:56:58 | Mar 03, 2016 2:56:58 PM com.sun.faces.renderkit.ResponseStateManagerImpl getTreeStructureToRestore INFO | jvm 1 | 2016/03/03 14:56:58 | SEVERE: invalid stream header: 448C5276 INFO | jvm 1 | 2016/03/03 14:56:58 | java.io.StreamCorruptedException: invalid stream header: 448C5276 INFO | jvm 1 | 2016/03/03 14:56:58 | at java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:804) INFO | jvm 1 | 2016/03/03 14:56:58 | at java.io.ObjectInputStream.<init>(ObjectInputStream.java:299) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.faces.renderkit.ApplicationObjectInputStream.<init>(ApplicationObjectInputStream.java:81) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.faces.spi.SerializationProviderFactory$JavaSerializationProvider.createObjectInputStream(SerializationProviderFactory.java:211) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.faces.renderkit.ResponseStateManagerImpl.getTreeStructureToRestore(ResponseStateManagerImpl.java:170) INFO | jvm 1 | 2016/03/03 14:56:58 | at javax.faces.render.ResponseStateManager.getState(ResponseStateManager.java:226) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.faces.application.StateManagerImpl.restoreTree(StateManagerImpl.java:650) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.faces.application.StateManagerImpl.restoreView(StateManagerImpl.java:131) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.jsf.SeamStateManager.restoreView(SeamStateManager.java:76) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.faces.application.ViewHandlerImpl.restoreView(ViewHandlerImpl.java:311) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.jsf.SeamViewHandler.restoreView(SeamViewHandler.java:93) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.facelets.FaceletViewHandler.restoreView(FaceletViewHandler.java:317) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.faces.lifecycle.RestoreViewPhase.execute(RestoreViewPhase.java:175) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:100) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.faces.lifecycle.RestoreViewPhase.doPhase(RestoreViewPhase.java:103) INFO | jvm 1 | 2016/03/03 14:56:58 | at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118) INFO | jvm 1 | 2016/03/03 14:56:58 | at javax.faces.webapp.FacesServlet.service(FacesServlet.java:265) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:748) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:486) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:411) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:338) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.web.RewriteFilter.process(RewriteFilter.java:98) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.web.RewriteFilter.doFilter(RewriteFilter.java:57) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.web.LoggingFilter.doFilter(LoggingFilter.java:60) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:73) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.web.IdentityFilter.doFilter(IdentityFilter.java:40) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.web.MultipartFilter.doFilter(MultipartFilter.java:90) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.web.ExceptionFilter.doFilter(ExceptionFilter.java:64) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.web.RedirectFilter.doFilter(RedirectFilter.java:45) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:73) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.jboss.seam.servlet.SeamFilter.doFilter(SeamFilter.java:158) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:190) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314) INFO | jvm 1 | 2016/03/03 14:56:58 | at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) INFO | jvm 1 | 2016/03/03 14:56:58 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) INFO | jvm 1 | 2016/03/03 14:56:58 | at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) INFO | jvm 1 | 2016/03/03 14:56:58 | at java.lang.Thread.run(Thread.java:745) INFO | jvm 1 | 2016/03/03 14:56:58 | INFO | jvm 1 | 2016/03/03 14:56:58 | Mar 03, 2016 2:56:58 PM com.sun.faces.lifecycle.Phase doPhase INFO | jvm 1 | 2016/03/03 14:56:58 | SEVERE: JSF1054: (Phase ID: RESTORE_VIEW 1, View ID: ) Exception thrown during phase execution: javax.faces.event.PhaseEvent[source=com.sun.faces.lifecycle.LifecycleImpl@29ace333] INFO | jvm 1 | 2016/03/03 14:57:09 | 2016-03-03 14:57:09,891 DEBUG [org.gluu.oxtrust.ldap.service.StatusCheckerTimer] Starting update of appliance status
None
closed

Answers

By Aliaksandr Samuseu staff 03 Mar 2016 at 12:31 p.m. CST

Copy
Aliaksandr Samuseu gravatar
Hi, Michael. Thanks for reporting this. We'll try to reproduce the issue. Could you please stay in contact for some time so we could inquire you about other details of your setup? Regards, Alex.

By Michael Evanson user 03 Mar 2016 at 12:39 p.m. CST

Copy
Michael Evanson gravatar
Thanks Alex. Until you have further questions I can let you know that we are running centos 6.5 with 2G of raw ram and another 2G of swap. I know it isn't ideal, but assuming we can get it running our corporation will be able to approve an increase of ram. However during these times of the error we are not experiencing any shortages of ram. We have already set file descriptors to 64K

By Aliaksandr Samuseu staff 03 Mar 2016 at 12:41 p.m. CST

Copy
Aliaksandr Samuseu gravatar
Here is a few questions right away: 1. How much memory did you allocate for tomcat when you were running ./setup.py script during installation? How much RAM this host has in total? 2. Could you provide full name of the Gluu CE package you are using? Is OS at this host a 64 bit one? 3. How exactly did you conduct the transition from 2.4.0 to 2.4.1? 4. You said your issues happens once per hour approximately. And also it's triggered when login button is clicked. How much login attempts (approximately) does your instance serve per hour? 5. Are you familiar with java garbage collection monitoring? Have you tried to verify whether or not your issues has something to do with lack of heap memory in jvm already?

By Aliaksandr Samuseu staff 03 Mar 2016 at 12:50 p.m. CST

Copy
Aliaksandr Samuseu gravatar
> we are running centos 6.5 with 2G of raw ram and another 2G of swap That's too low, of course. I even remember being instructed to not consider issues when memory requirements aren't met :) (for 2.4.x instances that would be 4GB+ of RAM designated **exclusively** for tomcat's heap, so the host should have 5-6GB of RAM in total) What is in `/opt/tomcat/logs/catalina*`, `/opt/tomcat/logs/localhost*` and `/opt/tomcat/logs/host-manager*` logs? Anything memory-related? Could you provide output of `free -m` from the moment about half-hour since last restart due to this failure? In general, I think you should proceed with checking jvm's heap state, both for tomcat's jvm and for jvm used by opendj

By Mohib Zico staff 04 Mar 2016 at 7:03 a.m. CST

Copy
Mohib Zico gravatar
Michael, You can try to disable JSF viewState encryption. Here's how: 1. Remove '<env-entry> ... </env-entry> from 'web.xml' ( location: /opt/apache-tomcat-7.0.55/webapps/oxauth/WEB-INF ) 2. Remove '<Environment name.... />' from 'oxauth.xml' ( location: /opt/apache-tomcat-7.0.55/conf/Catalina/localhost ) 3. Restart tomcat

By Paul Frame user 04 Mar 2016 at 4:39 p.m. CST

Copy
Paul Frame gravatar
Related Question: What does JSF viewState encryption do? What do we lose by disabling it?

By Aliaksandr Samuseu staff 04 Mar 2016 at 7:29 p.m. CST

Copy
Aliaksandr Samuseu gravatar
Hi, Paul. From some paper I've found on the net: > From a more technical point of view, the ViewState is much more than bandwidth-intensive content. Its role is to memorize the state of a web form as it will be viewed by the user, even after numerous HTTP queries (stateless protocol). The objective is to store and restore results of users actions that impacted the user interface of a web page (choice within drop-down list, check-box selection So it's a blob of data describing the state of the page (filled fields, controls' states etc). viewState can either be stored on server, or (to unload server a bit) on client. In the former case the client only gets some id server will use to look up the state blob. In the latter case the blob will be sent to client and then returned again to server with POST request in a hidden field. That creates a possibility to [maliciously] mangle it at client-side. Encrypting the blob prevents it. So disabling encryption may lower security in some situations

Post an answer