ResourcedBacked metadata provider with local files reloads too often
Description
Environment
Activity
Scott Cantor January 12, 2011 at 2:34 PM
Forgot to note, an explicit TZ parameter was added to a DateTime constructor, may address Bradley's report. Suggest you recheck with latest snapshot and see.
Scott Cantor January 12, 2011 at 2:31 PM
Fixed in svn with changes to opensaml, along with some logging improvements.
Scott Cantor January 12, 2011 at 2:30 PM
The double entries turn out to be caused by the embedding of a Filesystem provider for the IdP's metadata inside the metadata handler. So that's not a bug. However, the ResourceBacked case was reloading the metadata too frequently in some cases, and this has been patched.
Also, the Filesystem provider now checks for last access time also to prevent reloads.
Scott Cantor January 11, 2011 at 10:02 PM
I'm using Jetty, I'll have to see if it's logging anything like this or not, but I didn't notice anything.
I can't imagine this is the same issue I'm seeing, because I would think the refresh log entries I'm getting would look different if there was an NPE or something in the middle.
More fodder anyway.
Bradley Schwoerer January 11, 2011 at 9:57 PMEdited
FWIW ... With the latest joda-time-1.6.2 I have been noticing this in my tomcat catalina log files. The first of the three I noticed with joda-time-1.6, so I had my local build start using 1.6.2 and then started noticing the later ones. I was going to report this after looking into it more, but I think the two are related.
Exception in thread "Timer-3" java.lang.NullPointerException
at org.joda.time.DateTimeUtils.currentTimeMillis(DateTimeUtils.java:52)
at org.joda.time.base.BaseDateTime.<init>(BaseDateTime.java:86)
at org.joda.time.DateTime.<init>(DateTime.java:109)
at org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider.refresh(AbstractReloadingMetadataProvider.java:227)
at org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider$RefreshMetadataTask.run(AbstractReloadingMetadataProvider.java:485)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
Exception in thread "Timer-14" java.lang.IllegalArgumentException: DateTimeZone must not be null
at org.joda.time.chrono.ZonedChronology.getInstance(ZonedChronology.java:64)
at org.joda.time.chrono.ISOChronology.getInstance(ISOChronology.java:107)
at org.joda.time.chrono.ISOChronology.getInstance(ISOChronology.java:86)
at org.joda.time.base.BaseDateTime.<init>(BaseDateTime.java:97)
at org.joda.time.DateTime.<init>(DateTime.java:120)
at org.opensaml.util.resource.FilesystemResource.getLastModifiedTime(FilesystemResource.java:134)
at org.opensaml.util.resource.ResourceChangeWatcher.run(ResourceChangeWatcher.java:154)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
Exception in thread "Timer-15" java.lang.IllegalArgumentException: DateTimeZone must not be null
at org.joda.time.chrono.ZonedChronology.getInstance(ZonedChronology.java:64)
at org.joda.time.chrono.ISOChronology.getInstance(ISOChronology.java:107)
at org.joda.time.chrono.ISOChronology.getInstance(ISOChronology.java:86)
at org.joda.time.base.BaseDateTime.<init>(BaseDateTime.java:97)
at org.joda.time.DateTime.<init>(DateTime.java:120)
at org.opensaml.util.resource.FilesystemResource.getLastModifiedTime(FilesystemResource.java:134)
at org.opensaml.util.resource.ResourceChangeWatcher.run(ResourceChangeWatcher.java:154)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
Having fixed the bug causing 5 minute reload intervals for HTTP sources, the ResourceBacked case with local files (used by default for the IdP's own metadata) seems to have a glitch causing the first reload attempt to detect no change and schedule a reload in a few hours, but then detect a change to the file a minute later and do a reload. Then it waits 3 hours and repeats:
15:47:48.451 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:230] - Beginning refresh of metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml'
15:47:48.452 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:234] - Metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml' has not changed since last refresh
15:47:48.452 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:298] - Computing new expiration time for cached metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml
15:47:48.452 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:301] - Expiration of cached metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml' will occur at 2011-01-11T00:47:48.451Z
15:47:48.452 - INFO [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:236] - Metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml' unchanged since last refresh, next refresh will occur at approximately 2011-01-10T23:47:48.451Z
15:48:05.374 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:230] - Beginning refresh of metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml'
15:48:05.376 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:240] - Processing new metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml'
15:48:05.376 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:322] - Unmarshalling metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml'
15:48:05.377 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:368] - Filtering metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml'
15:48:05.378 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:377] - Releasing cached DOM for metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml'
15:48:05.378 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:380] - Post-processing metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml'
15:48:05.378 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:383] - Computing expiration time for metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml'
15:48:05.378 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:386] - Expiration of metadata from '/opt/shibboleth-idp/metadata/idp-metadata.xml' will occur at 2011-01-11T00:48:05.374Z
15:48:05.378 - INFO [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:404] - New metadata loaded from '/opt/shibboleth-idp/metadata/idp-metadata.xml', next refresh will occur at approximately 2011-01-10T23:48:05.375Z