Shibboleth2 IdP load-test issue

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
13 messages Options
Reply | Threaded
Open this post in threaded view
|

Shibboleth2 IdP load-test issue

Adam Lantos-3
Hello,


I've performed some load-testing on our shib2 sp + shib2 idp (2.1.2)
setup. The test scenario was pretty straightforward: access some
protected resource at SP, then authenticate at IdP, and finally access
the resource again.

When more than five concurrent threads were active, the idp frequently
throwed SAXExceptions causing authnrequest to fail. Here is the
stacktrace from my idp-process.log:

11:23:49.393 ERROR
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:317]
- Error decoding
authentication request message
org.opensaml.ws.message.decoder.MessageDecodingException: Encountered
error parsing message into its DOM representation
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:166)
[open
ws-1.2.2.jar:na]
        at org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTTPRedirectDeflateDecoder.java
:105) [opensaml-2.2.3.jar:na]
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:74)
[openws-1.2.2.jar
:na]
        at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69)
[op
ensaml-2.2.3.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler
.java:306) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfil
eHandler.java:168) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
r.java:145) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
r.java:82) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileReque
stDispatcherServlet.java:82) [shibboleth-common-1.1.2.jar:na]

[...]

Caused by: 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(BaseMessageDecoder.java:143)
[openws-1.2.2.jar:na]
        ... 27 common frames omitted
Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
while parsing.
        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.3.04]
        at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.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


11:23:49.409 ERROR
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:415]
- Unable to unmarshall authentication request context
11:23:49.415 ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
- Error processing profile request
edu.internet2.middleware.shibboleth.common.profile.ProfileException:
Error recovering request state

11:23:49.422 WARN
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:255]
- No metadata for relying party null, treating party as anonymous
11:23:49.430 ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
- Error processing profile request
java.lang.NullPointerException
        at org.apache.xerces.parsers.AbstractDOMParser.endDocument(Unknown
Source) [na:na]


I presume the BasicParserPool synchronizing code fails here, and two
or more threads use the same DOMParser instance concurrently. But this
is only a guess, so please let me know what to investigate further.


thanks,
 Adam
Reply | Threaded
Open this post in threaded view
|

Re: Shibboleth2 IdP load-test issue

Chad La Joie
This issue is already in JIRA.  You can see that fix that some one
proposed for this.  I'm still unable to reproduce it but every time I
look at it I become more and more convinced that this is a threading
issue somewhere inside Xerces, the XML parser in use.

Adam Lantos wrote:

> Hello,
>
>
> I've performed some load-testing on our shib2 sp + shib2 idp (2.1.2)
> setup. The test scenario was pretty straightforward: access some
> protected resource at SP, then authenticate at IdP, and finally access
> the resource again.
>
> When more than five concurrent threads were active, the idp frequently
> throwed SAXExceptions causing authnrequest to fail. Here is the
> stacktrace from my idp-process.log:
>
> 11:23:49.393 ERROR
> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:317]
> - Error decoding
> authentication request message
> org.opensaml.ws.message.decoder.MessageDecodingException: Encountered
> error parsing message into its DOM representation
>         at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:166)
> [open
> ws-1.2.2.jar:na]
>         at org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTTPRedirectDeflateDecoder.java
> :105) [opensaml-2.2.3.jar:na]
>         at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:74)
> [openws-1.2.2.jar
> :na]
>         at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69)
> [op
> ensaml-2.2.3.jar:na]
>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler
> .java:306) [shibboleth-identityprovider-2.1.2.jar:na]
>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfil
> eHandler.java:168) [shibboleth-identityprovider-2.1.2.jar:na]
>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
> r.java:145) [shibboleth-identityprovider-2.1.2.jar:na]
>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
> r.java:82) [shibboleth-identityprovider-2.1.2.jar:na]
>         at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileReque
> stDispatcherServlet.java:82) [shibboleth-common-1.1.2.jar:na]
>
> [...]
>
> Caused by: 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(BaseMessageDecoder.java:143)
> [openws-1.2.2.jar:na]
>         ... 27 common frames omitted
> Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
> while parsing.
>         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.3.04]
>         at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.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
>
>
> 11:23:49.409 ERROR
> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:415]
> - Unable to unmarshall authentication request context
> 11:23:49.415 ERROR
> [edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
> - Error processing profile request
> edu.internet2.middleware.shibboleth.common.profile.ProfileException:
> Error recovering request state
>
> 11:23:49.422 WARN
> [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:255]
> - No metadata for relying party null, treating party as anonymous
> 11:23:49.430 ERROR
> [edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
> - Error processing profile request
> java.lang.NullPointerException
>         at org.apache.xerces.parsers.AbstractDOMParser.endDocument(Unknown
> Source) [na:na]
>
>
> I presume the BasicParserPool synchronizing code fails here, and two
> or more threads use the same DOMParser instance concurrently. But this
> is only a guess, so please let me know what to investigate further.
>
>
> thanks,
>  Adam

--
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
[hidden email], http://www.switch.ch

Reply | Threaded
Open this post in threaded view
|

Re: Shibboleth2 IdP load-test issue

Adam Lantos-3
Hello Chad,

Unfortunately Xerces Javadoc is not too helpful with this case, but
the Xerces-J FAQ at http://xerces.apache.org/xerces2-j/faq-dom.html
states that the Xerces dom implementation is _not_ thread-safe, so
external synchronizing is needed.

I think Shibboleth doesn't want to use the same domparser
implementation in two separate threads, because each thread processes
separate requests, so each thread needs its own domparser instance. If
I get it right, it's the ParserPool's responsibility to ensure the
one-parser-per-request need.


On Mon, Feb 9, 2009 at 12:32 PM, Chad La Joie <[hidden email]> wrote:

> This issue is already in JIRA.  You can see that fix that some one
> proposed for this.  I'm still unable to reproduce it but every time I
> look at it I become more and more convinced that this is a threading
> issue somewhere inside Xerces, the XML parser in use.
>
> Adam Lantos wrote:
>> Hello,
>>
>>
>> I've performed some load-testing on our shib2 sp + shib2 idp (2.1.2)
>> setup. The test scenario was pretty straightforward: access some
>> protected resource at SP, then authenticate at IdP, and finally access
>> the resource again.
>>
>> When more than five concurrent threads were active, the idp frequently
>> throwed SAXExceptions causing authnrequest to fail. Here is the
>> stacktrace from my idp-process.log:
>>
>> 11:23:49.393 ERROR
>> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:317]
>> - Error decoding
>> authentication request message
>> org.opensaml.ws.message.decoder.MessageDecodingException: Encountered
>> error parsing message into its DOM representation
>>         at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:166)
>> [open
>> ws-1.2.2.jar:na]
>>         at org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTTPRedirectDeflateDecoder.java
>> :105) [opensaml-2.2.3.jar:na]
>>         at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:74)
>> [openws-1.2.2.jar
>> :na]
>>         at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69)
>> [op
>> ensaml-2.2.3.jar:na]
>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler
>> .java:306) [shibboleth-identityprovider-2.1.2.jar:na]
>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfil
>> eHandler.java:168) [shibboleth-identityprovider-2.1.2.jar:na]
>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
>> r.java:145) [shibboleth-identityprovider-2.1.2.jar:na]
>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
>> r.java:82) [shibboleth-identityprovider-2.1.2.jar:na]
>>         at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileReque
>> stDispatcherServlet.java:82) [shibboleth-common-1.1.2.jar:na]
>>
>> [...]
>>
>> Caused by: 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(BaseMessageDecoder.java:143)
>> [openws-1.2.2.jar:na]
>>         ... 27 common frames omitted
>> Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
>> while parsing.
>>         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.3.04]
>>         at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.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
>>
>>
>> 11:23:49.409 ERROR
>> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:415]
>> - Unable to unmarshall authentication request context
>> 11:23:49.415 ERROR
>> [edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
>> - Error processing profile request
>> edu.internet2.middleware.shibboleth.common.profile.ProfileException:
>> Error recovering request state
>>
>> 11:23:49.422 WARN
>> [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:255]
>> - No metadata for relying party null, treating party as anonymous
>> 11:23:49.430 ERROR
>> [edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
>> - Error processing profile request
>> java.lang.NullPointerException
>>         at org.apache.xerces.parsers.AbstractDOMParser.endDocument(Unknown
>> Source) [na:na]
>>
>>
>> I presume the BasicParserPool synchronizing code fails here, and two
>> or more threads use the same DOMParser instance concurrently. But this
>> is only a guess, so please let me know what to investigate further.
>>
>>
>> thanks,
>>  Adam
>
> --
> 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
> [hidden email], http://www.switch.ch
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Shibboleth2 IdP load-test issue

Chad La Joie
It's not supposed to be using the same one.  It seems to be some sort of
issue with Xerces's parser factory which is supposed to be thread safe.

Either way, it's a know a bug, one of the reporters suggested a fix that
another has reported fixes the problem.  However, until I can figure out
what is wrong (or until more people report the problem), reproduce the
problem, and test the fix, I'm not willing to apply it to the main code
branch.

Adam Lantos wrote:

> Hello Chad,
>
> Unfortunately Xerces Javadoc is not too helpful with this case, but
> the Xerces-J FAQ at http://xerces.apache.org/xerces2-j/faq-dom.html
> states that the Xerces dom implementation is _not_ thread-safe, so
> external synchronizing is needed.
>
> I think Shibboleth doesn't want to use the same domparser
> implementation in two separate threads, because each thread processes
> separate requests, so each thread needs its own domparser instance. If
> I get it right, it's the ParserPool's responsibility to ensure the
> one-parser-per-request need.
>
>
> On Mon, Feb 9, 2009 at 12:32 PM, Chad La Joie <[hidden email]> wrote:
>> This issue is already in JIRA.  You can see that fix that some one
>> proposed for this.  I'm still unable to reproduce it but every time I
>> look at it I become more and more convinced that this is a threading
>> issue somewhere inside Xerces, the XML parser in use.
>>
>> Adam Lantos wrote:
>>> Hello,
>>>
>>>
>>> I've performed some load-testing on our shib2 sp + shib2 idp (2.1.2)
>>> setup. The test scenario was pretty straightforward: access some
>>> protected resource at SP, then authenticate at IdP, and finally access
>>> the resource again.
>>>
>>> When more than five concurrent threads were active, the idp frequently
>>> throwed SAXExceptions causing authnrequest to fail. Here is the
>>> stacktrace from my idp-process.log:
>>>
>>> 11:23:49.393 ERROR
>>> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:317]
>>> - Error decoding
>>> authentication request message
>>> org.opensaml.ws.message.decoder.MessageDecodingException: Encountered
>>> error parsing message into its DOM representation
>>>         at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:166)
>>> [open
>>> ws-1.2.2.jar:na]
>>>         at org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTTPRedirectDeflateDecoder.java
>>> :105) [opensaml-2.2.3.jar:na]
>>>         at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:74)
>>> [openws-1.2.2.jar
>>> :na]
>>>         at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69)
>>> [op
>>> ensaml-2.2.3.jar:na]
>>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler
>>> .java:306) [shibboleth-identityprovider-2.1.2.jar:na]
>>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfil
>>> eHandler.java:168) [shibboleth-identityprovider-2.1.2.jar:na]
>>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
>>> r.java:145) [shibboleth-identityprovider-2.1.2.jar:na]
>>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
>>> r.java:82) [shibboleth-identityprovider-2.1.2.jar:na]
>>>         at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileReque
>>> stDispatcherServlet.java:82) [shibboleth-common-1.1.2.jar:na]
>>>
>>> [...]
>>>
>>> Caused by: 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(BaseMessageDecoder.java:143)
>>> [openws-1.2.2.jar:na]
>>>         ... 27 common frames omitted
>>> Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
>>> while parsing.
>>>         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.3.04]
>>>         at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.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
>>>
>>>
>>> 11:23:49.409 ERROR
>>> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:415]
>>> - Unable to unmarshall authentication request context
>>> 11:23:49.415 ERROR
>>> [edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
>>> - Error processing profile request
>>> edu.internet2.middleware.shibboleth.common.profile.ProfileException:
>>> Error recovering request state
>>>
>>> 11:23:49.422 WARN
>>> [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:255]
>>> - No metadata for relying party null, treating party as anonymous
>>> 11:23:49.430 ERROR
>>> [edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
>>> - Error processing profile request
>>> java.lang.NullPointerException
>>>         at org.apache.xerces.parsers.AbstractDOMParser.endDocument(Unknown
>>> Source) [na:na]
>>>
>>>
>>> I presume the BasicParserPool synchronizing code fails here, and two
>>> or more threads use the same DOMParser instance concurrently. But this
>>> is only a guess, so please let me know what to investigate further.
>>>
>>>
>>> thanks,
>>>  Adam
>> --
>> 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
>> [hidden email], http://www.switch.ch
>>
>>

--
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
[hidden email], http://www.switch.ch

Reply | Threaded
Open this post in threaded view
|

Re: Shibboleth2 IdP load-test issue

Adam Lantos-3
I think I've figured it out:

The DocumentBuilderProxy.finalize() method calls
owningPool.returnBuilder(this); which duplicates the
documentbuilderproxy instance in the pool, as BasicParserPool.parse()
also returns the builder on its finally() path. I commented out the
DocumentBuilderProxy.finalize() method, then the issue disappeared.


--
 Adam


On Mon, Feb 9, 2009 at 1:03 PM, Chad La Joie <[hidden email]> wrote:

> It's not supposed to be using the same one.  It seems to be some sort of
> issue with Xerces's parser factory which is supposed to be thread safe.
>
> Either way, it's a know a bug, one of the reporters suggested a fix that
> another has reported fixes the problem.  However, until I can figure out
> what is wrong (or until more people report the problem), reproduce the
> problem, and test the fix, I'm not willing to apply it to the main code
> branch.
>
> Adam Lantos wrote:
>> Hello Chad,
>>
>> Unfortunately Xerces Javadoc is not too helpful with this case, but
>> the Xerces-J FAQ at http://xerces.apache.org/xerces2-j/faq-dom.html
>> states that the Xerces dom implementation is _not_ thread-safe, so
>> external synchronizing is needed.
>>
>> I think Shibboleth doesn't want to use the same domparser
>> implementation in two separate threads, because each thread processes
>> separate requests, so each thread needs its own domparser instance. If
>> I get it right, it's the ParserPool's responsibility to ensure the
>> one-parser-per-request need.
>>
>>
>> On Mon, Feb 9, 2009 at 12:32 PM, Chad La Joie <[hidden email]> wrote:
>>> This issue is already in JIRA.  You can see that fix that some one
>>> proposed for this.  I'm still unable to reproduce it but every time I
>>> look at it I become more and more convinced that this is a threading
>>> issue somewhere inside Xerces, the XML parser in use.
>>>
>>> Adam Lantos wrote:
>>>> Hello,
>>>>
>>>>
>>>> I've performed some load-testing on our shib2 sp + shib2 idp (2.1.2)
>>>> setup. The test scenario was pretty straightforward: access some
>>>> protected resource at SP, then authenticate at IdP, and finally access
>>>> the resource again.
>>>>
>>>> When more than five concurrent threads were active, the idp frequently
>>>> throwed SAXExceptions causing authnrequest to fail. Here is the
>>>> stacktrace from my idp-process.log:
>>>>
>>>> 11:23:49.393 ERROR
>>>> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:317]
>>>> - Error decoding
>>>> authentication request message
>>>> org.opensaml.ws.message.decoder.MessageDecodingException: Encountered
>>>> error parsing message into its DOM representation
>>>>         at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:166)
>>>> [open
>>>> ws-1.2.2.jar:na]
>>>>         at org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTTPRedirectDeflateDecoder.java
>>>> :105) [opensaml-2.2.3.jar:na]
>>>>         at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:74)
>>>> [openws-1.2.2.jar
>>>> :na]
>>>>         at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69)
>>>> [op
>>>> ensaml-2.2.3.jar:na]
>>>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler
>>>> .java:306) [shibboleth-identityprovider-2.1.2.jar:na]
>>>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfil
>>>> eHandler.java:168) [shibboleth-identityprovider-2.1.2.jar:na]
>>>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
>>>> r.java:145) [shibboleth-identityprovider-2.1.2.jar:na]
>>>>         at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
>>>> r.java:82) [shibboleth-identityprovider-2.1.2.jar:na]
>>>>         at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileReque
>>>> stDispatcherServlet.java:82) [shibboleth-common-1.1.2.jar:na]
>>>>
>>>> [...]
>>>>
>>>> Caused by: 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(BaseMessageDecoder.java:143)
>>>> [openws-1.2.2.jar:na]
>>>>         ... 27 common frames omitted
>>>> Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
>>>> while parsing.
>>>>         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.3.04]
>>>>         at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.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
>>>>
>>>>
>>>> 11:23:49.409 ERROR
>>>> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:415]
>>>> - Unable to unmarshall authentication request context
>>>> 11:23:49.415 ERROR
>>>> [edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
>>>> - Error processing profile request
>>>> edu.internet2.middleware.shibboleth.common.profile.ProfileException:
>>>> Error recovering request state
>>>>
>>>> 11:23:49.422 WARN
>>>> [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:255]
>>>> - No metadata for relying party null, treating party as anonymous
>>>> 11:23:49.430 ERROR
>>>> [edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
>>>> - Error processing profile request
>>>> java.lang.NullPointerException
>>>>         at org.apache.xerces.parsers.AbstractDOMParser.endDocument(Unknown
>>>> Source) [na:na]
>>>>
>>>>
>>>> I presume the BasicParserPool synchronizing code fails here, and two
>>>> or more threads use the same DOMParser instance concurrently. But this
>>>> is only a guess, so please let me know what to investigate further.
>>>>
>>>>
>>>> thanks,
>>>>  Adam
>>> --
>>> 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
>>> [hidden email], http://www.switch.ch
>>>
>>>
>
> --
> 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
> [hidden email], http://www.switch.ch
>
>
Reply | Threaded
Open this post in threaded view
|

RE: Shibboleth2 IdP load-test issue

Cantor, Scott E.
Adam Lantos wrote on 2009-02-09:
> I think I've figured it out:

It would be helpful if you filed that suggested fix in the Jira entry so it gets considered when the bug is addressed.

-- Scott


Reply | Threaded
Open this post in threaded view
|

Re: Shibboleth2 IdP load-test issue

Adam Lantos-3
In reply to this post by Adam Lantos-3
Sure, I posted my patch.

--
 Adam


On Mon, Feb 9, 2009 at 6:56 PM, Scott Cantor <[hidden email]> wrote:
> Adam Lantos wrote on 2009-02-09:
>> I think I've figured it out:
>
> It would be helpful if you filed that suggested fix in the Jira entry so it gets considered when the bug is addressed.
>
> -- Scott
>
>
>
Reply | Threaded
Open this post in threaded view
|

RE: Shibboleth2 IdP load-test issue

Mark Southam
In reply to this post by Adam Lantos-3
I can confirm that I am also getting this error in load tests.

-----Original Message-----
From: [hidden email] [mailto:[hidden email]] On Behalf Of Adam Lantos
Sent: 09 February 2009 11:30
To: [hidden email]
Subject: [Shib-Users] Shibboleth2 IdP load-test issue

Hello,


I've performed some load-testing on our shib2 sp + shib2 idp (2.1.2)
setup. The test scenario was pretty straightforward: access some
protected resource at SP, then authenticate at IdP, and finally access
the resource again.

When more than five concurrent threads were active, the idp frequently
throwed SAXExceptions causing authnrequest to fail. Here is the
stacktrace from my idp-process.log:

11:23:49.393 ERROR
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:317]
- Error decoding
authentication request message
org.opensaml.ws.message.decoder.MessageDecodingException: Encountered
error parsing message into its DOM representation
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:166)
[open
ws-1.2.2.jar:na]
        at org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTTPRedirectDeflateDecoder.java
:105) [opensaml-2.2.3.jar:na]
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:74)
[openws-1.2.2.jar
:na]
        at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69)
[op
ensaml-2.2.3.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler
.java:306) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfil
eHandler.java:168) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
r.java:145) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
r.java:82) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileReque
stDispatcherServlet.java:82) [shibboleth-common-1.1.2.jar:na]

[...]

Caused by: 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(BaseMessageDecoder.java:143)
[openws-1.2.2.jar:na]
        ... 27 common frames omitted
Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
while parsing.
        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.3.04]
        at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.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


11:23:49.409 ERROR
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:415]
- Unable to unmarshall authentication request context
11:23:49.415 ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
- Error processing profile request
edu.internet2.middleware.shibboleth.common.profile.ProfileException:
Error recovering request state

11:23:49.422 WARN
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:255]
- No metadata for relying party null, treating party as anonymous
11:23:49.430 ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
- Error processing profile request
java.lang.NullPointerException
        at org.apache.xerces.parsers.AbstractDOMParser.endDocument(Unknown
Source) [na:na]


I presume the BasicParserPool synchronizing code fails here, and two
or more threads use the same DOMParser instance concurrently. But this
is only a guess, so please let me know what to investigate further.


thanks,
 Adam
______________________________________________________________________

You might be interested in this...

Schools and Colleges for the Future
Find out more about the programmes shaping education for the future.
http://www.rm.com/futureeducation

______________________________________________________________________

P.S. Think Green - don't print this email unless you really need to.


This message is confidential, so please treat it appropriately and for its intended purpose only.  In particular, if it refers to any technical data, terms or prices not generally available or known, such items are "commercially sensitive information" within the terms of the Freedom of Information Act 2000 and related laws.  As it would be prejudicial to RM's commercial interests if these were disclosed, please refrain from doing so.

 

As Internet communications are not secure, please be aware that RM cannot accept responsibility for its contents.  Any views or opinions presented are those of the author only and not of RM.  If you are not the intended recipient of this e-mail, please accept our apologies and arrange for copies of it to be deleted.  For your information, RM may intercept incoming and outgoing email communications.

 

RM Education plc
Registered Office: New Mill House, 183 Milton Park, Abingdon, Oxfordshire, OX14 4SE, England
Registered Number: 1148594

Reply | Threaded
Open this post in threaded view
|

Re: Shibboleth2 IdP load-test issue

Adam Lantos-3
Mark,

Try this patch with xmltooling-1.2.0, it solved the parser threading
issue for me:

https://bugs.internet2.edu/jira/secure/attachment/10215/remove_finalizer_from_documentbuilderproxy.patch


thanks,
 Adam


On Mon, Feb 23, 2009 at 12:45 PM, Mark Southam <[hidden email]> wrote:

> I can confirm that I am also getting this error in load tests.
>
> -----Original Message-----
> From: [hidden email] [mailto:[hidden email]] On Behalf Of Adam Lantos
> Sent: 09 February 2009 11:30
> To: [hidden email]
> Subject: [Shib-Users] Shibboleth2 IdP load-test issue
>
> Hello,
>
>
> I've performed some load-testing on our shib2 sp + shib2 idp (2.1.2)
> setup. The test scenario was pretty straightforward: access some
> protected resource at SP, then authenticate at IdP, and finally access
> the resource again.
>
> When more than five concurrent threads were active, the idp frequently
> throwed SAXExceptions causing authnrequest to fail. Here is the
> stacktrace from my idp-process.log:
>
> 11:23:49.393 ERROR
> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:317]
> - Error decoding
> authentication request message
> org.opensaml.ws.message.decoder.MessageDecodingException: Encountered
> error parsing message into its DOM representation
>        at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:166)
> [open
> ws-1.2.2.jar:na]
>        at org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTTPRedirectDeflateDecoder.java
> :105) [opensaml-2.2.3.jar:na]
>        at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:74)
> [openws-1.2.2.jar
> :na]
>        at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69)
> [op
> ensaml-2.2.3.jar:na]
>        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler
> .java:306) [shibboleth-identityprovider-2.1.2.jar:na]
>        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfil
> eHandler.java:168) [shibboleth-identityprovider-2.1.2.jar:na]
>        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
> r.java:145) [shibboleth-identityprovider-2.1.2.jar:na]
>        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
> r.java:82) [shibboleth-identityprovider-2.1.2.jar:na]
>        at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileReque
> stDispatcherServlet.java:82) [shibboleth-common-1.1.2.jar:na]
>
> [...]
>
> Caused by: 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(BaseMessageDecoder.java:143)
> [openws-1.2.2.jar:na]
>        ... 27 common frames omitted
> Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
> while parsing.
>        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.3.04]
>        at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.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
>
>
> 11:23:49.409 ERROR
> [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:415]
> - Unable to unmarshall authentication request context
> 11:23:49.415 ERROR
> [edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
> - Error processing profile request
> edu.internet2.middleware.shibboleth.common.profile.ProfileException:
> Error recovering request state
>
> 11:23:49.422 WARN
> [edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:255]
> - No metadata for relying party null, treating party as anonymous
> 11:23:49.430 ERROR
> [edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
> - Error processing profile request
> java.lang.NullPointerException
>        at org.apache.xerces.parsers.AbstractDOMParser.endDocument(Unknown
> Source) [na:na]
>
>
> I presume the BasicParserPool synchronizing code fails here, and two
> or more threads use the same DOMParser instance concurrently. But this
> is only a guess, so please let me know what to investigate further.
>
>
> thanks,
>  Adam
> ______________________________________________________________________
>
> You might be interested in this...
>
> Schools and Colleges for the Future
> Find out more about the programmes shaping education for the future.
> http://www.rm.com/futureeducation
>
> ______________________________________________________________________
>
> P.S. Think Green - don't print this email unless you really need to.
>
>
> This message is confidential, so please treat it appropriately and for its intended purpose only.  In particular, if it refers to any technical data, terms or prices not generally available or known, such items are "commercially sensitive information" within the terms of the Freedom of Information Act 2000 and related laws.  As it would be prejudicial to RM's commercial interests if these were disclosed, please refrain from doing so.
>
>
>
> As Internet communications are not secure, please be aware that RM cannot accept responsibility for its contents.  Any views or opinions presented are those of the author only and not of RM.  If you are not the intended recipient of this e-mail, please accept our apologies and arrange for copies of it to be deleted.  For your information, RM may intercept incoming and outgoing email communications.
>
>
>
> RM Education plc
> Registered Office: New Mill House, 183 Milton Park, Abingdon, Oxfordshire, OX14 4SE, England
> Registered Number: 1148594
>
>
Reply | Threaded
Open this post in threaded view
|

RE: Shibboleth2 IdP load-test issue

Mark Southam
In reply to this post by Adam Lantos-3
My versions: sp 2.1 win64 and idp 2.1.2

-----Original Message-----
From: [hidden email] [mailto:[hidden email]] On Behalf Of Adam Lantos
Sent: 09 February 2009 11:30
To: [hidden email]
Subject: [Shib-Users] Shibboleth2 IdP load-test issue

Hello,


I've performed some load-testing on our shib2 sp + shib2 idp (2.1.2)
setup. The test scenario was pretty straightforward: access some
protected resource at SP, then authenticate at IdP, and finally access
the resource again.

When more than five concurrent threads were active, the idp frequently
throwed SAXExceptions causing authnrequest to fail. Here is the
stacktrace from my idp-process.log:

11:23:49.393 ERROR
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:317]
- Error decoding
authentication request message
org.opensaml.ws.message.decoder.MessageDecodingException: Encountered
error parsing message into its DOM representation
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:166)
[open
ws-1.2.2.jar:na]
        at org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTTPRedirectDeflateDecoder.java
:105) [opensaml-2.2.3.jar:na]
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:74)
[openws-1.2.2.jar
:na]
        at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69)
[op
ensaml-2.2.3.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler
.java:306) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfil
eHandler.java:168) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
r.java:145) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
r.java:82) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileReque
stDispatcherServlet.java:82) [shibboleth-common-1.1.2.jar:na]

[...]

Caused by: 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(BaseMessageDecoder.java:143)
[openws-1.2.2.jar:na]
        ... 27 common frames omitted
Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
while parsing.
        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.3.04]
        at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.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


11:23:49.409 ERROR
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:415]
- Unable to unmarshall authentication request context
11:23:49.415 ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
- Error processing profile request
edu.internet2.middleware.shibboleth.common.profile.ProfileException:
Error recovering request state

11:23:49.422 WARN
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:255]
- No metadata for relying party null, treating party as anonymous
11:23:49.430 ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
- Error processing profile request
java.lang.NullPointerException
        at org.apache.xerces.parsers.AbstractDOMParser.endDocument(Unknown
Source) [na:na]


I presume the BasicParserPool synchronizing code fails here, and two
or more threads use the same DOMParser instance concurrently. But this
is only a guess, so please let me know what to investigate further.


thanks,
 Adam
______________________________________________________________________

You might be interested in this...

Schools and Colleges for the Future
Find out more about the programmes shaping education for the future.
http://www.rm.com/futureeducation

______________________________________________________________________

P.S. Think Green - don't print this email unless you really need to.


This message is confidential, so please treat it appropriately and for its intended purpose only.  In particular, if it refers to any technical data, terms or prices not generally available or known, such items are "commercially sensitive information" within the terms of the Freedom of Information Act 2000 and related laws.  As it would be prejudicial to RM's commercial interests if these were disclosed, please refrain from doing so.

 

As Internet communications are not secure, please be aware that RM cannot accept responsibility for its contents.  Any views or opinions presented are those of the author only and not of RM.  If you are not the intended recipient of this e-mail, please accept our apologies and arrange for copies of it to be deleted.  For your information, RM may intercept incoming and outgoing email communications.

 

RM Education plc
Registered Office: New Mill House, 183 Milton Park, Abingdon, Oxfordshire, OX14 4SE, England
Registered Number: 1148594

Reply | Threaded
Open this post in threaded view
|

RE: Shibboleth2 IdP load-test issue

Mark Southam
In reply to this post by Adam Lantos-3
Thanks Adam - will do

-----Original Message-----
From: [hidden email] [mailto:[hidden email]] On Behalf Of Adam Lantos
Sent: 09 February 2009 11:30
To: [hidden email]
Subject: [Shib-Users] Shibboleth2 IdP load-test issue

Hello,


I've performed some load-testing on our shib2 sp + shib2 idp (2.1.2)
setup. The test scenario was pretty straightforward: access some
protected resource at SP, then authenticate at IdP, and finally access
the resource again.

When more than five concurrent threads were active, the idp frequently
throwed SAXExceptions causing authnrequest to fail. Here is the
stacktrace from my idp-process.log:

11:23:49.393 ERROR
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:317]
- Error decoding
authentication request message
org.opensaml.ws.message.decoder.MessageDecodingException: Encountered
error parsing message into its DOM representation
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:166)
[open
ws-1.2.2.jar:na]
        at org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTTPRedirectDeflateDecoder.java
:105) [opensaml-2.2.3.jar:na]
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:74)
[openws-1.2.2.jar
:na]
        at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69)
[op
ensaml-2.2.3.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler
.java:306) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfil
eHandler.java:168) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
r.java:145) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
r.java:82) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileReque
stDispatcherServlet.java:82) [shibboleth-common-1.1.2.jar:na]

[...]

Caused by: 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(BaseMessageDecoder.java:143)
[openws-1.2.2.jar:na]
        ... 27 common frames omitted
Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
while parsing.
        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.3.04]
        at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.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


11:23:49.409 ERROR
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:415]
- Unable to unmarshall authentication request context
11:23:49.415 ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
- Error processing profile request
edu.internet2.middleware.shibboleth.common.profile.ProfileException:
Error recovering request state

11:23:49.422 WARN
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:255]
- No metadata for relying party null, treating party as anonymous
11:23:49.430 ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
- Error processing profile request
java.lang.NullPointerException
        at org.apache.xerces.parsers.AbstractDOMParser.endDocument(Unknown
Source) [na:na]


I presume the BasicParserPool synchronizing code fails here, and two
or more threads use the same DOMParser instance concurrently. But this
is only a guess, so please let me know what to investigate further.


thanks,
 Adam
______________________________________________________________________

You might be interested in this...

Schools and Colleges for the Future
Find out more about the programmes shaping education for the future.
http://www.rm.com/futureeducation

______________________________________________________________________

P.S. Think Green - don't print this email unless you really need to.


This message is confidential, so please treat it appropriately and for its intended purpose only.  In particular, if it refers to any technical data, terms or prices not generally available or known, such items are "commercially sensitive information" within the terms of the Freedom of Information Act 2000 and related laws.  As it would be prejudicial to RM's commercial interests if these were disclosed, please refrain from doing so.

 

As Internet communications are not secure, please be aware that RM cannot accept responsibility for its contents.  Any views or opinions presented are those of the author only and not of RM.  If you are not the intended recipient of this e-mail, please accept our apologies and arrange for copies of it to be deleted.  For your information, RM may intercept incoming and outgoing email communications.

 

RM Education plc
Registered Office: New Mill House, 183 Milton Park, Abingdon, Oxfordshire, OX14 4SE, England
Registered Number: 1148594

Reply | Threaded
Open this post in threaded view
|

Re: Shibboleth2 IdP load-test issue

Brent Putman
In reply to this post by Adam Lantos-3
Just FYI, I have checked in a fix for this issue to java-xmltooling.
The actual change is different than Adam's patch, for reasons outlined
in the Jira issue.

https://bugs.internet2.edu/jira/browse/JXT-46


If anyone who has been doing load-testing and has seen this,  has an
inclination test this fix prior to our next release, that would be
greatly appreciated.

Many thanks to Adam for helping us finally identify and squash this bug.


--Brent


Adam Lantos wrote:

> Mark,
>
> Try this patch with xmltooling-1.2.0, it solved the parser threading
> issue for me:
>
> https://bugs.internet2.edu/jira/secure/attachment/10215/remove_finalizer_from_documentbuilderproxy.patch
>
>
> thanks,
>  Adam
>
>
> On Mon, Feb 23, 2009 at 12:45 PM, Mark Southam <[hidden email]> wrote:
>  
>> Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
>>
>>    
Reply | Threaded
Open this post in threaded view
|

RE: Shibboleth2 IdP load-test issue

Mark Southam
In reply to this post by Adam Lantos-3
Hi Brent,

I can confirm, your patch does fix the problem.

Regards,
Mark

-----Original Message-----
From: [hidden email] [mailto:[hidden email]] On Behalf Of Adam Lantos
Sent: 09 February 2009 11:30
To: [hidden email]
Subject: [Shib-Users] Shibboleth2 IdP load-test issue

Hello,


I've performed some load-testing on our shib2 sp + shib2 idp (2.1.2)
setup. The test scenario was pretty straightforward: access some
protected resource at SP, then authenticate at IdP, and finally access
the resource again.

When more than five concurrent threads were active, the idp frequently
throwed SAXExceptions causing authnrequest to fail. Here is the
stacktrace from my idp-process.log:

11:23:49.393 ERROR
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:317]
- Error decoding
authentication request message
org.opensaml.ws.message.decoder.MessageDecodingException: Encountered
error parsing message into its DOM representation
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.unmarshallMessage(BaseMessageDecoder.java:166)
[open
ws-1.2.2.jar:na]
        at org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder.doDecode(HTTPRedirectDeflateDecoder.java
:105) [opensaml-2.2.3.jar:na]
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:74)
[openws-1.2.2.jar
:na]
        at org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML2MessageDecoder.java:69)
[op
ensaml-2.2.3.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.decodeRequest(SSOProfileHandler
.java:306) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.performAuthentication(SSOProfil
eHandler.java:168) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
r.java:145) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.processRequest(SSOProfileHandle
r.java:82) [shibboleth-identityprovider-2.1.2.jar:na]
        at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileReque
stDispatcherServlet.java:82) [shibboleth-common-1.1.2.jar:na]

[...]

Caused by: 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(BaseMessageDecoder.java:143)
[openws-1.2.2.jar:na]
        ... 27 common frames omitted
Caused by: org.xml.sax.SAXException: FWK005 parse may not be called
while parsing.
        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.3.04]
        at org.opensaml.xml.parse.BasicParserPool$DocumentBuilderProxy.parse(BasicParserPool.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


11:23:49.409 ERROR
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:415]
- Unable to unmarshall authentication request context
11:23:49.415 ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
- Error processing profile request
edu.internet2.middleware.shibboleth.common.profile.ProfileException:
Error recovering request state

11:23:49.422 WARN
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:255]
- No metadata for relying party null, treating party as anonymous
11:23:49.430 ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:85]
- Error processing profile request
java.lang.NullPointerException
        at org.apache.xerces.parsers.AbstractDOMParser.endDocument(Unknown
Source) [na:na]


I presume the BasicParserPool synchronizing code fails here, and two
or more threads use the same DOMParser instance concurrently. But this
is only a guess, so please let me know what to investigate further.


thanks,
 Adam
______________________________________________________________________

You might be interested in this...

Schools and Colleges for the Future
Find out more about the programmes shaping education for the future.
http://www.rm.com/futureeducation

______________________________________________________________________

P.S. Think Green - don't print this email unless you really need to.


This message is confidential, so please treat it appropriately and for its intended purpose only.  In particular, if it refers to any technical data, terms or prices not generally available or known, such items are "commercially sensitive information" within the terms of the Freedom of Information Act 2000 and related laws.  As it would be prejudicial to RM's commercial interests if these were disclosed, please refrain from doing so.

 

As Internet communications are not secure, please be aware that RM cannot accept responsibility for its contents.  Any views or opinions presented are those of the author only and not of RM.  If you are not the intended recipient of this e-mail, please accept our apologies and arrange for copies of it to be deleted.  For your information, RM may intercept incoming and outgoing email communications.

 

RM Education plc
Registered Office: New Mill House, 183 Milton Park, Abingdon, Oxfordshire, OX14 4SE, England
Registered Number: 1148594