Metadata not updating in IDP

[Matthew Slowe]

$saluataion{timeofday(localtime())} all,

We have a shibboleth-identityprovider-2.4.0 instance which, since,
August, seems to stop managing to update its metadata from the UK
Federation after a little while after a tomcat restart.

Then, after some time[*], it starts ignoring it because it's not valid
any more.

The config for this hasn't changed in years... and I can't see why it's
breaking. Any ideas?

Thanks,
Matthew

[*] I set maxValidityInterval="2592000" (30d), UKFED appears to set
about 12d.

Last time it "worked" prior to Tomcat restart this morning on 2014-08-12:

09:36:48.328 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:253] - Beginning refresh of metadata from '/opt/idp/metadata/idp-metadata.xml'
09:36:48.351 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:260] - Processing new metadata from '/opt/idp/metadata/idp-metadata.xml'
09:36:48.351 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:344] - Unmarshalling metadata from '/opt/idp/metadata/idp-metadata.xml'
09:36:48.399 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:388] - Filtering metadata from '/opt/idp/metadata/idp-metadata.xml'
09:36:48.399 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:397] - Releasing cached DOM for metadata from '/opt/idp/metadata/idp-metadata.xml'
09:36:48.400 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:400] - Post-processing metadata from '/opt/idp/metadata/idp-metadata.xml'
09:36:48.400 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:403] - Computing expiration time for metadata from '/opt/idp/metadata/idp-metadata.xml'
09:36:48.402 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:406] - Expiration of metadata from '/opt/idp/metadata/idp-metadata.xml' will occur at 2014-09-12T12:36:48.328Z
09:36:48.402 - INFO [o.o.s.m.p.AbstractReloadingMetadataProvider:423] - New metadata succesfully loaded for '/opt/idp/metadata/idp-metadata.xml'
09:36:48.403 - INFO [o.o.s.m.p.AbstractReloadingMetadataProvider:271] - Next refresh cycle for metadata provider '/opt/idp/metadata/idp-metadata.xml' will occur on '2014-09-12T11:36:48.346Z' ('2014-09-12T12:36:48.346+01:00' local time)
09:36:48.491 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:253] - Beginning refresh of metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml'
09:36:57.064 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:260] - Processing new metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml'
09:36:57.064 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:344] - Unmarshalling metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml'
09:37:04.055 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:388] - Filtering metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml'
09:37:05.983 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:397] - Releasing cached DOM for metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml'
09:37:06.145 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:400] - Post-processing metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml'
09:37:06.176 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:403] - Computing expiration time for metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml'
09:37:06.281 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:406] - Expiration of metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml' will occur at 2014-09-12T12:36:48.491Z
09:37:06.282 - INFO [o.o.s.m.p.AbstractReloadingMetadataProvider:423] - New metadata succesfully loaded for 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml'
09:37:06.282 - INFO [o.o.s.m.p.AbstractReloadingMetadataProvider:271] - Next refresh cycle for metadata provider 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml' will occur on '2014-09-12T11:36:52.939Z' ('2014-09-12T12:36:52.939+01:00' local time)
09:37:07.417 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:253] - Beginning refresh of metadata from '/opt/idp/metadata/idp-metadata.xml'
09:37:07.418 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:260] - Processing new metadata from '/opt/idp/metadata/idp-metadata.xml'
09:37:07.419 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:344] - Unmarshalling metadata from '/opt/idp/metadata/idp-metadata.xml'
09:37:07.421 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:388] - Filtering metadata from '/opt/idp/metadata/idp-metadata.xml'
09:37:07.422 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:397] - Releasing cached DOM for metadata from '/opt/idp/metadata/idp-metadata.xml'
09:37:07.423 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:400] - Post-processing metadata from '/opt/idp/metadata/idp-metadata.xml'
09:37:07.423 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:403] - Computing expiration time for metadata from '/opt/idp/metadata/idp-metadata.xml'
09:37:07.424 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:406] - Expiration of metadata from '/opt/idp/metadata/idp-metadata.xml' will occur at 2014-09-12T12:37:07.417Z
09:37:07.425 - INFO [o.o.s.m.p.AbstractReloadingMetadataProvider:423] - New metadata succesfully loaded for '/opt/idp/metadata/idp-metadata.xml'
09:37:07.426 - INFO [o.o.s.m.p.AbstractReloadingMetadataProvider:271] - Next refresh cycle for metadata provider '/opt/idp/metadata/idp-metadata.xml' will occur on '2014-09-12T11:37:07.419Z' ('2014-09-12T12:37:07.419+01:00' local time)

Some time later this becomes:

09:32:16.533 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:253] - Beginning refresh of metadata from '/opt/idp/metadata/idp-metadata.xml'
09:32:16.534 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:257] - Metadata from '/opt/idp/metadata/idp-metadata.xml' has not changed since last refresh
09:32:16.534 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:322] - Computing new expiration time for cached metadata from '/opt/idp/metadata/idp-metadata.xml
09:32:16.535 - INFO [o.o.s.m.p.AbstractReloadingMetadataProvider:271] - Next refresh cycle for metadata provider '/opt/idp/metadata/idp-metadata.xml' will occur on '2014-09-18T11:32:16.533Z' ('2014-09-18T12:32:16.533+01:00' local time)
09:32:20.791 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:253] - Beginning refresh of metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml'
09:32:20.832 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:257] - Metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml' has not changed since last refresh
09:32:20.832 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:322] - Computing new expiration time for cached metadata from 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml
09:32:20.902 - INFO [o.o.s.m.p.AbstractReloadingMetadataProvider:271] - Next refresh cycle for metadata provider 'http://metadata.ukfederation.org.uk/ukfederation-metadata.xml' will occur on '2014-09-18T11:32:20.819Z' ('2014-09-18T12:32:20.819+01:00'
local time)
09:32:33.303 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:253] - Beginning refresh of metadata from '/opt/idp/metadata/idp-metadata.xml'
09:32:33.303 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:257] - Metadata from '/opt/idp/metadata/idp-metadata.xml' has not changed since last refresh
09:32:33.304 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:322] - Computing new expiration time for cached metadata from '/opt/idp/metadata/idp-metadata.xml
09:32:33.304 - INFO [o.o.s.m.p.AbstractReloadingMetadataProvider:271] - Next refresh cycle for metadata provider '/opt/idp/metadata/idp-metadata.xml' will occur on '2014-09-18T11:32:33.303Z' ('2014-09-18T12:32:33.303+01:00' local time)


Still later this gets even shorter:

06:40:59.836 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:253] - Beginning refresh of metadata from '/opt/idp/metadata/idp-metadata.xml'
06:40:59.837 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:257] - Metadata from '/opt/idp/metadata/idp-metadata.xml' has not changed since last refresh
06:40:59.837 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:322] - Computing new expiration time for cached metadata from '/opt/idp/metadata/idp-metadata.xml
06:40:59.838 - INFO [o.o.s.m.p.AbstractReloadingMetadataProvider:271] - Next refresh cycle for metadata provider '/opt/idp/metadata/idp-metadata.xml' will occur on '2014-09-03T08:40:59.836Z' ('2014-09-03T09:40:59.836+01:00' local time)
09:40:59.836 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:253] - Beginning refresh of metadata from '/opt/idp/metadata/idp-metadata.xml'
09:40:59.837 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:257] - Metadata from '/opt/idp/metadata/idp-metadata.xml' has not changed since last refresh
09:40:59.837 - DEBUG [o.o.s.m.p.AbstractReloadingMetadataProvider:322] - Computing new expiration time for cached metadata from '/opt/idp/metadata/idp-metadata.xml

[Rod Widdowson]

Does this look familiar?

https://issues.shibboleth.net/jira/browse/JOST-220

TL;DR we spotted a potential bug in OpenSAML and fixed it. We don't know if
this is the cause because we never reproduced the problem. This potential
fix is available in 2.4.2. Also you might want to check your container
logs.

[Matthew Slowe]

Post by Rod Widdowson
Does this look familiar?
https://issues.shibboleth.net/jira/browse/JOST-220
TL;DR we spotted a potential bug in OpenSAML and fixed it. We don't know if
this is the cause because we never reproduced the problem. This potential
fix is available in 2.4.2. Also you might want to check your container
logs.

The "java.lang.IllegalArgumentException: Negative delay." in there does
-- it's in the tomcat logs.

I will look at getting the IDP upgraded :-)

[Peter Schober]

Post by Matthew Slowe
We have a shibboleth-identityprovider-2.4.0 instance which, since,
August, seems to stop managing to update its metadata from the UK
Federation after a little while after a tomcat restart.

Jfyi, we also had a couple of Shib IDPs stop refreshing metadata early
September, this going unnnoticed until the local copy exprired.
I don't have anything new to add to the bug report (no logs etc.), so
this is just to confirm your observation.

Strangely enough it this was noted to affect 6 IDPs more or less at
the same time/weekend, so there was some speculation whether maybe
there was an issue with conditional HTTP GET and the httpd serving up
metadata files from disk. But that wouldn't account for a container
restart on each of the IDPs to fix the issue.
-peter

[Peter Schober]

there was some speculation whether maybe there was an issue with
conditional HTTP GET and the httpd serving up metadata files from
disk. But that wouldn't account for a container restart on each of
the IDPs to fix the issue.

Well, it would (D'oh!), since the IDP would unconditionally download
the metadata on a restart. (Not saying it's related.)
-peter