"Encountered error parsing message into its DOM representation" and "Unable to read XML from input stream"

[Derek Yuen]

Hi,

While investigating another problem on my production Shibboleth IdP 2.2.1 (with ECP extension), I noticed that there has been an increased frequency of the following error in the IdP's idp-process log:

17:06:37.054 - ERROR [org.opensaml.ws.message.decoder.BaseMessageDecoder:186] - Encountered error parsing message into its DOM representation
org.opensaml.xml.parse.XMLParserException: Unable to read XML from input stream

(There's a stack dump as well which I've included at the bottom of this message.)


Worth mentioning is that the IdP was completely not responsive today, requiring a restart of Apache HTTPD and Tomcat.
The only entries in the idp-process log leading up to, and throughout the the outage were these "Encountered error parsing message into its DOM representation" lines (with stack dumps), and there were a lot of them until the services were restarted.

I couldn't locate much from the shib-users mailing list archives; I found some ideas and pursued them.
A report of a problem with the similar error (but different stack dump output) suggests a corruption of an "incoming (deflated and base64 encoded) message". I don't completely understand what this means, but would be happy to investigate with some advice.

Another idea was: "If you have a load balancer, perhaps it's due to the load balancer re-routing traffic to another node while an authentication transaction was in-flight?"
      Yes, we have a load balancer (F5) in front of the IdP but at the time I had disabled the second node in the server pool. 
      I've also verified that no traffic was being sent to the standby host either before or during the problem.

What I do know is, I had configured our load balancer so that only the one IdP is handling our entire production load.
(I had wanted to test something on the other IdP).

It ran fine for a few hours (say 3-4 hours?) and then the outage. 
I don't see any contention on the system for compute resources (cpu utilization was low; memory was around 50% used)
I mistakenly didn't enable logging of garbage collection so I don't know if there was a very long garbage collection pause.
This problem seems to be load related but the unresponsive behaviour and repetitive errors suggest to me a deadlock somewhere, but i'm only guessing.

I did try to run a jstack at the time of the problem but i can't seem to find the output. 
I'll keep looking.

I'm no Java developer nor am I an expert in analyzing Java thread dumps/stack analysis. 
Could someone please help me decipher the stack dump ?
Is there additional debugging or diagnostic information that could help? 



Thanks in advance for any insight.


Sincerely appreciated,
Derek

P.S:  Environment: Shibboleth IdP 2.2.1 with ECP on RHEL 5 / Apache 2.2.3 / Tomcat 6 / Java JDK 1.6.0_24 / local MySQL 5 persistentId store









In our idp-process log:

17:06:37.051 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/SOAP/ECP
17:06:37.051 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:96] - shibboleth.HandlerManager: Located profile handler of the following type for the request path: edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler
17:06:37.051 - DEBUG [edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler:291] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:SOAP'
17:06:37.051 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:72] - Beginning to decode message from inbound transport of type: org.opensaml.ws.transport.http.HttpServletRequestAdapter
17:06:37.051 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPSOAP11Decoder:121] - Unmarshalling SOAP message
17:06:37.051 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:161] - Parsing message stream into DOM document
17:06:37.054 - ERROR [org.opensaml.ws.message.decoder.BaseMessageDecoder:186] - Encountered error parsing message into its DOM representation
org.opensaml.xml.parse.XMLParserException: Unable to read XML from input stream
        at org.opensaml.xml.parse.BasicParserPool.parse(BasicParserPool.java:220) ~[xmltooling-1.3.1.jar:na]
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:164) [openws-1.4.1.jar:na]
        at org.opensaml.saml2.binding.decoding.HTTPSOAP11Decoder.doDecode(HTTPSOAP11Decoder.java:122) [opensaml-2.4.1.jar:na]
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:75) [openws-1.4.1.jar:na]
        at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69) [opensaml-2.4.1.jar:na]
        at edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler.decodeRequest(ECPProfileHandler.java:308) [shibboleth-idp-ext-ecp-1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler.completeAuthenticationRequest(ECPProfileHandler.java:215) [shibboleth-idp-ext-ecp-1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler.processRequest(ECPProfileHandler.java:193) [shibboleth-idp-ext-ecp-1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler.processRequest(ECPProfileHandler.java:110) [shibboleth-idp-ext-ecp-1.2.jar:na]
        at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:83) [shibboleth-common-1.2.1.jar:na]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) [servlet-api.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) [catalina.jar:6.0.32]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.32]
        at edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:49) [shibboleth-identityprovider-2.2.1.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.32]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.32]
        at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:77) [shibboleth-identityprovider-2.2.1.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.32]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.32]
        at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:51) [shibboleth-common-1.2.1.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.32]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.32]
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) [catalina.jar:6.0.32]
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) [catalina.jar:6.0.32]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [catalina.jar:6.0.32]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [catalina.jar:6.0.32]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [catalina.jar:6.0.32]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298) [catalina.jar:6.0.32]
        at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190) [tomcat-coyote.jar:6.0.32]
        at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:291) [tomcat-coyote.jar:6.0.32]
        at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:776) [tomcat-coyote.jar:6.0.32]
        at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:705) [tomcat-coyote.jar:6.0.32]
        at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:898) [tomcat-coyote.jar:6.0.32]
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) [tomcat-coyote.jar:6.0.32]
        at java.lang.Thread.run(Thread.java:662) [na:1.6.0_24]
Caused by: java.io.IOException: null
        at org.apache.jk.common.JkInputStream.receive(JkInputStream.java:205) ~[tomcat-coyote.jar:6.0.32]
        at org.apache.jk.common.JkInputStream.refillReadBuffer(JkInputStream.java:265) ~[tomcat-coyote.jar:6.0.32]
        at org.apache.jk.common.JkInputStream.doRead(JkInputStream.java:183) ~[tomcat-coyote.jar:6.0.32]
        at org.apache.coyote.Request.doRead(Request.java:428) ~[tomcat-coyote.jar:6.0.32]
        at org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:304) ~[catalina.jar:6.0.32]
        at org.apache.tomcat.util.buf.ByteChunk.substract(ByteChunk.java:403) ~[tomcat-coyote.jar:6.0.32]
        at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:327) ~[catalina.jar:6.0.32]
        at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:193) ~[catalina.jar:6.0.32]
        at org.apache.xerces.impl.XMLEntityManager$RewindableInputStream.read(Unknown Source) ~[na:na]
        at org.apache.xerces.impl.io.UTF8Reader.read(Unknown Source) ~[na:na]
        at org.apache.xerces.impl.XMLEntityScanner.load(Unknown Source) ~[na:na]
        at org.apache.xerces.impl.XMLEntityScanner.skipSpaces(Unknown Source) ~[na:na]
        at org.apache.xerces.impl.XMLDocumentScannerImpl$TrailingMiscDispatcher.dispatch(Unknown Source) ~[na:na]
        at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown Source) ~[na:na]
        at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source) ~[na:na]
        at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source) ~[na:na]
        at org.apache.xerces.parsers.XMLParser.parse(Unknown Source) ~[na:na]
        at org.apache.xerces.parsers.DOMParser.parse(Unknown Source) ~[na:na]
        at org.apache.xerces.jaxp.DocumentBuilderImpl.parse(Unknown Source) ~[na:na]
        at javax.xml.parsers.DocumentBuilder.parse(Unknown Source) ~[na:1.4.01]
        at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.java:671) ~[xmltooling-1.3.1.jar:na]
        at org.opensaml.xml.parse.BasicParserPool.parse(BasicParserPool.java:215) ~[xmltooling-1.3.1.jar:na]
        ... 34 common frames omitted
17:06:37.079 - DEBUG [edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler:256] - sending soap error: edu.internet2.middleware.shibboleth.common.profile.ProfileException: Error decoding authentication request message
17:06:36.765 - INFO [Shibboleth-Access:73] - 20120714T210636Z|157.56.244.37|idp.utorauth.utoronto.ca:443|/profile/SAML2/SOAP/ECP|
17:06:37.080 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/SOAP/ECP
17:06:37.080 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:96] - shibboleth.HandlerManager: Located profile handler of the following type for the request path: edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler
17:06:37.080 - DEBUG [edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler:291] - Decoding message with decoder binding 'urn:oasis:names:tc:SAML:2.0:bindings:SOAP'