Metadata Typo Causes Integration Headaches

[Brent Putman]

Hi Marvin,


> 2. Metadata-based credential resolution is complicated by filtering
> that can reduce the effective key set from what's patently defined in
> metadata XML files.

Yes, absolutely, there's a layer that filters credentials by the
supplied criteria.  But I don't think that's what was going on here... 
See below

> 3. IdP logging in the credential resolution process could be improved.

Probably, but I'd like to understand exactly what happened

> After I saw that initially, I was satisfied that metadata resolution
> was working as intended. That turned out to be a big mistake that cost
> a lot of wasted time. The breakthrough came when we revisited the logs
> after running out of leads with the vendor and we noticed that no
> matter what logging categories we turned up we never saw any log
> entries for the actual signature verification attempt. Code review
> suggested that could be caused by failure to find any trusted
> certificates, then we finally realized that the resolved metadata
> entry was being further filtered:
>
> 2018-09-17 12:36:58,073 DEBUG
> org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:376
> 1.2.3.4 Attempting to filter candidate RoleDescriptors via resolved
> Predicates
> 2018-09-17 12:36:58,073 DEBUG
> org.opensaml.saml.metadata.resolver.impl.PredicateRoleDescriptorResolver:398
> 1.2.3.4 After predicate filtering 1 RoleDescriptors remain

Yes.  The RoleDescriptorResolver's purpose is to extract
RoleDescriptors from EntityDescriptor, usually just based on role QName
and protocol (and/or theoretically other things, but nothing else is
actually configured by default).

>
> There's a similar process for applying role criteria, 
I think  you mean Credential criteria...

> which includes
> key usage and key algorithm selectors. Unfortunately there's no
> equivalent log output like the one above that indicates how many
> elements remain after criteria selection, but we could infer that
> something about the key criteria was likely preventing our key from
> being resolved. That led us to review metadata where we noticed an
> incorrect XML namespace on the KeyInfo element and children;
> correcting that problem fixed everything.

There is indeed an entire layer in most of the CredentialResolver impls
that can further filter the returned Credentials using
Predicate<Credential> (either directly supplied or derived from
Criterion beans. See AbstractCriteriaFilteringCredentialResolver.  I
looked and we don't have any logging on the pre and post filtering
numbers.

However, from what you describe about the erroneous KeyInfo XML
namespace, I don't think that was what was actually happening here.  I
think that the MetadataCredentialResolver was fundamentally unable to
"see" the KeyInfo data, since it could not have been unmarshalled
correctly.  I think you would see log output from the below about an
unknown child XMLObject from the KeyDescriptorUnmarshaller:

log.debug("Ignoring unknown child element {}",
childXMLObject.getElementQName());

Then based on that, the KeyDescriptor's KeyInfo instance would have
been null, and I think this should have resulted in some output from
the KeyInfoCredentialResolver (used by the MCR) like so:

log.info("KeyInfo was null, any credentials will be resolved by
post-processing hooks only");

And then later, also from the KICR:

log.debug("A total of {} credentials were resolved", credentials.size());

So in the MCR itself, it would have extracted 0 credentials from
metadata, and therefore there was nothing to filter in the first place.

At least I think that's what would have happened.  Would be nice to see
the full logs.  There's also some caching in there, so possibly the
initial failure to find and extract credentials from KeyInfo might have
been done early on and not appear later on subsequent attempts.


> It would have been immensely helpful for the trust engine to log the
> number of resolved trusted certificates at DEBUG prior to attempting
> signature validation; summary logging after applying criteria also
> would have helped. I intend to file a Jira issue for those logging
> improvements because I feel strongly that they would be generally
> beneficial.

That's fine, adding some logging is easy enough.  I agree that there
are places where more logging would have been beneficial in this case,
but they're probably around the MetadataCredentialResolver
fundamentally not finding any creds in metadata, vs the
criterion/predicate filtering layer.


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20180919/b5b21a85/attachment.html>