exception during IsPassive login

[Paul Hethmon]

I'm running Shib 2.3.6 as a base and have recently noticed a problem with
passive authentication support. This is occurring when there is not a
session for the user and an AuthnRequest comes in with IsPassive set to
true. The sequence I'm seeing is my login handler is called, I detect the
passive request without a session, I set the
PassiveAuthenticationException error in the HttpRequest object and return
control to the AuthenticationEngine. It then goes through what I consider
normal stuff, noticing the exception, removing the login context, etc. But
then it sends the request back to the handler which then thinks it's a new
request (user not authenticated). At that point, there is no AuthnRequest,
so you end up with the "error decoding authentication request message"
error.

Log and stack trace:

09:40:33.620 - INFO
[com.clareity.jaguar.shibboleth.authn.ClareityLoginHandler:260] - Passive
authentication requested without a valid SSO session. Returning SAML error
to SP [http
://www.narrpr.com]
09:40:33.621 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:144] -
Returning control to authentication engine
09:40:33.635 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] -
Processing incoming request
09:40:33.635 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:514] -
Completing user authentication process
09:40:33.635 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:585] -
Validating authentication was performed successfully
09:40:33.635 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:605] -
Exception returned from login handler for authentication method
urn:oasis:names:tc:S
AML:2.0:ac:classes:Password:
edu.internet2.middleware.shibboleth.idp.authn.PassiveAuthenticationExceptio
n: Passive authentication not supported without a previous session.
09:40:33.636 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:161] -
Returning control to profile handler
09:40:33.636 - DEBUG
[edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:177] -
Redirecting user to profile handler at
http://idp.stwmls.safemls.net:80/idp/profile/
SAML2/POST/SSO
09:40:33.707 - INFO [Shibboleth-Access:74] -
20130219T144033Z|127.0.0.1|idp.stwmls.safemls.net:80|/profile/SAML2/POST/SS
O|
09:40:33.708 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:8
6] - shibboleth.HandlerManager: Looking up profile handler for request
path: /SAML2/
POST/SSO
09:40:33.708 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:9
7] - shibboleth.HandlerManager: Located profile handler of the following
type for th
e request path: 
edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler
09:40:33.708 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:574] -
Unbinding LoginContext
09:40:33.709 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:600] -
Expiring LoginContext cookie
09:40:33.709 - DEBUG
[com.clareity.shibboleth.storage.DbStorageService:458] - Removing from
[loginContexts] for key [44224018-c387-4589-87e6-b055d265c2dc]
09:40:33.709 - DEBUG
[edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:611] -
Removed LoginContext, with key 44224018-c387-4589-87e6-b055d265c2dc, from
StorageService
 partition loginContexts
09:40:33.710 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:17
0] - Incoming request contains a login context but principal was not
authenticated, 
processing first leg of request
09:40:33.710 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:33
9] - Decoding message with decoder binding
'urn:oasis:names:tc:SAML:2.0:bindings:HTT
P-POST'
09:40:33.722 - WARN
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:37
3] - Error decoding authentication request message
org.opensaml.ws.message.decoder.MessageDecodingException: This message
deocoder only supports the HTTP POST method
        at 
org.opensaml.saml2.binding.decoding.HTTPPostDecoder.doDecode(HTTPPostDecode
r.java:83) ~[opensaml-2.5.3.jar:na]
        at 
org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecode
r.java:79) ~[openws-1.4.4.jar:na]
        at 
org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder.decode(BaseSAML
2MessageDecoder.java:70) ~[opensaml-2.5.3.jar:na]

So I know I haven't changed my login handler in that area for quite a
while. I did update to 2.3.6 sometime last summer. So I'm not sure when
the error started happening. Checking Jira did not bring any search
results that were relevant.

I'm going to dig further until I find it, but thought I would pop out this
message to see if it rings any bells with anyone.

cheers,

Paul