[Shib-Dev] New IdP v2.2 Snapshot Available

[Chad La Joie]

I have just released a new version[1] of IdP v2.2 (the 20100616 version).

The main changes in this release focus on metadata fetching and
reloading and include:
- ability to turn off the fail-fast initialization behavior
- reloading of metadata is now done in a background process
- HTTP (and FileBackedHTTP) providers now support:
- gzip and deflate compression
- conditional fetching based on Last-Modified and/or ETag data
- ability to ignore the server's SSL certificate
- HTTP proxy support
- HTTP basic authentication support
- byte-for-byte equality of backup file created by the FileBackedHTTP
provider

The documentation on the site has been updated, though will be reworked
before the release, especially the part describing the reloading process.

I am asking people to *please* test this release, especially the
metadata related items. I've done a fair amount of testing on them, but
quite a lot of the metadata provider code changed so I'd prefer other
people give it a go as well. And if you do test it, please report back
positive test results, I don't want to assume that no news is good news
in this case.

Thanks.

[1]
http://shibboleth.internet2.edu/downloads/maven2/edu/internet2/middleware/shibboleth-identityprovider/2.2.0-SNAPSHOT
--
Chad La Joie
http://itumi.biz
trusted identities, delivered

[Russell Beall]

I installed this in my staging environment, and the first thing I had to do was instrument some more LDAP related classes to the TC config.

That was pretty easy since TC prompted me regarding which classes needed to be added.

Initial results show quite an increase in the load time, not because it was busy, but because it was hanging on something. Then when I try to log into anything, it hangs again. Debug tracing seems to indicate that it is waiting on the LDAP code, for instance, the login attempt seems to hang after the line "Attempting to authenticate user 'beall'". And on startup, it seems to hang just after printing the line "Loading 3 principal connectors". There is a precision to the delay time also, since it is precisely 60 seconds each time for most of the delays, and precisely 120 seconds for several of the authentication attempts.

This happens both with and without TC in the mix.

Perhaps some of my deprecated time specifiers changed the timing somewhere? I noticed that time specifiers which formerly read 60000ms, now print to the log as 60000000ms. I presume that the field specifiers changed from milliseconds to seconds?

Haven't dug much beyond this point yet.

Russ.

[Chad La Joie]

hmm... nothing like that should have changed since the previous
snapshot. Had you tested with that one too or just this snapshot?

[Russell Beall]

This was my first run at trying out any 2.2 instance.

Russ.

[Kevin P. Foote]

Russ

FWIW..

I haven't seen that pause as of yet. I've been using the 2.2.x-SNAPSHOT
for a couple months so far in my test setup. Just updated today to
latest via svn

jdk 1.6.0_16
tomcat 6.0.20
terracotta 3.2.0

------
thanks
kevin.foote

On Thu, 17 Jun 2010, Russell Beall wrote:

-> This was my first run at trying out any 2.2 instance.
->
-> Russ.
->
-> On Jun 17, 2010, at 11:54 AM, Chad La Joie wrote:
->
-> > hmm... nothing like that should have changed since the previous snapshot. Had you tested with that one too or just this snapshot?
-> >
-> > On 6/17/10 2:49 PM, Russell Beall wrote:
-> >> I installed this in my staging environment, and the first thing I had to do was instrument some more LDAP related classes to the TC config.
-> >>
-> >> That was pretty easy since TC prompted me regarding which classes needed to be added.
-> >>
-> >> Initial results show quite an increase in the load time, not because it was busy, but because it was hanging on something. Then when I try to log into anything, it hangs again. Debug tracing seems to indicate that it is waiting on the LDAP code, for instance, the login attempt seems to hang after the line "Attempting to authenticate user 'beall'". And on startup, it seems to hang just after printing the line "Loading 3 principal connectors". There is a precision to the delay time also, since it is precisely 60 seconds each time for most of the delays, and precisely 120 seconds for several of the authentication attempts.
-> >>
-> >> This happens both with and without TC in the mix.
-> >>
-> >> Perhaps some of my deprecated time specifiers changed the timing somewhere? I noticed that time specifiers which formerly read 60000ms, now print to the log as 60000000ms. I presume that the field specifiers changed from milliseconds to seconds?
-> >>
-> >> Haven't dug much beyond this point yet.
-> >>
-> >> Russ.
-> >>
-> >> On Jun 16, 2010, at 6:20 AM, Chad La Joie wrote:
-> >>
-> >>> I have just released a new version[1] of IdP v2.2 (the 20100616 version).
-> >>>
-> >>> The main changes in this release focus on metadata fetching and reloading and include:
-> >>> - ability to turn off the fail-fast initialization behavior
-> >>> - reloading of metadata is now done in a background process
-> >>> - HTTP (and FileBackedHTTP) providers now support:
-> >>> - gzip and deflate compression
-> >>> - conditional fetching based on Last-Modified and/or ETag data
-> >>> - ability to ignore the server's SSL certificate
-> >>> - HTTP proxy support
-> >>> - HTTP basic authentication support
-> >>> - byte-for-byte equality of backup file created by the FileBackedHTTP provider
-> >>>
-> >>> The documentation on the site has been updated, though will be reworked before the release, especially the part describing the reloading process.
-> >>>
-> >>> I am asking people to *please* test this release, especially the metadata related items. I've done a fair amount of testing on them, but quite a lot of the metadata provider code changed so I'd prefer other people give it a go as well. And if you do test it, please report back positive test results, I don't want to assume that no news is good news in this case.
-> >>>
-> >>> Thanks.
-> >>>
-> >>> [1] http://shibboleth.internet2.edu/downloads/maven2/edu/internet2/middleware/shibboleth-identityprovider/2.2.0-SNAPSHOT
-> >>> --
-> >>> Chad La Joie
-> >>> http://itumi.biz
-> >>> trusted identities, delivered
-> >>
-> >>
-> >
-> > --
-> > Chad La Joie
-> > http://itumi.biz
-> > trusted identities, delivered
->
->

[Chad La Joie]

Can you turn on debug logging for the LDAP library and send me a log for
one login? I'll review it with Dan and see if anything stands out.

On 6/17/10 2:49 PM, Russell Beall wrote:

[Russell Beall]

Ok. It seems to be related to a TLS bind because if I turn TLS off, I don't get any delays.

Here is a snippet from startup with TLS on. You can see here the one second interval between the bind and the start of the next line:

14:28:24.617 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:490] - Loading 3 principal connectors
14:28:24.640 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:80] - Bind with the following parameters:
14:28:24.641 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:81] - dn = uscrdn=usc.edu.xxxxxxxxxxxx,ou=accounts,dc=usc,dc=edu
14:28:24.642 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:88] - credential = <suppressed>
14:29:28.478 - INFO [edu.internet2.middleware.shibboleth.common.config.BaseService:179] - shibboleth.AttributeResolver service configuration loaded

And here is a section of the login attempt, also with one second between the search attempt and the resulting data processing:
14:28:34.809 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:294] - Search filter: (uid=beall)
14:28:34.810 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:349] - LDAP data connector gds - Retrieving attributes from LDAP
14:28:34.810 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:80] - Bind with the following parameters:
14:28:34.811 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:81] - dn = uscrdn=usc.edu.xxxxxxxxxxxx,ou=accounts,dc=usc,dc=edu
14:28:34.812 - DEBUG [edu.vt.middleware.ldap.handler.TlsConnectionHandler:88] - credential = <suppressed>
14:28:34.917 - DEBUG [edu.vt.middleware.ldap.Ldap:191] - Search with the following parameters:
14:28:34.918 - DEBUG [edu.vt.middleware.ldap.Ldap:192] - dn = dc=usc,dc=edu
14:28:34.919 - DEBUG [edu.vt.middleware.ldap.Ldap:193] - filter = (uid=beall)
14:28:34.920 - DEBUG [edu.vt.middleware.ldap.Ldap:194] - filterArgs = []
14:28:34.920 - DEBUG [edu.vt.middleware.ldap.Ldap:195] - searchControls = javax.naming.directory.SearchControls@5c3f1224
14:28:34.921 - DEBUG [edu.vt.middleware.ldap.Ldap:196] - handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@30c028cc, edu.vt.middleware.ldap.handler.BinarySearchResultHandler@17b68215, edu.vt.middleware.ldap.handler.EntryDnSearchResultHandler@4f163cdc]
14:29:35.157 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:400] - LDAP data connector gds - Found the following attribute: uid[beall]
14:29:35.190 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.LdapDataConnector:400] - LDAP data connector gds - Found the following attribute: eduPersonPrincipalName[be...@usc.edu]

Russ.

[Scott Cantor]

> Ok. It seems to be related to a TLS bind because if I turn TLS off, I
don't
> get any delays.

May be useless information, but in my experience, delays involving protocols
with certs tend to be something checking a CRL or OCSP endpoint and hanging.

-- Scott

[Chad La Joie]

If it's TLS related you might also want to add the property
-Djavax.net.debug=all to your startup properties. That'll show whats
going on in the TLS handshake too, at least as much as the IdP side knows.

[Daniel Fisher]

What does your DataConnector configuration look like for both TLS and
non-TLS?
Do the LDAP logs shed any light on the problem?

--Daniel Fisher

On 6/17/10 5:47 PM, Russell Beall wrote:

[Russell Beall]

On the LDAP side, by grepping for the particular connection, here is what I see on startup:

[17/Jun/2010:15:37:35 -0700] conn=2252464 op=-1 msgId=-1 - fd=177 slot=177 LDAP connection from 128.125.253.234:35717 to 68.181.195.113
[17/Jun/2010:15:37:35 -0700] conn=2252464 op=0 msgId=1 - EXT oid="1.3.6.1.4.1.1466.20037"
[17/Jun/2010:15:37:35 -0700] conn=2252464 op=0 msgId=1 - RESULT err=0 tag=120 nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate SSL.
[17/Jun/2010:15:37:39 -0700] conn=2252464 op=-1 msgId=-1 - SSL 256-bit AES-256
[17/Jun/2010:15:37:39 -0700] conn=2252464 op=1 msgId=2 - BIND dn="uscrdn=usc.edu.xxxxxxxxxxxxx,ou=accounts,dc=usc,dc=edu" method=128 version=3
[17/Jun/2010:15:37:42 -0700] conn=2252464 op=1 msgId=2 - RESULT err=0 tag=97 nentries=0 etime=4 dn="uscrdn=usc.edu.scfs2kk2,ou=accounts,dc=usc,dc=edu"
[17/Jun/2010:15:38:43 -0700] conn=2252464 op=2 msgId=0 - RESULT err=80 tag=120 nentries=0 etime=61
[17/Jun/2010:15:38:43 -0700] conn=2252464 op=-1 msgId=-1 - closing from 128.125.253.234:35717 - B1 - Client request contains an ASN.1 BER tag that is corrupt or connection aborted -
[17/Jun/2010:15:38:43 -0700] conn=2252464 op=-1 msgId=-1 - closed.

Similar situations occur during login, and multiple connections are made and closed with an error condition. I xxxxxx'ed out the service account DN and my DN, so in the below text, xxxxxxxx is the shib service account, and yyyyyyy denotes my DN (probably didn't need to hide that one...).

[17/Jun/2010:15:42:54 -0700] conn=2252496 op=-1 msgId=-1 - fd=172 slot=172 LDAP connection from 128.125.253.234:35734 to 68.181.195.113
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=0 msgId=1 - EXT oid="1.3.6.1.4.1.1466.20037"
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=0 msgId=1 - RESULT err=0 tag=120 nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate SSL.
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=-1 msgId=-1 - SSL 256-bit AES-256
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=1 msgId=2 - BIND dn="uscrdn=usc.edu.xxxxxxxxxxxxx,ou=accounts,dc=usc,dc=edu" method=128 version=3
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=1 msgId=2 - RESULT err=0 tag=97 nentries=0 etime=0 dn="uscrdn=usc.edu.scfs2kk2,ou=accounts,dc=usc,dc=edu"
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=2 msgId=3 - SRCH base="dc=usc,dc=edu" scope=2 filter="(uid=beall)" attrs="1.1"
[17/Jun/2010:15:42:54 -0700] conn=2252496 op=2 msgId=3 - RESULT err=0 tag=101 nentries=1 etime=0
[17/Jun/2010:15:42:54 -0700] conn=2252497 op=-1 msgId=-1 - fd=176 slot=176 LDAP connection from 128.125.253.234:35735 to 68.181.195.113
[17/Jun/2010:15:42:54 -0700] conn=2252497 op=0 msgId=1 - EXT oid="1.3.6.1.4.1.1466.20037"
[17/Jun/2010:15:42:54 -0700] conn=2252497 op=0 msgId=1 - RESULT err=0 tag=120 nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate SSL.
[17/Jun/2010:15:42:54 -0700] conn=2252497 op=-1 msgId=-1 - SSL 256-bit AES-256
[17/Jun/2010:15:42:54 -0700] conn=2252497 op=1 msgId=2 - BIND dn="uscrdn=usc.edu.yyyyyyyyyyyyyy,ou=accounts,dc=usc,dc=edu" method=128 version=3
[17/Jun/2010:15:42:55 -0700] conn=2252497 op=1 msgId=2 - RESULT err=0 tag=97 nentries=0 etime=1 dn="uscrdn=usc.edu.scrf7xn7,ou=accounts,dc=usc,dc=edu"
[17/Jun/2010:15:43:55 -0700] conn=2252497 op=2 msgId=0 - RESULT err=80 tag=120 nentries=0 etime=60
[17/Jun/2010:15:43:55 -0700] conn=2252497 op=-1 msgId=-1 - closing from 128.125.253.234:35735 - B1 - Client request contains an ASN.1 BER tag that is corrupt or connection aborted -
[17/Jun/2010:15:43:55 -0700] conn=2252497 op=-1 msgId=-1 - closed.
[17/Jun/2010:15:43:55 -0700] conn=2252496 op=3 msgId=4 - SRCH base="dc=usc,dc=edu" scope=2 filter="(uid=beall)" attrs="1.1"
[17/Jun/2010:15:43:55 -0700] conn=2252496 op=3 msgId=4 - RESULT err=0 tag=101 nentries=1 etime=0
[17/Jun/2010:15:44:55 -0700] conn=2252496 op=4 msgId=0 - RESULT err=80 tag=120 nentries=0 etime=60
[17/Jun/2010:15:44:55 -0700] conn=2252496 op=-1 msgId=-1 - closing from 128.125.253.234:35734 - B1 - Client request contains an ASN.1 BER tag that is corrupt or connection aborted -
[17/Jun/2010:15:44:55 -0700] conn=2252496 op=-1 msgId=-1 - closed.
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=-1 msgId=-1 - fd=172 slot=172 LDAP connection from 128.125.253.234:35741 to 68.181.195.113
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=0 msgId=1 - EXT oid="1.3.6.1.4.1.1466.20037"
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=0 msgId=1 - RESULT err=0 tag=120 nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate SSL.
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=-1 msgId=-1 - SSL 256-bit AES-256
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=1 msgId=2 - BIND dn="uscrdn=usc.edu.xxxxxxxxxxxx,ou=accounts,dc=usc,dc=edu" method=128 version=3
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=1 msgId=2 - RESULT err=0 tag=97 nentries=0 etime=0 dn="uscrdn=usc.edu.scfs2kk2,ou=accounts,dc=usc,dc=edu"
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=2 msgId=3 - SRCH base="dc=usc,dc=edu" scope=2 filter="(uid=beall)" attrs=ALL
[17/Jun/2010:15:44:55 -0700] conn=2252509 op=2 msgId=3 - RESULT err=0 tag=101 nentries=1 etime=0
[17/Jun/2010:15:45:56 -0700] conn=2252509 op=3 msgId=0 - RESULT err=80 tag=120 nentries=0 etime=60
[17/Jun/2010:15:45:56 -0700] conn=2252509 op=-1 msgId=-1 - closing from 128.125.253.234:35741 - B1 - Client request contains an ASN.1 BER tag that is corrupt or connection aborted -
[17/Jun/2010:15:45:56 -0700] conn=2252509 op=-1 msgId=-1 - closed.

Russ.

[Russell Beall]

(Meant to send this a while ago but it got stuck in an open mail window... This is the debug printing done with -Djavax.net.debug=all)

--------

Ok. With that debugging parameter on, the IdP startup sequence pauses at this point, and prints to catalina.out:

main, called close()
main, called closeInternal(true)
main, SEND TLSv1 ALERT: warning, description = close_notify
Padded plaintext before ENCRYPTION: len = 32
0000: 01 00 56 C1 79 46 22 CB A4 BF 7D 3D AB 5F D3 39 ..V.yF"....=._.9
0010: AD F5 34 3C 8F 7C 09 09 09 09 09 09 09 09 09 09 ..4<............
main, WRITE: TLSv1 Alert, length = 32
[Raw write]: length = 37
0000: 15 03 01 00 20 C8 F6 39 3D 34 A0 96 2B C0 11 29 .... ..9=4..+..)
0010: EB 3F 37 6B F7 66 89 DA E5 03 32 D7 D5 70 67 E0 .?7k.f....2..pg.
0020: 2C EA 64 04 BA ,.d..
main, waiting for close_notify or alert: state 5

---
Then after 60 secs or so, the rest is printed:
---

[Raw read]: length = 5
0000: 17 03 01 00 40 ....@
[Raw read]: length = 64
0000: 37 BF C9 14 42 5C B5 DC CF A5 87 D5 72 CC 74 29 7...B\......r.t)
0010: B2 4A 9E 94 65 95 19 2C CD 4F B3 5F 28 83 C0 7A .J..e..,.O._(..z
0020: 27 75 02 61 3D A9 E2 40 A0 EB 1C F3 D9 67 6A 50 'u.a=..@.....gjP
0030: FB 1E C7 7D E7 E6 46 5B 2C FC 51 95 81 35 63 3D ......F[,.Q..5c=
Thread-2, READ: TLSv1 Application Data, length = 64
Padded plaintext after DECRYPTION: len = 64
0000: 30 24 02 01 00 78 1F 0A 01 50 04 00 04 00 8A 16 0$...x...P......
0010: 31 2E 33 2E 36 2E 31 2E 34 2E 31 2E 31 34 36 36 1.3.6.1.4.1.1466
0020: 2E 32 30 30 33 36 6A 2A 6F B5 9E C0 A4 E4 D8 1B .20036j*o.......
0030: 75 41 D1 26 74 B2 B7 85 90 08 05 05 05 05 05 05 uA.&t...........
main, received EOFException: ignored
main, called closeInternal(false)
main, close invoked again; state = 5
89.830: [GC 525312K->25629K(2013696K), 0.1485788 secs]
Finalizer, called close()
Finalizer, called closeInternal(true)

Hopefully this will be useful to Dan...

Russ.

[Daniel Fisher]

Can you send a complete trace?
Send it to me directly if you don't want it on the list.
There's definitely something suspicious going on, I'm hoping some of the
handshake details will point to the problem.

--Daniel Fisher

[Russell Beall]

Ok, it is sent off.

Russ.

[Jim Fox]

My first attempt at this gives me an ldap error:

unabled to connect to the ldap
LDAP: error code 7 - SASL(-4): no mechanism available: ]

probably related to how to tell the library that I want EXTERNAL
authentication.

I used (idp 2.1.5) use (in the dataconnector)

<LDAPProperty name="java.naming.security.authentication" value="EXTERNAL" />

Do I ask for SASL a different way now?

Jim

[Daniel Fisher]

<resolver:DataConnector id="myldap" xsi:type="LDAPDirectory"
xmlns="urn:mace:shibboleth:2.0:resolver:dc"
...
authenticationType="EXTERNAL">

--Daniel Fisher

[Jim Fox]

Thanks, the

authenticationType="external"

worked.

It seems now that my local metadata expires as soon as it is loaded. I
get:

Metadata document does not contain an EntityDescriptor with
the ID https://urizen2.cac.washington.edu/

Metadata document contained an EntityDescriptor with the ID
https://urizen2.cac.washington.edu/, but it was no longer valid

on the very first request after the idp starts.

Earlier in the log I see:

Expiration of metadata from '/usr/local/idp/metadata/UW-rp-metadata.xml'
will occur at 2010-06-19T00:26:33.745Z

which would be in about two or three hours. Shouldn't be yet.

I've tried setting the RefreshDelays and even

requireValidMetadata="false"

Is there a default "expire metadata on load" option that I'm failing to reset?

Jim

[Chad La Joie]

Turn on debug logging for org.opensaml.saml2.metadata and see what it says.

--

[Jim Fox]

>
> Turn on debug logging for org.opensaml.saml2.metadata and see what it says.
>

It appeared to be caused by missing saml2 endpoints in the metadata. Just
misleading messages.

When I try to access a postgres DB for tgtid info I get:

....RDBMSDataConnector:335] - RDBMS data connector
[tgtidDB2, select tid('6BB477326A7C11D5A4AE0004AC494FFE', 'https://urizen2.cac.washington.edu/'), 0A000, 0]
Unable to execute SQL query org.postgresql.util.PSQLException:
Method org.postgresql.jdbc3.Jdbc3Statement.setQueryTimeout(int) is not yet
implemented.; SQL State: {}, SQL Code: {}

I can run the select command from psql successfully.

Jim

[Jim Fox]

It seems to be a known issue that the postgres jdbc library distributed
with our java (1.6) doesn't support setQueryTimeout()

Setting the timeout to zero bypasses this issue.

Otherwise it is working fine. I haven't seen any of the ldap delays that
Russell encountered.

Jim

On Fri, 18 Jun 2010, Jim Fox wrote:

> Date: Fri, 18 Jun 2010 14:17:02 -0700
> From: Jim Fox <f...@washington.edu>
> To: "shibbol...@internet2.edu" <shibbol...@internet2.edu>
> Reply-To: "shibbol...@internet2.edu" <shibbol...@internet2.edu>
> Subject: Re: [Shib-Dev] New IdP v2.2 Snapshot Available

[Mahabalagiri, Datta]

I can't get the metadata to reload upon file changes. I don't think it worked me in the previous version either.

<MetadataProvider xsi:type="FilesystemMetadataProvider" xmlns="urn:mace:shibboleth:2.0:metadata"
id="custom"
metadataFile="/path-to-my-metadata/test-metadata.xml" />

Thanks.
Datta

[Chad La Joie]

I appreciate you testing but that's not a very helpful description for
diagnosing the problem. Try doing this:

1. Turn on debug logging for the metadata providers
(org.opensaml.saml2.metadata)

2. Clear our your idp-process log

3. Start the IdP

4. Send me the log

That should give me the information I need to begin to research the issue.

On 6/21/10 4:37 PM, Mahabalagiri, Datta wrote:
> I can't get the metadata to reload upon file changes. I don't think it worked me in the previous version either.
>
> <MetadataProvider xsi:type="FilesystemMetadataProvider" xmlns="urn:mace:shibboleth:2.0:metadata"
> id="custom"
> metadataFile="/path-to-my-metadata/test-metadata.xml" />

--

[Mahabalagiri, Datta]

Sorry. Here is the logs.
It does pick up changes if I set maxRefreshDelay (after the set interval).

relying-party.xml configuration:
<MetadataProvider id="ShibbolethMetadata" xsi:type="ChainingMetadataProvider" xmlns="urn:mace:shibboleth:2.0:metadata">
<MetadataProvider id="IdPMD" xsi:type="ResourceBackedMetadataProvider" xmlns="urn:mace:shibboleth:2.0:metadata" >
<MetadataResource xsi:type="resource:ClasspathResource" file="/conf/idp-metadata.xml"/>
</MetadataProvider>

<MetadataProvider xsi:type="FilesystemMetadataProvider" xmlns="urn:mace:shibboleth:2.0:metadata"

id="custom2"
metadataFile="/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/custom/custom-metadata.xml" />
</MetadataProvider>

2010-06-21-14:00:57.694 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:57.702 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:57.708 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:57.719 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:57.752 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:57.812 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:57.818 - [] - INFO [org.opensaml.xml.XMLConfigurator:189] - Preparing to load ValidatorSuites
2010-06-21-14:00:57.835 - [] - INFO [org.opensaml.xml.XMLConfigurator:191] - ValidatorSuites load complete
2010-06-21-14:00:57.852 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:57.890 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:57.894 - [] - INFO [org.opensaml.xml.XMLConfigurator:189] - Preparing to load ValidatorSuites
2010-06-21-14:00:57.901 - [] - INFO [org.opensaml.xml.XMLConfigurator:191] - ValidatorSuites load complete
2010-06-21-14:00:57.904 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:57.916 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:57.919 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:57.927 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:57.938 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.034 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.042 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.061 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.073 - [] - INFO [org.opensaml.xml.XMLConfigurator:189] - Preparing to load ValidatorSuites
2010-06-21-14:00:58.084 - [] - INFO [org.opensaml.xml.XMLConfigurator:191] - ValidatorSuites load complete
2010-06-21-14:00:58.121 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.167 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.176 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.234 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.237 - [] - INFO [org.opensaml.xml.XMLConfigurator:189] - Preparing to load ValidatorSuites
2010-06-21-14:00:58.260 - [] - INFO [org.opensaml.xml.XMLConfigurator:191] - ValidatorSuites load complete
2010-06-21-14:00:58.262 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.263 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.275 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.343 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.352 - [] - INFO [org.opensaml.xml.XMLConfigurator:189] - Preparing to load ValidatorSuites
2010-06-21-14:00:58.373 - [] - INFO [org.opensaml.xml.XMLConfigurator:191] - ValidatorSuites load complete
2010-06-21-14:00:58.374 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.376 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.377 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.378 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.381 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.387 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.391 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.394 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.396 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.401 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.402 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.411 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.412 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.413 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.416 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.440 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.453 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.507 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.509 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.510 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.512 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.512 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.514 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.540 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.542 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.591 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.592 - [] - INFO [org.opensaml.xml.XMLConfigurator:198] - Preparing to load IDAttributes
2010-06-21-14:00:58.592 - [] - INFO [org.opensaml.xml.XMLConfigurator:200] - IDAttributes load complete
2010-06-21-14:00:58.616 - [] - INFO [org.opensaml.xml.XMLConfigurator:180] - Preparing to load ObjectProviders
2010-06-21-14:00:58.621 - [] - INFO [org.opensaml.xml.XMLConfigurator:182] - ObjectProviders load complete
2010-06-21-14:00:58.630 - [] - INFO [org.apache.velocity.app.VelocityEngine:49] - LogSystem has been deprecated. Please use a LogChute implementation.
2010-06-21-14:00:58.915 - [] - WARN [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.ComputedIDDataConnector:64] - This data connector is deprecated. The StoredID data connector should be used in its place.
2010-06-21-14:01:02.233 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:231] - Beginning refresh of metadata from 'file:/usr/local/apache-tomcat-6.0.18/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.234 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:241] - Processing new metadata from 'file:/usr/local/apache-tomcat-6.0.18/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.234 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:323] - Unmarshalling metadata from 'file:/usr/local/apache-tomcat-6.0.18/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.289 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:327] - Filtering metadata from 'file:/usr/local/apache-tomcat-6.0.18/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.289 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:336] - Releasing cached DOM for metadata from 'file:/usr/local/apache-tomcat-6.0.18/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.290 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:339] - Post-processing metadata from 'file:/usr/local/apache-tomcat-6.0.18/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.290 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:342] - Computing expiration time for metadata from 'file:/usr/local/apache-tomcat-6.0.18/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.291 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:345] - Expiration of metadata from 'file:/usr/local/apache-tomcat-6.0.18/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml' will occur at 2010-06-22T01:01:02.233Z
2010-06-21-14:01:02.292 - [] - INFO [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:243] - New metadata loaded from 'file:/usr/local/apache-tomcat-6.0.18/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml', next refresh will occur at approximately 2010-06-22T00:01:02.248Z
2010-06-21-14:01:02.297 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:231] - Beginning refresh of metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/custom/custom-metadata.xml'
2010-06-21-14:01:02.297 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:241] - Processing new metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/custom/custom-metadata.xml'
2010-06-21-14:01:02.297 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:323] - Unmarshalling metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/custom/custom-metadata.xml'
2010-06-21-14:01:02.301 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:327] - Filtering metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/custom/custom-metadata.xml'
2010-06-21-14:01:02.302 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:336] - Releasing cached DOM for metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/custom/custom-metadata.xml'
2010-06-21-14:01:02.302 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:339] - Post-processing metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/custom/custom-metadata.xml'
2010-06-21-14:01:02.302 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:342] - Computing expiration time for metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/custom/custom-metadata.xml'
2010-06-21-14:01:02.302 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:345] - Expiration of metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/custom/custom-metadata.xml' will occur at 2010-06-22T01:01:02.297Z
2010-06-21-14:01:02.303 - [] - INFO [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:243] - New metadata loaded from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/custom/custom-metadata.xml', next refresh will occur at approximately 2010-06-22T00:01:02.299Z
2010-06-21-14:01:02.519 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:231] - Beginning refresh of metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.531 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:241] - Processing new metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.532 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:323] - Unmarshalling metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.533 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:327] - Filtering metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.533 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:336] - Releasing cached DOM for metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.534 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:339] - Post-processing metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.534 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:342] - Computing expiration time for metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml'
2010-06-21-14:01:02.535 - [] - DEBUG [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:345] - Expiration of metadata from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml' will occur at 2010-06-22T01:01:02.519Z
2010-06-21-14:01:02.535 - [] - INFO [org.opensaml.saml2.metadata.provider.AbstractReloadingMetadataProvider:243] - New metadata loaded from '/usr/local/tomcat6/webapps/idp/WEB-INF/classes/conf/idp-metadata.xml', next refresh will occur at approximately 2010-06-22T00:01:02.523Z

Datta

[Chad La Joie]

If you don't set maxRefreshDelay then it defaults to 4 hours. Did you
wait that long to see if it rescanned the file? And if you did are you
saying that it did not pick up the changes?

[Mahabalagiri, Datta]

I didn't wait 4 hours. I misread the documentation. I thought it would reload as soon as file changes. I guess it scans file system at maxRefreshDelay intervals?

Datta

> -----Original Message-----
> From: shibboleth-...@internet2.edu [mailto:shibboleth-dev-
> req...@internet2.edu] On Behalf Of Chad La Joie
> Sent: Monday, June 21, 2010 2:37 PM
> To: shibbol...@internet2.edu
> Subject: Re: [Shib-Dev] New IdP v2.2 Snapshot Available
>

[Chad La Joie]

Take a look at the documentation, it tries to explain the algorithm used
to determined the next refresh cycle and the log itself tells you the
time when the next refresh will occur.

On 6/21/10 6:23 PM, Mahabalagiri, Datta wrote:
> I didn't wait 4 hours. I misread the documentation. I thought it would reload as soon as file changes. I guess it scans file system at maxRefreshDelay intervals?

[Etienne Dysli]

I have installed this snapshot (20100616) in my testing environment.
After clearing some configuration errors and warnings, I ran into this
error (full stack trace omitted):

2010-06-28 15:45:42,751 - ERROR
[edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:135]
- Unable to redirect to login page.
javax.servlet.ServletException: java.lang.NoClassDefFoundError:
org/apache/taglibs/standard/tag/rt/core/SetTag

Are we supposed to have the JSTL JARs installed or should they be part
of the distributed IdP package?

Regards,
Etienne

[Chad La Joie]

Do you use the JSTL in your login.jsp, the default one doesn't?

--

[Etienne Dysli]

Chad La Joie wrote:
> Do you use the JSTL in your login.jsp, the default one doesn't?

Yes, I do use JSTL in my custom JSPs. But the catch is that I haven't
installed them in this 2.2 instance yet... The error vanished after
clearing Tomcat's work directory though.

Regards,
Etienne

[Chad La Joie]

I know you've been in the room before when I've mentioned how much I
hate how Tomcat does it's "caching" of things...

--

[Etienne Dysli]

Chad La Joie wrote:
> I know you've been in the room before when I've mentioned how much I
> hate how Tomcat does it's "caching" of things...

;)

[Yang Xiang]

Hi,

I installed the v2.2 snapshot today and got some errors regarding
REMOTE_USER. The same configuration (of IdP and SP) worked fine with IdP
v2.1.5. Following are the error messages:
----------------------------------
14:02:23.471 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:459] - Resolving attributes for principal 'yang' for SAML request from relying party 'http://localhost/test-sp1'
14:02:23.472 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:118] - shibboleth.AttributeResolver resolving attributes for principal yang
14:02:23.472 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:249] - Specific attributes for principal yang were not requested, resolving all attributes.
14:02:23.472 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:285] - Resolving attribute transientId for principal yang
14:02:23.473 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:307] - Resolved attribute transientId containing 1 values
14:02:23.474 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:136] - shibboleth.AttributeResolver resolved, for principal yang, the attributes: [transientId]
14:02:23.474 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:70] - shibboleth.AttributeFilterEngine filtering 1 attributes for principal yang
14:02:23.474 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:122] - Evaluating if filter policy releaseTransientIdToAnyone is active for principal yang
14:02:23.474 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:131] - Filter policy releaseTransientIdToAnyone is active for principal yang
14:02:23.475 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:156] - Processing permit value rule for attribute transientId for principal yang
14:02:23.475 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.filtering.provider.ShibbolethAttributeFilteringEngine:106] - Filtered attributes for principal yang. The following attributes remain: [transientId]
14:02:23.477 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:487] - Creating attribute statement in response to SAML request '_155999400e33f99c476b5b28cac39a52' from relying party 'http://localhost/test-sp1'
14:02:23.477 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML2AttributeAuthority:225] - Attribute transientId was not encoded because no SAML2AttributeEncoder was attached to it.
14:02:23.478 - DEBUG
[edu.internet2.middleware.shibboleth.common.attribute.provider.ShibbolethSAML2AttributeAuthority:127] - No attributes remained after encoding and filtering by value, no attribute statement built
14:02:23.482 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler:825] - Attemping to build NameID for principal 'yang' in response to request from relying party 'http://localhost/test-sp1
14:02:23.482 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:514] - Relying party 'http://localhost/test-sp1' supports the name formats: [urn:mace:shibboleth:1.0:nameIdentifier]
14:02:23.482 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:446] - Relying party 'http://localhost/test-sp1' supports the name formats: [urn:mace:shibboleth:1.0:nameIdentifier]
14:02:23.482 - DEBUG
[edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler:458] - No attributes for principal 'yang' supports encoding into a supported NameIdentifier format for relying party 'http://localhost/test-sp1'
14:02:23.487 - ERROR
[edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet:88] - Error occured while processing request
java.lang.NullPointerException: null
at
edu.internet2.middleware.shibboleth.idp.profile.saml2.AbstractSAML2ProfileHandler.buildNameId(AbstractSAML2ProfileHandler.java:837) [shibboleth-identityprovider-2.2.0-SNAPSHOT.jar:na]
at
edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler.buildNameId(SSOProfileHandler.java:584) [shibboleth-identityprovider-2.2.0-SNAPSHOT.jar:na]

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

I just noticed that the error was caused by the method
edu.internet2.middleware.shibboleth.idp.profile.AbstractSAMLProfileHandler.selectNameIDAttributeAndEncoder(Class<T>, BaseSAMLProfileRequestContext) while no encoder could be found.

This is not a config error, isn't it?

Yang

[Chad La Joie]

No, that was a bug in the IdP, it's already been fixed. It occurs when
your configuration results in request that would not include in a NameID
(likely because the attribute that would have been encoded in that way
is filtered out).

--