Metarefresh fails to process edugain metadata

[Olivier Salaün]

Hi,

I hope this is the right place to submit issues; I could not find simpleSAMLphp's bug tracker.

I am using simpleSAMLphp 1.13.2.

I enabled the metarefresh module and configured it to load RENATER's Test federation metadata and eduGAIN metadata, see the attached config-metarefresh.php file.
I then ran simpleSAML's cron.php?tag=hourly to trigger metadata refresh. RENATER's Test federation metadata get loaded and PHP files representing the corresponding SAML entities get created in metadata/ directory. I also find evidences in simplesaml lig file that it went well:

Feb  4 15:34:02 pan simplesamlphp[6544]: 7 [74f1277e4a] cron [metarefresh]: In set [renatertest] loading source [h
ttps://federation.renater.fr/test/renater-test-metadata.xml]
Feb  4 15:34:15 pan simplesamlphp[6544]: 7 [74f1277e4a] Writing: /opt/testidp/simplesamlphp-1.13.2/metadata/metadata-renater-test/saml20-idp-remote.php

But eduGAIN metadata fail to load. metadata/ directory doesn't get populated, limited traced in simplesaml log file:

Feb  4 15:34:16 pan simplesamlphp[6544]: 6 [74f1277e4a] cron [metarefresh]: Executing set [edugain]
Feb  4 15:34:16 pan simplesamlphp[6544]: 7 [74f1277e4a] cron [metarefresh]: In set [edugain] loading source [http://mds.edugain.org/]

It seems that the code dies silently.

I started adding traces to the code, that dies within SAMLParser::processDescriptorsElement().
I did not go ahead because I miss a proper Php debugger.

Is this a known issue of 1.13.2 version?
Any suggestion to get round it?

Thanks.

--

Olivier Salaün Etudes et projets applicatifs
Tél : +33 2 23 23 71 27 Fax : +33 2 23 23 71 11 www.renater.fr	RENATER 263 Avenue du Gal Leclerc 35042 Rennes Cedex

[GALAMBOS Daniel]

Hi,

I run a little older (1.12) version, parsing the edugain costs around
half a GB RAM and a lot of time.
You may hit the PHP max_execute_time or memory_limit configure options.

(I know the metadata parsing improved since then.)
--
Galambos Daniel

> *Olivier Salaün*

> Etudes et projets applicatifs
>
> Tél : +33 2 23 23 71 27
> Fax : +33 2 23 23 71 11

> www.renater.fr <http://www.renater.fr>

> RENATER
> 263 Avenue du Gal Leclerc
> 35042 Rennes Cedex
>
>
>

> --
> You received this message because you are subscribed to the Google
> Groups "simpleSAMLphp" group.
> To unsubscribe from this group and stop receiving emails from it, send
> an email to simplesamlph...@googlegroups.com
> <mailto:simplesamlph...@googlegroups.com>.
> To post to this group, send email to simple...@googlegroups.com
> <mailto:simple...@googlegroups.com>.
> Visit this group at http://groups.google.com/group/simplesamlphp.
> For more options, visit https://groups.google.com/d/optout.

[Jaime Perez Crespo]

Hi Olivier!

> On 04 Feb 2015, at 16:34 pm, Olivier Salaün <olivier...@renater.fr> wrote:
> Hi,
>
> I hope this is the right place to submit issues; I could not find simpleSAMLphp's bug tracker.

We’ve been using github’s issue tracker since we moved there:

https://github.com/simplesamlphp/simplesamlphp/issues

> I am using simpleSAMLphp 1.13.2.
>
> I enabled the metarefresh module and configured it to load RENATER's Test federation metadata and eduGAIN metadata, see the attached config-metarefresh.php file.
> I then ran simpleSAML's cron.php?tag=hourly to trigger metadata refresh. RENATER's Test federation metadata get loaded and PHP files representing the corresponding SAML entities get created in metadata/ directory. I also find evidences in simplesaml lig file that it went well:
> Feb 4 15:34:02 pan simplesamlphp[6544]: 7 [74f1277e4a] cron [metarefresh]: In set [renatertest] loading source [h
> ttps://federation.renater.fr/test/renater-test-metadata.xml]
> Feb 4 15:34:15 pan simplesamlphp[6544]: 7 [74f1277e4a] Writing: /opt/testidp/simplesamlphp-1.13.2/metadata/metadata-renater-test/saml20-idp-remote.php
> But eduGAIN metadata fail to load. metadata/ directory doesn't get populated, limited traced in simplesaml log file:
> Feb 4 15:34:16 pan simplesamlphp[6544]: 6 [74f1277e4a] cron [metarefresh]: Executing set [edugain]
> Feb 4 15:34:16 pan simplesamlphp[6544]: 7 [74f1277e4a] cron [metarefresh]: In set [edugain] loading source [http://mds.edugain.org/]
> It seems that the code dies silently.

Did you take a look at your web server’s error log? If SSP is dying it’s obviously not gonna print out anything to its log file, but you should find the reason for it dying at the error log.

> I started adding traces to the code, that dies within SAMLParser::processDescriptorsElement().
> I did not go ahead because I miss a proper Php debugger.
>
> Is this a known issue of 1.13.2 version?

There is a known issue with XML canonicalization in PHP, that makes the complexity to grow quadratically. That means a huge increase in the number of entities to canonicalize, means also an unaffordable increase of time for execution. 1.13.2 contains a workaround in xmlseclibs to avoid this problem, but your web server needs to be set up with enough memory to process a metadata file as big as eduGAIN’s. So yeah, as Daniel was saying, looks like you’ve been bitten but your own memory limit. Try increasing both the maximum execution time and the memory limit and run metarefresh again.

--
Jaime Pérez
UNINETT / Feide
mail: jaime...@uninett.no
xmpp: ja...@jabber.uninett.no

"Two roads diverged in a wood, and I, I took the one less traveled by, and that has made all the difference."
- Robert Frost

[Olivier Salaün]

Hi Jaime,

Le 05/02/2015 12:38, Jaime Perez Crespo a écrit :

Hi Olivier!

On 04 Feb 2015, at 16:34 pm, Olivier Salaün <olivier...@renater.fr> wrote:
Hi,

I hope this is the right place to submit issues; I could not find simpleSAMLphp's bug tracker.

We’ve been using github’s issue tracker since we moved there:

https://github.com/simplesamlphp/simplesamlphp/issues

I found it afterward, sorry.

I am using simpleSAMLphp 1.13.2.

I enabled the metarefresh module and configured it to load RENATER's Test federation metadata and eduGAIN metadata, see the attached config-metarefresh.php file.
I then ran simpleSAML's cron.php?tag=hourly to trigger metadata refresh. RENATER's Test federation metadata get loaded and PHP files representing the corresponding SAML entities get created in metadata/ directory. I also find evidences in simplesaml lig file that it went well:
Feb  4 15:34:02 pan simplesamlphp[6544]: 7 [74f1277e4a] cron [metarefresh]: In set [renatertest] loading source [h
ttps://federation.renater.fr/test/renater-test-metadata.xml]
Feb  4 15:34:15 pan simplesamlphp[6544]: 7 [74f1277e4a] Writing: /opt/testidp/simplesamlphp-1.13.2/metadata/metadata-renater-test/saml20-idp-remote.php
But eduGAIN metadata fail to load. metadata/ directory doesn't get populated, limited traced in simplesaml log file:
Feb  4 15:34:16 pan simplesamlphp[6544]: 6 [74f1277e4a] cron [metarefresh]: Executing set [edugain]
Feb  4 15:34:16 pan simplesamlphp[6544]: 7 [74f1277e4a] cron [metarefresh]: In set [edugain] loading source [http://mds.edugain.org/]
It seems that the code dies silently.

Did you take a look at your web server’s error log? If SSP is dying it’s obviously not gonna print out anything to its log file, but you should find the reason for it dying at the error log.

Eventually I found errors in Apache log files including this one :

[Thu Feb 05 16:52:47 2015] [error] [client 195.220.94.108] PHP Fatal error:  Allowed memory size of 536870912 bytes exhausted (tried to allocate 479989761 bytes) in /opt/testidp/simplesamlphp/modules/metarefresh/lib/MetaLoader.php on line 98

I then increased PhP's memory_limit to 512M.
I don't get that error anymore, but metarefresh still does not create output files for eduGAIN.

I started adding traces to the code, that dies within SAMLParser::processDescriptorsElement().
I did not go ahead because I miss a proper Php debugger.

Is this a known issue of 1.13.2 version?

There is a known issue with XML canonicalization in PHP, that makes the complexity to grow quadratically. That means a huge increase in the number of entities to canonicalize, means also an unaffordable increase of time for execution. 1.13.2 contains a workaround in xmlseclibs to avoid this problem, but your web server needs to be set up with enough memory to process a metadata file as big as eduGAIN’s. So yeah, as Daniel was saying, looks like you’ve been bitten but your own memory limit. Try increasing both the maximum execution time and the memory limit and run metarefresh again.

I changed Php configuration with:

• memory_limit = 512M
• max_execution_time = 300     

But parsing of eduGAIN metadata still fails.

How do other institutions part of eduGAIN cope with this?
Runing metadata parsing on a different server like Terena?
If so, are they using a standard simpleSAMLphp? using metarefresh.php script?

[Jaime Perez Crespo]

Hi,

> On 05 Feb 2015, at 17:09 pm, Olivier Salaün <olivier...@renater.fr> wrote:
>> https://github.com/simplesamlphp/simplesamlphp/issues
> I found it afterward, sorry.

No prob!

> Eventually I found errors in Apache log files including this one :
> [Thu Feb 05 16:52:47 2015] [error] [client 195.220.94.108] PHP Fatal error: Allowed memory size of 536870912 bytes exhausted (tried to allocate 479989761 bytes) in /opt/testidp/simplesamlphp/modules/metarefresh/lib/MetaLoader.php on line 98
> I then increased PhP's memory_limit to 512M.
> I don't get that error anymore, but metarefresh still does not create output files for eduGAIN.

Nor any other errors? Neither in apache logs or in SSP logs? That’s strange...

> I changed Php configuration with:
> • memory_limit = 512M
> • max_execution_time = 300
> But parsing of eduGAIN metadata still fails.

The memory limit is actually the same I have in my virtual machines, where I test SSP. The max_execution_time should be enough I think, but that could be the problem. In any reasonable machine it shouldn’t take more than 5 minutes, but I would just increase it and try again.

> How do other institutions part of eduGAIN cope with this?

I forgot in my previous email to add a link to a notice we published on SSP’s website some time ago:

https://simplesamlphp.org/metaprocessing

> Runing metadata parsing on a different server like Terena?

That’s an option, though with the patched xmlseclibs it shouldn’t be necessary.

> If so, are they using a standard simpleSAMLphp? using metarefresh.php script?

Yes, it should just work. I’ve just tried in my local installation running on a virtual machine (which is therefore a bit limited) and consumption of eduGAIN metadata (with metarefresh) completed successfully in a bit more than a minute. So I don’t see any reason why it shouldn’t work for you...

[Olivier Salaün]

Hello,

Le 05/02/2015 17:45, Jaime Perez Crespo a écrit :

[...]

Eventually I found errors in Apache log files including this one :
[Thu Feb 05 16:52:47 2015] [error] [client 195.220.94.108] PHP Fatal error:  Allowed memory size of 536870912 bytes exhausted (tried to allocate 479989761 bytes) in /opt/testidp/simplesamlphp/modules/metarefresh/lib/MetaLoader.php on line 98
I then increased PhP's memory_limit to 512M.
I don't get that error anymore, but metarefresh still does not create output files for eduGAIN.

Nor any other errors? Neither in apache logs or in SSP logs? That’s strange...

I started debugging the code with xdebug.
I figured out that, while loading http://mds.edugain.org, within MetaLoader::loadDource() the addMetadata() calls aren't executed. In the end $hook_cron::metaloader variable is empty. But I need to try again with a clean code, since I've added lots of traces in the code...

I changed Php configuration with:
	• memory_limit = 512M
	• max_execution_time = 300
But parsing of eduGAIN metadata still fails.

The memory limit is actually the same I have in my virtual machines, where I test SSP. The max_execution_time should be enough I think, but that could be the problem. In any reasonable machine it shouldn’t take more than 5 minutes, but I would just increase it and try again.

While loading /simplesaml/module.php/cron/cron.php I don't have a timeout, but the php metadata files just don't get created.

How do other institutions part of eduGAIN cope with this?

I forgot in my previous email to add a link to a notice we published on SSP’s website some time ago:

https://simplesamlphp.org/metaprocessing

I managed to find this page, but thanks for mentioning it.

Runing metadata parsing on a different server like Terena?

That’s an option, though with the patched xmlseclibs it shouldn’t be necessary.

In the end I've adopted a different approach: because I run simpleSAMLphp as an Identity Provider, I don't need SAML description of SPs. Therefore I produced a different metadata file with eduGAIN SPs only, using pyff.

Now simpleSAML loads that metadata file and generates the expected saml20-sp-remote.php and shib13-sp-remote.php files.
Houra !

If so, are they using a standard simpleSAMLphp? using metarefresh.php script?

Yes, it should just work. I’ve just tried in my local installation running on a virtual machine (which is therefore a bit limited) and consumption of eduGAIN metadata (with metarefresh) completed successfully in a bit more than a minute. So I don’t see any reason why it shouldn’t work for you...

Can you precise from what URL your download the eduGAIN metadata?
I suppose it's a downstream version, published by your federation? If so, its content may be slightly different than http://mds.edugain.org.
Maybe you can try configuring your config-metarefresh.php with config-metarefresh.php to ensure it loads well.

As I wrote above, I also need to have another try after I've cleaned up the simpleSAMLphp code I'm running. It's now full of additional traces.
If the metadata problems persists afterward, I'll submit a bug via the bug tracker.

Thanks for your help, Jaime.

[Jaime Perez Crespo]

Hi Olivier!

> On 06 Feb 2015, at 17:06 pm, Olivier Salaün <olivier...@renater.fr> wrote:
> I started debugging the code with xdebug.

> I figured out that, while loading http://mds.edugain.org, within MetaLoader::loadDource() the addMetadata() calls aren't executed. In the end $hook_cron::metaloader variable is empty. But I need to try again with a clean code, since I've added lots of traces in the code…

Have you checked if it at least iterates over the entities? You don’t get any logs? I suspect it’s dying during the call to loadXML(), which is coherent with the previous diagnosis.

> While loading /simplesaml/module.php/cron/cron.php I don't have a timeout, but the php metadata files just don't get created.

I think it’s the same problem here. But of course when you are running from cron there’s no apache server where to throw your logs at.

> In the end I've adopted a different approach: because I run simpleSAMLphp as an Identity Provider, I don't need SAML description of SPs. Therefore I produced a different metadata file with eduGAIN SPs only, using pyff.
>
> Now simpleSAML loads that metadata file and generates the expected saml20-sp-remote.php and shib13-sp-remote.php files.
> Houra !

So it’s clearly a performance issue then...

> Can you precise from what URL your download the eduGAIN metadata?
> I suppose it's a downstream version, published by your federation? If so, its content may be slightly different than http://mds.edugain.org.
> Maybe you can try configuring your config-metarefresh.php with config-metarefresh.php to ensure it loads well.

Yes, that’s what I did. I already have a config file with multiple sources from many federations to be able to test changes properly, so I just tried with eduGAIN’s feed. I’m using the canonical URL of the MDS, so the same as you then.

> As I wrote above, I also need to have another try after I've cleaned up the simpleSAMLphp code I'm running. It's now full of additional traces.
> If the metadata problems persists afterward, I'll submit a bug via the bug tracker.

I’d try setting up a clean instance of SSP 1.13.2, configuring metarefresh and see if it works then.

> Thanks for your help, Jaime.

No problem! Have a nice weekend!