A problem with metadata:FilesystemMetadataProvider

[Marco Malavolti]

Hi to all, I hope you are fine. :)

Today I have a problem with the MetadataProvider (type:
metadata:FileBackedHTTPMetadataProvider) of my IDP.

I work with VM that has:
- Ubuntu 12.04.4 LTS
- Tomcat 7.0.26-1ubuntu
- Shibboleth IdP 2.4.0 installed
- I have updated my openSAML jar to the version 2.6.1 because I have
followed the advice found on this thread:
https://issues.shibboleth.net/jira/browse/JOST-220

This is my MetadataProvider configuration:

<!-- Metadata Refresh Period
minRefreshDelay == every 1 minutes
maxRefreshDelay == every 3 minutes -->

<metadata:MetadataProvider id="URLMD-Federation"
xsi:type="metadata:FileBackedHTTPMetadataProvider"
minRefreshDelay="PT1M"
maxRefreshDelay="PT3M"
metadataURL="http://www.example.it/metadata-sha256.xml"
backingFile="/opt/shibboleth-idp/metadata/metadata-sha256.xml">

<metadata:MetadataFilter xsi:type="metadata:ChainingFilter">
<metadata:MetadataFilter
xsi:type="metadata:RequiredValidUntil" maxValidityInterval="P5D" />
<metadata:MetadataFilter
xsi:type="metadata:SignatureValidation"
trustEngineRef="shibboleth.MetadataTrustEngine"
requireSignedMetadata="true" />
</metadata:MetadataFilter>
</metadata:MetadataProvider>

Into my environment the Federation's metadata are signed every day and,
in the same time, the EntitiesDescriptor acquires a new validUntil value
valid for the next 5 days.

Is it possible that with this configuration my IdP doesn't retrieve the
new metadata but says to me only:

Beginning refresh of metadata from
'http://www.example.it/metadata-sha256.xml'
12:51:59.446 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:249] -
Attempting to fetch metadata document from
'http://www.example.it/metadata-sha256.xml'
12:51:59.452 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:254] -
Metadata document from 'http://www.example.it/metadata-sha256.xml' has
not changed since last retrieval
12:51:59.452 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:257]
- Metadata from 'http://www.example.it/metadata-sha256.xml' has not
changed since last refresh
12:51:59.452 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:327]
- Computing new expiration time for cached metadata from
'http://www.example.it/metadata-sha256.xml
12:51:59.453 - INFO
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:276]
- Next refresh cycle for metadata provider
'http://www.example.it/metadata-sha256.xml' will occur on
'2014-08-11T10:54:14.447Z' ('2014-08-11T12:54:14.447+02:00' local time)

when the backingFile metadata file is different or not exists?

I have switched off my firewall so that any ports are blocked.
I have tried to understand something on the "idp-process.log" into DEBUG
mode without success because any ERROR appears on it.
I have tried to understand something on Tomcat7 "catalina.out" (without
success because I haven't found any useful information to resolve this
problem)
I have tried to force the download of the remote source metadata by
changing something into the backingFile file. Nothing to do.

I have found that the unique way that I have to correctly retrieve the
remote metadata source file into its backingFile metadata is restart the
Tomcat7 container.

I have understood that the "metadata:FileBackedHTTPMetadataProvider"
works like its brother "metadata:HTTPMetadataProvider", but I have not
understood why the local/backingFile metadatas isn't come updated when
it is different from the remote one.

Help me, please!

Best Regards,
Marco Malavolti

P.S.: Forgive me for my bad English. If you don't understand me I can
try to explain again in a better way I hope.

[Cantor, Scott]

Post by Marco Malavolti
I have understood that the "metadata:FileBackedHTTPMetadataProvider"
works like its brother "metadata:HTTPMetadataProvider", but I have not
understood why the local/backingFile metadatas isn't come updated when
it is different from the remote one.

You're hitting a race condition. The code has a design flaw (not quite a
bug) such that it tracks the last time that it *checks* for a new file,
and not the last timestamp of the file it loaded. So what happens is, the
timestamp on the file itself when it changes is older than the last time
the code checked for a new file, and it misses the update. Mine does this
frequently when I use that provider.

-- Scott

[Peter Schober]

Post by Marco Malavolti
<!-- Metadata Refresh Period
minRefreshDelay == every 1 minutes
maxRefreshDelay == every 3 minutes -->

Out of curiosity: Did you set these so low in order to reproduce the
issue more quickly? (You said metadata is signed once a day, so
checking every other minute or so does not make much sense, of course.)
-peter

[Cantor, Scott]

Post by Peter Schober

Post by Marco Malavolti
<!-- Metadata Refresh Period
minRefreshDelay == every 1 minutes
maxRefreshDelay == every 3 minutes -->

Out of curiosity: Did you set these so low in order to reproduce the
issue more quickly? (You said metadata is signed once a day, so
checking every other minute or so does not make much sense, of course.)

I didn't even notice the settings, but that practically guarantees you'll
hit the race condition. Every couple of minutes, it's updating the
timestamp in memory, which means you have a much smaller window to hit. In
other words, don't do this.

I hit this problem with a 15 minute or so window, so you're pretty much
ensuring no updates with that.

-- Scott

[Marco Malavolti]

Post by Cantor, Scott

Post by Peter Schober

Post by Marco Malavolti
<!-- Metadata Refresh Period
minRefreshDelay == every 1 minutes
maxRefreshDelay == every 3 minutes -->

Out of curiosity: Did you set these so low in order to reproduce the
issue more quickly? (You said metadata is signed once a day, so
checking every other minute or so does not make much sense, of course.)

Yes, I have set these so low in order to reproduce the issue more
quickly, but I have the same problem with the default configuration values:
- minRefreshDelay="PT5M"
- maxRefreshDelay="PT4H"

Post by Cantor, Scott
I didn't even notice the settings, but that practically guarantees you'll
hit the race condition. Every couple of minutes, it's updating the
timestamp in memory, which means you have a much smaller window to hit. In
other words, don't do this.
I hit this problem with a 15 minute or so window, so you're pretty much
ensuring no updates with that.
-- Scott

I will repeat the tests with the default settings, but I am pretty sure
that I will meet the same problem.

I keep you updated.

Thank you

[Cantor, Scott]

Post by Marco Malavolti
Yes, I have set these so low in order to reproduce the issue more
- minRefreshDelay="PT5M"
- maxRefreshDelay="PT4H"

Then your file has a last-modified value that's older than every time it
runs a check. Trust me, it works, so the only way it's not working is if
you're essentially forcibly causing the race condition every time. Your
tests won't mean anything unless you keep the timestamp on the file new
enough to trigger a load.

What you want is for the file time to be essentially the exact time you
update the file, not the actual time the file was last changed at the
source.

Basically, either change your file update process, or switch to the HTTP
versions.


-- Scott

[Marco Malavolti]

Update:

The "http://www.example.it/metadata/metadata-sha256.xml" has a new
validUntil value, but the backingFile is not updated.

I have tried this steps:
1) Removed the metadata-sha256.xml from its location.
2) Restarted Tomcat7
3) Removed again the new metadata-sha256.xml from its location.
4) I have waited the new refresh cycle to see what happen and I see the
"Log" that I have attached here.

I have used the same MetadataProvider configuration with a different
HTTP URL where I have uploaded the metadata-sha256.xml file and it works.

I begin to think that the problem can be on the retrieving URL, but I
don't understand why, with a Tomcat restart, the metadata is updated
correctly.

Thank you for all the help that you have gave to me.

I appreciate it very much.

Best Regards,
Marco
------------------------------------------------------------

Config:
<!-- Metadata Refresh Period
minRefreshDelay == every 5 minutes (default value)
maxRefreshDelay == every 4 hours (default value) -->

<metadata:MetadataProvider id="URLMD-Federation"
xsi:type="metadata:FileBackedHTTPMetadataProvider"
metadataURL="http://www.example.it/metadata/metadata-sha256.xml"
backingFile="/opt/shibboleth-idp/metadata/metadata-sha256.xml">

<metadata:MetadataFilter xsi:type="metadata:ChainingFilter">
<metadata:MetadataFilter xsi:type="metadata:SignatureValidation"
trustEngineRef="shibboleth.MetadataTrustEngine"
requireSignedMetadata="true" />
<metadata:MetadataFilter xsi:type="EntityRoleWhiteList">
<metadata:RetainedRole>samlmd:SPSSODescriptor</metadata:RetainedRole>
</metadata:MetadataFilter>
</metadata:MetadataFilter>
</metadata:MetadataProvider>

</metadata:MetadataProvider>

Log:
10:58:58.125 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:253]
- Beginning refresh of metadata from
'http://www.example.it/metadata/metadata-sha256.xml'
10:58:58.126 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:249] -
Attempting to fetch metadata document from
'http://www.example.it/metadata/metadata-sha256.xml'
10:58:58.145 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:254] -
Metadata document from
'http://www.example.it/metadata/metadata-sha256.xml' has not changed
since last retrieval
10:58:58.145 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:257]
- Metadata from 'http://www.example.it/metadata/metadata-sha256.xml' has
not changed since last refresh
10:58:58.146 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:327]
- Computing new expiration time for cached metadata from
'http://www.example.it/metadata/metadata-sha256.xml
10:58:58.193 - INFO
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:276]
- Next refresh cycle for metadata provider
'http://www.example.it/metadata/metadata-sha256.xml' will occur on
'2014-08-12T11:58:58.142Z' ('2014-08-12T13:58:58.142+02:00' local time)

--------------------------------------------------------------------------------------------------------------

Post by Cantor, Scott

Post by Marco Malavolti
Yes, I have set these so low in order to reproduce the issue more
- minRefreshDelay="PT5M"
- maxRefreshDelay="PT4H"

Then your file has a last-modified value that's older than every time it
runs a check. Trust me, it works, so the only way it's not working is if
you're essentially forcibly causing the race condition every time. Your
tests won't mean anything unless you keep the timestamp on the file new
enough to trigger a load.
What you want is for the file time to be essentially the exact time you
update the file, not the actual time the file was last changed at the
source.
Basically, either change your file update process, or switch to the HTTP
versions.
-- Scott

[Peter Schober]

Post by Marco Malavolti
The "http://www.example.it/metadata/metadata-sha256.xml" has a new
validUntil value, but the backingFile is not updated.

[...]

Post by Marco Malavolti
Metadata document from
'http://www.example.it/metadata/metadata-sha256.xml' has not changed
since last retrieval

Those two statements seem to contradict each other. Does the server
hosting the metadata support any of the more advanced methods to
indicate an unchanged resource (Last-Modified, ETag)?
-peter

[Cantor, Scott]

Post by Marco Malavolti
The "http://www.example.it/metadata/metadata-sha256.xml" has a new
validUntil value, but the backingFile is not updated.
1) Removed the metadata-sha256.xml from its location.
2) Restarted Tomcat7
3) Removed again the new metadata-sha256.xml from its location.
4) I have waited the new refresh cycle to see what happen and I see the
"Log" that I have attached here.

That means your server is broken, it's misreporting caching information.

Post by Marco Malavolti
I begin to think that the problem can be on the retrieving URL, but I
don't understand why, with a Tomcat restart, the metadata is updated
correctly.

The IdP, AFAIK, does not preserve HTTP cache state across restarts. The SP
does, it writes the data to an additional backing file.

-- Scott

[Marco Malavolti]

Update 2:

The new steps that I have executed are:

1) Configured the Metadata Provider like this:

<metadata:MetadataProvider id="URLMD-IDEM-Federation"
xsi:type="metadata:FileBackedHTTPMetadataProvider"
metadataURL="http://example.it/metadata-sha256.xml"
backingFile="/opt/shibboleth-idp/metadata/metadata-sha256.xml"
maxRefreshDelay="PT1H">

<metadata:MetadataFilter xsi:type="metadata:ChainingFilter">
<metadata:MetadataFilter
xsi:type="metadata:SignatureValidation"
trustEngineRef="shibboleth.MetadataTrustEngine"
requireSignedMetadata="true" />
</metadata:MetadataFilter>
</metadata:MetadataProvider>

2) Removed the old "metadata-sha256.xml"
3) Restarted Tomcat7 and retrieved the new "metadata-sha256.xml"
4) Modified the source metadata file on the example.it server
5) Waited the refresh time
6) Obtained this log:

21:21:48.977 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:253]
- Beginning refresh of metadata from 'http://example.it/metadata-sha256.xml'
21:21:48.979 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:249] -
Attempting to fetch metadata document from
'http://example.it/metadata-sha256.xml'
21:21:48.986 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:334] -
Attempting to extract metadata from response to request for metadata
from 'http://example.it/metadata-sha256.xml'
21:21:50.100 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:268] -
Successfully fetched 5384875bytes of metadata from
http://example.it/metadata-sha256.xml
21:21:50.100 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:260]
- Processing new metadata from 'http://example.it/metadata-sha256.xml'
21:21:50.101 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:349]
- Unmarshalling metadata from 'http://example.it/metadata-sha256.xml'
21:22:06.147 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:264]
- Error occurred while attempting to refresh metadata from
'http://example.it/metadata-sha256.xml'
java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOfRange(Arrays.java:2694) ~[na:1.7.0_60]
at java.lang.String.<init>(String.java:203) ~[na:1.7.0_60]
at java.lang.StringBuffer.toString(StringBuffer.java:561)
~[na:1.7.0_60]
at org.apache.xerces.dom.TextImpl.getWholeText(Unknown Source) ~[na:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshallTextContent(AbstractXMLObjectUnmarshaller.java:369)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshall(AbstractXMLObjectUnmarshaller.java:130)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshallChildElement(AbstractXMLObjectUnmarshaller.java:355)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshall(AbstractXMLObjectUnmarshaller.java:127)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshallChildElement(AbstractXMLObjectUnmarshaller.java:355)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshall(AbstractXMLObjectUnmarshaller.java:127)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshallChildElement(AbstractXMLObjectUnmarshaller.java:355)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshall(AbstractXMLObjectUnmarshaller.java:127)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshallChildElement(AbstractXMLObjectUnmarshaller.java:355)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshall(AbstractXMLObjectUnmarshaller.java:127)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshallChildElement(AbstractXMLObjectUnmarshaller.java:355)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.xml.io.AbstractXMLObjectUnmarshaller.unmarshall(AbstractXMLObjectUnmarshaller.java:127)
~[xmltooling-1.4.1.jar:na]
at
org.opensaml.saml2.metadata.provider.AbstractMetadataProvider.unmarshallMetadata(AbstractMetadataProvider.java:470)
~[opensaml-2.6.1.jar:na]
at
org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider.unmarshallMetadata(AbstractReloadingMetadataProvider.java:309)
~[opensaml-2.6.1.jar:na]
at
org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider.processNewMetadata(AbstractReloadingMetadataProvider.java:350)
~[opensaml-2.6.1.jar:na]
at
org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider.refresh(AbstractReloadingMetadataProvider.java:261)
~[opensaml-2.6.1.jar:na]
at
org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider$RefreshMetadataTask.run(AbstractReloadingMetadataProvider.java:513)
[opensaml-2.6.1.jar:na]
at java.util.TimerThread.mainLoop(Timer.java:555) [na:1.7.0_60]
at java.util.TimerThread.run(Timer.java:505) [na:1.7.0_60]
21:22:06.150 - INFO
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:276]
- Next refresh cycle for metadata provider
'http://example.it/metadata-sha256.xml' will occur on
'2014-08-13T19:27:06.149Z' ('2014-08-13T21:27:06.149+02:00' local time)
21:24:08.044 - INFO [Shibboleth-Access:73] -
20140813T192408Z|155.185.30.207|idem-pupagent.dmz-int.unimo.it:443|/profile/Metadata/SAML|
21:27:06.150 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:253]
- Beginning refresh of metadata from 'http://example.it/metadata-sha256.xml'
21:27:06.151 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:249] -
Attempting to fetch metadata document from
'http://example.it/metadata-sha256.xml'
21:27:06.156 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:254] -
Metadata document from 'http://example.it/metadata-sha256.xml' has not
changed since last retrieval
21:27:06.156 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:257]
- Metadata from 'http://example.it/metadata-sha256.xml' has not changed
since last refresh
21:27:06.157 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:327]
- Computing new expiration time for cached metadata from
'http://example.it/metadata-sha256.xml
21:27:06.556 - INFO
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:276]
- Next refresh cycle for metadata provider
'http://example.it/metadata-sha256.xml' will occur on
'2014-08-13T20:12:06.251Z' ('2014-08-13T22:12:06.251+02:00' local time)


This is my /etc/environments:

PATH="/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games"
IDP_LOG=/opt/shibboleth-idp/logs/idp-process.log
TOMCAT_LOG_DIR=/var/log/tomcat7/
CATALINA_HOME=/var/lib/tomcat7
CATALINA_OUT=/var/log/tomcat7/catalina.out
JAVA_OPTS="-Djava.awt.headless=true -Xms256m -Xmx2g -XX:MaxPermSize=128m
-XX:+DisableExplicitGC -XX:+UseParallelOldGC"
JAVA_HOME=/usr/lib/jvm/java-7-oracle
TOMCAT_HOME=/usr/share/tomcat7
IDP_HOME=/opt/shibboleth-idp
JAVA_ENDORSED_DIRS=/usr/share/tomcat7/endorsed

before I had this /etc/environment:

PATH="/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games"
IDP_LOG=/opt/shibboleth-idp/logs/idp-process.log
TOMCAT_LOG_DIR=/var/log/tomcat7/
CATALINA_HOME=/var/lib/tomcat7
CATALINA_OUT=/var/log/tomcat7/catalina.out
JAVA_OPTS="-Djava.awt.headless=true -Xmx512M -XX:MaxPermSize=128m"
JAVA_HOME=/usr/lib/jvm/java-7-oracle
TOMCAT_HOME=/usr/share/tomcat7
IDP_HOME=/opt/shibboleth-idp
JAVA_ENDORSED_DIRS=/usr/share/tomcat7/endorsed

and, I'm not sure it is important, I haven't restarted the VM after
apply the new /etc/environments.


I hope this can be useful to solve my problem...

Thank you very much for all, really!

Regards,
Marco

Post by Marco Malavolti
The "http://www.example.it/metadata/metadata-sha256.xml" has a new
validUntil value, but the backingFile is not updated.
1) Removed the metadata-sha256.xml from its location.
2) Restarted Tomcat7
3) Removed again the new metadata-sha256.xml from its location.
4) I have waited the new refresh cycle to see what happen and I see
the "Log" that I have attached here.
I have used the same MetadataProvider configuration with a different
HTTP URL where I have uploaded the metadata-sha256.xml file and it works.
I begin to think that the problem can be on the retrieving URL, but I
don't understand why, with a Tomcat restart, the metadata is updated
correctly.
Thank you for all the help that you have gave to me.
I appreciate it very much.
Best Regards,
Marco
------------------------------------------------------------
<!-- Metadata Refresh Period
minRefreshDelay == every 5 minutes (default value)
maxRefreshDelay == every 4 hours (default value) -->
<metadata:MetadataProvider id="URLMD-Federation"
xsi:type="metadata:FileBackedHTTPMetadataProvider"
metadataURL="http://www.example.it/metadata/metadata-sha256.xml"
backingFile="/opt/shibboleth-idp/metadata/metadata-sha256.xml">
<metadata:MetadataFilter xsi:type="metadata:ChainingFilter">
<metadata:MetadataFilter xsi:type="metadata:SignatureValidation"
trustEngineRef="shibboleth.MetadataTrustEngine"
requireSignedMetadata="true" />
<metadata:MetadataFilter xsi:type="EntityRoleWhiteList">
<metadata:RetainedRole>samlmd:SPSSODescriptor</metadata:RetainedRole>
</metadata:MetadataFilter>
</metadata:MetadataFilter>
</metadata:MetadataProvider>
</metadata:MetadataProvider>
10:58:58.125 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:253]
- Beginning refresh of metadata from
'http://www.example.it/metadata/metadata-sha256.xml'
10:58:58.126 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:249] -
Attempting to fetch metadata document from
'http://www.example.it/metadata/metadata-sha256.xml'
10:58:58.145 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:254] -
Metadata document from
'http://www.example.it/metadata/metadata-sha256.xml' has not changed
since last retrieval
10:58:58.145 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:257]
- Metadata from 'http://www.example.it/metadata/metadata-sha256.xml'
has not changed since last refresh
10:58:58.146 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:327]
- Computing new expiration time for cached metadata from
'http://www.example.it/metadata/metadata-sha256.xml
10:58:58.193 - INFO
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:276]
- Next refresh cycle for metadata provider
'http://www.example.it/metadata/metadata-sha256.xml' will occur on
'2014-08-12T11:58:58.142Z' ('2014-08-12T13:58:58.142+02:00' local time)
--------------------------------------------------------------------------------------------------------------

Post by Cantor, Scott

Post by Marco Malavolti
Yes, I have set these so low in order to reproduce the issue more
- minRefreshDelay="PT5M"
- maxRefreshDelay="PT4H"

Then your file has a last-modified value that's older than every time it
runs a check. Trust me, it works, so the only way it's not working is if
you're essentially forcibly causing the race condition every time. Your
tests won't mean anything unless you keep the timestamp on the file new
enough to trigger a load.
What you want is for the file time to be essentially the exact time you
update the file, not the actual time the file was last changed at the
source.
Basically, either change your file update process, or switch to the HTTP
versions.
-- Scott

[Cantor, Scott]

Post by Marco Malavolti
and, I'm not sure it is important, I haven't restarted the VM after
apply the new /etc/environments

You can't change Java options like heap size without restarting Tomcat.
Apart from that, I have no idea what your issue is.

-- Scott

[Marco Malavolti]

SOLUTION (for my use case):

I have found that the JAVA_OPTS option was not applied to the Tomcat7
environment because I have not set up it on the /etc/default/tomcat7 file.

So, I have applied this JAVA_OPTS string to that file without any other
changes:

JAVA_OPTS="-Djava.awt.headless=true -XX:+DisableExplicitGC
-XX:+UseParallelOldGC -Xms256m -Xmx2g -XX:MaxPermSize=512m"

and it works!!!!

At the end I had not need to change the opensaml library and its
dependencies, but only change the JAVA_OPTS for Tomcat7.

I hope that this solution could be useful to other peoples.

Thank you for all your help!!!
Marco

Post by Marco Malavolti
Hi to all, I hope you are fine. :)
metadata:FileBackedHTTPMetadataProvider) of my IDP.
- Ubuntu 12.04.4 LTS
- Tomcat 7.0.26-1ubuntu
- Shibboleth IdP 2.4.0 installed
- I have updated my openSAML jar to the version 2.6.1 because I have
https://issues.shibboleth.net/jira/browse/JOST-220
<!-- Metadata Refresh Period
minRefreshDelay == every 1 minutes
maxRefreshDelay == every 3 minutes -->
<metadata:MetadataProvider id="URLMD-Federation"
xsi:type="metadata:FileBackedHTTPMetadataProvider"
minRefreshDelay="PT1M"
maxRefreshDelay="PT3M"
metadataURL="http://www.example.it/metadata-sha256.xml"
backingFile="/opt/shibboleth-idp/metadata/metadata-sha256.xml">
<metadata:MetadataFilter xsi:type="metadata:ChainingFilter">
<metadata:MetadataFilter
xsi:type="metadata:RequiredValidUntil" maxValidityInterval="P5D" />
<metadata:MetadataFilter
xsi:type="metadata:SignatureValidation"
trustEngineRef="shibboleth.MetadataTrustEngine"
requireSignedMetadata="true" />
</metadata:MetadataFilter>
</metadata:MetadataProvider>
Into my environment the Federation's metadata are signed every day
and, in the same time, the EntitiesDescriptor acquires a new
validUntil value valid for the next 5 days.
Is it possible that with this configuration my IdP doesn't retrieve
Beginning refresh of metadata from
'http://www.example.it/metadata-sha256.xml'
12:51:59.446 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:249] -
Attempting to fetch metadata document from
'http://www.example.it/metadata-sha256.xml'
12:51:59.452 - DEBUG
[org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:254] -
Metadata document from 'http://www.example.it/metadata-sha256.xml' has
not changed since last retrieval
12:51:59.452 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:257]
- Metadata from 'http://www.example.it/metadata-sha256.xml' has not
changed since last refresh
12:51:59.452 - DEBUG
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:327]
- Computing new expiration time for cached metadata from
'http://www.example.it/metadata-sha256.xml
12:51:59.453 - INFO
[org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:276]
- Next refresh cycle for metadata provider
'http://www.example.it/metadata-sha256.xml' will occur on
'2014-08-11T10:54:14.447Z' ('2014-08-11T12:54:14.447+02:00' local time)
when the backingFile metadata file is different or not exists?
I have switched off my firewall so that any ports are blocked.
I have tried to understand something on the "idp-process.log" into
DEBUG mode without success because any ERROR appears on it.
I have tried to understand something on Tomcat7 "catalina.out"
(without success because I haven't found any useful information to
resolve this problem)
I have tried to force the download of the remote source metadata by
changing something into the backingFile file. Nothing to do.
I have found that the unique way that I have to correctly retrieve the
remote metadata source file into its backingFile metadata is restart
the Tomcat7 container.
I have understood that the "metadata:FileBackedHTTPMetadataProvider"
works like its brother "metadata:HTTPMetadataProvider", but I have not
understood why the local/backingFile metadatas isn't come updated when
it is different from the remote one.
Help me, please!
Best Regards,
Marco Malavolti
P.S.: Forgive me for my bad English. If you don't understand me I can
try to explain again in a better way I hope.