[Shib-Users] Encountered error parsing message into its DOM representation

[Will David]

Hi,

I have a new idp installation (shibboleth idp 2.1.2, Tomcat 5.5.27, Apache
2.2 on Windows 2008) which I am trialing with a small group of users.  

I am intermittently getting errors in my idp log  (I have copied an
extract of the log below).   I have been trying to spot common factors
that might
be causing this error and have tried reproducing it but am unable to.

Has anyone else experienced this or have any clues what to look for?

Will


Here is the log extract:

07:56:43.605 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:200] -
Cached metadata is stale, refreshing
07:56:43.605 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:228] -
Refreshing cache of metadata from URL
http://metadata.ukfederation.org.uk/ukfederation-metadata.xml, max cache
duration set to 2880 seconds
07:56:43.605 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:271] -
Fetching metadata document from remote server
07:57:06.662 - INFO [Shibboleth-Access:72] -
20090731T065706Z|203.124.20.55|idp2.londonlibrary.co.uk:443|/profile/
SAML2/Redirect/SSO|
07:57:06.662 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager
:85] - shibboleth.HandlerManager: Looking up profile handler for request
path: /SAML2/Redirect/SSO
07:57:06.662 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager
:93] - shibboleth.HandlerManager: Located profile handler of the
following type for the request
path:edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler
07:57:06.662 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:
144] - Incoming request does not contain a login context, processing as
first leg of request
07:57:06.662 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:
288] - Decoding message with decoder binding
urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect 
07:57:06.662 - DEBUG
[org.opensaml.ws.message.decoder.BaseMessageDecoder:72] - Beginning to
decode message from inbound transport of type:
org.opensaml.ws.transport.http.HttpServletRequestAdapter
07:57:06.662 - DEBUG
[org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:93] -
Decoded RelayState: null
07:57:06.662 - DEBUG
[org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:130] -
 Base64 decoding and inflating SAML message
07:57:06.662 - DEBUG
[org.opensaml.ws.message.decoder.BaseMessageDecoder:140] - Parsing
message stream into DOM document
07:57:06.662 - ERROR
[org.opensaml.ws.message.decoder.BaseMessageDecoder:165] - Encountered
error parsing message into its DOM representation
org.opensaml.xml.parse.XMLParserException: Invalid XML
at
org.opensaml.xml.parse.BasicParserPool.parse(BasicParserPool.java:209)
[xmltooling-1.2.0.jar:na]
at
org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMe
ssageDecoder.java:143) [openws-1.2.2.jar:na]
at
org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTT
PRedirectDeflateDecoder.java:105) [opensaml-2.2.3.jar:na]
at
org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecode
r.java:74) [openws-1.2.2.jar:na]
at
org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML
2MessageDecoder.java:69) [opensaml-2.2.3.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.dec
odeRequest(SSOProfileHandler.java:306)
[shibboleth-identityprovider-2.1.2.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.per
formAuthentication(SSOProfileHandler.java:168)
[shibboleth-identityprovider-2.1.2.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.pro
cessRequest(SSOProfileHandler.java:145)
[shibboleth-identityprovider-2.1.2.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.pro
cessRequest(SSOProfileHandler.java:82)
[shibboleth-identityprovider-2.1.2.jar:na]
at
edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcher
Servlet.service(ProfileRequestDispatcherServlet.java:82)
[shibboleth-common-1.1.2.jar:na]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
[servlet-api.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Applicatio
nFilterChain.java:269) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterC
hain.java:188) [catalina.jar:na]
at
edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(I
dPSessionFilter.java:77) [shibboleth-identityprovider-2.1.2.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Applicatio
nFilterChain.java:215) [catalina.jar:na]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterC
hain.java:188) [catalina.jar:na]
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.j
ava:204) [catalina.jar:na]
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.j
ava:172) [catalina.jar:na]
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:12
7) [catalina.jar:na]
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:11
7) [catalina.jar:na]
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.jav
a:108) [catalina.jar:na]
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
[catalina.jar:na]
at
org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
[tomcat-ajp.jar:na]
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:283)
[tomcat-ajp.jar:na]
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:773)
[tomcat-ajp.jar:na]
at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:703
) [tomcat-ajp.jar:na]
at
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.j
ava:895) [tomcat-ajp.jar:na]
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.
java:689) [tomcat-util.jar:5.1]
at java.lang.Thread.run(Unknown Source) [na:1.6.0_13]
Caused by: org.xml.sax.SAXException: FWK005 parse may not be called while
parsing.
at org.apache.xerces.parsers.DOMParser.parse(Unknown Source)
[xercesImpl-2.9.1.jar:na]
at org.apache.xerces.jaxp.DocumentBuilderImpl.parse(Unknown Source)
[xercesImpl-2.9.1.jar:na]
at javax.xml.parsers.DocumentBuilder.parse(Unknown Source)
[na:1.6.0_13]
at
org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicPa
rserPool.java:602) [xmltooling-1.2.0.jar:na]
at
org.opensaml.xml.parse.BasicParserPool.parse(BasicParserPool.java:206)
[xmltooling-1.2.0.jar:na]
.. 28 common frames omitted

*******************************
Will David
The London Library
14 St James's Square
London
SW1Y 4LG
Telephone: 020 7766 4730 (direct line)
020 7930 7705 (main switchboard)
Email: will....@londonlibrary.co.uk 
Website: http://www.londonlibrary.co.uk 

[Chad La Joie]

The error means that the incoming (deflated and Base64 encoded) message
was corrupt. Is there any commonality between the SPs that cause this?
Or any of the browsers hitting the IdP?

> ... 28 common frames omitted

>
> *******************************
> Will David
> The London Library
> 14 St James's Square
> London
> SW1Y 4LG
> Telephone: 020 7766 4730 (direct line)
> 020 7930 7705 (main switchboard)
> Email: will....@londonlibrary.co.uk
> Website: http://www.londonlibrary.co.uk

--
SWITCH
Serving Swiss Universities
--------------------------
Chad La Joie, Software Engineer, Net Services
Werdstrasse 2, P.O. Box, 8021 Zürich, Switzerland
phone +41 44 268 15 75, fax +41 44 268 15 68
chad....@switch.ch, http://www.switch.ch

[Will David]

Chad,

Not that I can see.  This has happened with quite a number of different SPs (a different one for the last 4 occasions this has happened).

With browsers this seems to have occurred with IE users predominantly (most of my trial users are IE users) but I believe I have seen an instance where this has occurred with a non-IE browser.

At the moment I can't see any pattern at all.

Will

*******************************
Will David
The London Library
14 St James's Square
London
SW1Y 4LG
Telephone: 020 7766 4730 (direct line)
020 7930 7705 (main switchboard)
Email: will....@londonlibrary.co.uk
Website: http://www.londonlibrary.co.uk

[Scott Cantor]

> Not that I can see. This has happened with quite a number of different SPs
> (a different one for the last 4 occasions this has happened).

I noted in your log that RelayState was null. That's actually somewhat unusual for a Shib SP, so I think something's breaking the redirect. Do you have a sample from the web server log of the incoming requests?

-- Scott

[Will David]

Scott,

For the example I gave you in the original post this is the corresponding entries in the Apache access log:

91.135.1.25 - - [31/Jul/2009:07:56:43 +0100] "GET /idp/profile/Shibboleth/SSO?time=1249023402&dest=http://www.ukwhoswho.com&target=GUARD_-5f40189b--12255498e15---5f79&providerId=https://sp.sams.oup.com/shibboleth&shire=https://sp.sams.oup.com/samlengine/shibb/acs HTTP/1.1" 200 708
91.135.1.25 - - [31/Jul/2009:07:57:13 +0100] "GET /images/thelondonlibrary.gif HTTP/1.1" 200 4021
91.135.1.25 - - [31/Jul/2009:07:57:31 +0100] "GET /idp/profile/Shibboleth/SSO?time=1249023449&dest=http://www.ukwhoswho.com&target=GUARD_-5f40189b--12255498e15---5f78&providerId=https://sp.sams.oup.com/shibboleth&shire=https://sp.sams.oup.com/samlengine/shibb/acs HTTP/1.1" 302 -
91.135.1.25 - - [31/Jul/2009:07:58:10 +0100] "GET /idp/profile/Shibboleth/SSO?time=1249023488&dest=http://www.oxfordartonline.com/SHIBBOLETH/login.jsp?dest=http%3A%2F%2Fwww.oxfordartonline.com%2Fsubscriber&target=GUARD_-5f40189b--12255498e15---5f77&providerId=https://sp.sams.oup.com/shibboleth&shire=https://sp.sams.oup.com/samlengine/shibb/acs HTTP/1.1" 302 -
91.135.1.25 - - [31/Jul/2009:07:58:10 +0100] "GET /idp/Authn/UserPassword HTTP/1.1" 200 5224
91.135.1.25 - - [31/Jul/2009:07:58:10 +0100] "GET /css/londonlibrary1.css HTTP/1.1" 304 -
91.135.1.25 - - [31/Jul/2009:07:58:10 +0100] "GET /css/newtabs2.css HTTP/1.1" 304 -
91.135.1.25 - - [31/Jul/2009:07:58:19 +0100] "POST /idp/Authn/UserPassword HTTP/1.1" 200 8272
91.135.1.25 - - [31/Jul/2009:07:59:12 +0100] "GET /idp/profile/Shibboleth/SSO?time=1249023551&dest=http://www.ukwhoswho.com&target=GUARD_-5f40189b--12255498e15---5f75&providerId=https://sp.sams.oup.com/shibboleth&shire=https://sp.sams.oup.com/samlengine/shibb/acs HTTP/1.1" 302 -
91.135.1.25 - - [31/Jul/2009:07:59:12 +0100] "GET /idp/Authn/UserPassword HTTP/1.1" 200 5224
91.135.1.25 - - [31/Jul/2009:07:59:12 +0100] "GET /css/londonlibrary1.css HTTP/1.1" 304 -
91.135.1.25 - - [31/Jul/2009:07:59:12 +0100] "GET /css/newtabs2.css HTTP/1.1" 304 -
91.135.1.25 - - [31/Jul/2009:07:59:21 +0100] "POST /idp/Authn/UserPassword HTTP/1.1" 200 8272

Thanks.

Will

*******************************
Will David
The London Library
14 St James's Square
London
SW1Y 4LG
Telephone: 020 7766 4730 (direct line)
020 7930 7705 (main switchboard)
Email: will....@londonlibrary.co.uk
Website: http://www.londonlibrary.co.uk

-----Original Message-----

[Scott Cantor]

> For the example I gave you in the original post this is the corresponding
> entries in the Apache access log:

It's not Shibboleth on the other end, so that explains the lack of relay state. I don't see where XML is coming into it, those are legacy requests, no XML involved.

-- Scott