Shibboleth IdP Problems

[Michael Parente]

Hi all,

I am wondering if anyone that utilizes Shibboleth with InCommon had any 
strange behavior with their IdP on the day of the Internet2 outage 
(08/16/2011).

Around noon EST we lost the ability to log in through our IdP. The 
Shibboleth login page would basically time out, so we looked at the 
Shibboleth logs on the IdP and found the following errors:

12:00:45.530 - WARN 
[org.opensaml.saml2.metadata.provider.FileBackedHTTPMetadataProvider:101] - 
Unable to read metadata from 
http://wayf.incommonfederation.org/InCommon/InCommon-metadata.xml 
attempting to read it from local backup
java.net.ConnectException: Connection timed out
12:00:46.140 - INFO 
[edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:802] 
- PKIX validation info cache cleared
12:00:46.140 - INFO 
[edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:802] 
- PKIX validation info cache cleared
12:00:46.152 - ERROR 
[org.opensaml.common.binding.security.IssueInstantRule:107] - Message 
was expired: message issue time was '2011-08-16T15:54:07.000Z', message 
expired at: '2011-08-16T15:58:07.000Z', current time: 
'2011-08-16T12:00:46.152-04:00'
12:00:46.153 - WARN 
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:316] 
- Message did not meet security requirements
org.opensaml.ws.security.SecurityPolicyException: Message was rejected 
due to issue instant expiration

We received a ton of these errors so we decided to restart Tomcat. For 
the next couple hours we tried looking for any clue as to what was 
causing this behavior, restarting the IdP frequently. The strange thing 
is, the IdP would work for a period of time, and then stop working. It 
seemed like each time the IdP would stop working, we saw this error:

13:07:59.611 - WARN 
[org.opensaml.saml2.metadata.provider.FileBackedHTTPMetadataProvider:101] - 
Unable to read metadata from 
http://wayf.incommonfederation.org/InCommon/InCommon-metadata.xml 
attempting to read it from local backup
java.net.ConnectException: Connection timed out

Followed by a whole lot of these errors:

13:08:02.678 - ERROR 
[org.opensaml.common.binding.security.IssueInstantRule:107] - Message 
was expired: message issue time was '2011-08-16T16:53:19.000Z', message 
expired at: '2011-08-16T16:57:19.000Z', current time: 
'2011-08-16T13:08:02.678-04:00'
13:08:02.679 - WARN 
[edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:316] 
- Message did not meet security requirements
org.opensaml.ws.security.SecurityPolicyException: Message was rejected 
due to issue instant expiration

After 2:30pm EST the IdP stopped hanging, but we began having another 
problem. After logging in through the IdP there were no attributes 
passed. We saw hundreds of the following two errors continuously over 
the next hour and a half:

14:29:10.158 - ERROR 
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.attributeDefinition.ScriptedAttributeDefinition:134] 
- ScriptletAttributeDefinition password unable to execute script
javax.script.ScriptException: 
sun.org.mozilla.javascript.EvaluatorException: missing name after . 
operator (<Unknown source>#3) in <Unknown source> at line number 3
14:29:10.159 - WARN 
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:465] 
- Error resolving attributes for principal 'xsun4'.  No name identifier 
or attribute statement will be included in response

Then, after restarting the IdP at about 4:10pm EST, everything started 
working again and no more errors showed up in the logs. The reason I 
specifically mentioned the InCommon outage is because we have never had 
a problem with our IdP (and have not since) except during that period of 
time. It seemed too coincidental to happen by chance, but if it was 
related, why did it cause our IdP to have so many problems? Shouldn't 
Shibboleth have continued to work with our non-federated applications 
instead of completely crashing? BTW, we are running IdP version 2.1.5, 
RedHat 5, Tomcat 6, OpenJDK 1.6.

Any insight would be GREATLY appreciated as we are pretty much at a loss 
here as to what caused the problem on our end.

Thanks,
Mike