Metadata not updating in IDP

Matthew Slowe m.slowe at kent.ac.uk
Fri Oct 3 05:09:07 EDT 2014


$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


-- 
Matthew Slowe
Server Infrastructure Team	e: m.slowe at kent.ac.uk
IS, University of Kent		t: +44 (0)1227 824265
Canterbury, UK			w: www.kent.ac.uk


More information about the users mailing list