Metadata expiry and computing a new expiration time.

[Cantor, Scott]

On 9/14/15, 12:26 PM, "Cantor, Scott" <cantor.2 at osu.edu> wrote:

>On 9/14/15, 12:22 PM, "users on behalf of Simon Fraser" <users-bounces at shibboleth.net on behalf of srf at sanger.ac.uk> wrote:
>
>>There's one INFO message about when the next refresh cycle is, and the
>>rest appear to be tagged DEBUG.
>
>Oh, because it's not changed. Judgement call. It does log more if it's changed, so you sort of read into the fact that nothing's logged that it didn't change. Mainly because for local file metadata, it's common to poll every few minutes, so the log would be full of noise.

And...I think maybe that's the underlying bug. When you were originally investigating, were you still seeing the "next refresh cycle" log entries depsite it not reloading? If so, this is the bug.

I just encountered this in my testing with 768M of heap on a fairly large metadata file:

2015-09-14 15:25:02,140 - DEBUG [org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolver:294] - Error occurred while attempting to refresh metadata from 'https://metadata.example.com/global-metadata.xml'
java.lang.OutOfMemoryError: GC overhead limit exceeded
	at java.util.Arrays.copyOf(Arrays.java:3332)
2015-09-14 15:25:02,140 - INFO [org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolver:306] - Next refresh cycle for metadata provider 'https://metadata.example.com/global-metadata.xml' will occur on '2015-09-14T19:30:02.140Z' ('2015-09-14T15:30:02.140-04:00' local time)


It's not being swallowed completely, but we screwed up the logging of the exception so on INFO it looks routine. Very bad.

I don't know if V2 is similarly broken, but I'll leave a bug filed for Brent to look at.

-- Scott