IDP3 Occasionally failing to generate user attributes

Tue Sep 1 17:56:49 UTC 2020

Thanks again, Scott.

For the record, here's a successful "normal" auth that directly preceeded that one:

2020-08-31 07:36:49,495 - INFO [net.shibboleth.idp.authn.impl.ValidateExternalAuthentication:147] - Profile Action ValidateExternalAuthentication: External authentication succeeded for user: cadavidson
2020-08-31 07:36:49,542 - INFO [Shibboleth-Audit.SSO:275] - 20200831T113649Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|a3cf1e078fb9gaba-4cecghej450b9h7|https://loyola.zoom.us|http://shibboleth.net/ns/profiles/saml2/sso/browser|https://shibprodapp.loyola.edu/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_8246c63fffc15a5a7843db5858246787|cadavidson|urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport|commonName,loyIsFaculty,eduPersonAffiliation,displayName,givenName,loyPrtlConst,loyolaID,eduPersonScopedAffiliation,loyCampusHousing,surname,loyZoomHIPAA,eduPersonPrincipalName,email|AAdzZWNyZXQxo5gPYOQH/gTsiXPV0DLKO9K592kOoqZvuAV+5Pm9/dYYIGKfreW2xxA2n/uHXPrwaVIPjZ1k6e+4aGEOIzofEdvC1mvqrYUy+YT5sP0IqWkARJ2A/cT2ViJYq3SxYEw=|_d3940f93885c60902391b1f49487b8e7|

These two auths both contain the long alphanumeric string that begins with "AAdzZWN" which is what Zoom ends up using as the user ID of the new account it creates. I was assuming (forgive me because I don't know much about NameID) that this was the transient NameID value that our IDP generated for that auth. Is that correct?

The only interesting things I see in the transaction log for the Bridge SP is that there don't appear to be entries *at all* for these "failed" logins. If I compare the T-log from the SP with the IDP process log, see:

  *   Corresponding events for five or six "normal" user logins in a row
  *   Then, in the IDP process log there are 82 of these "failed" logins in a row, all compressed into the next minute or so, all of which have NO corresponding event in the SP log for the bridge
  *   Then there is one "normal" user login that has a corresponding entry in the SP log
  *   Then in the IDP process log there are 132 of the "failed" logins in a row, over the space of the next minute or two, all of which have NO corresponding event in the SP log for the bridge.
  *   Then there's another "normal" login that has a corresponding entry in the SP log

And then it continues on like that. It seems like these "failures" are compressed into spats of a few minutes or so at a time, spaced out over the day.

Sorry about the brain dump, I'm collecting my own thoughts as much as I'm asking a question here, I suppose.

I really appreciate your help - I know you spend a TON of time answering questions like this that are probably actually very basic.

Tim Enders
Senior Systems Engineer
[1518788691975_Loyola.jpg]
4501 N. Charles Street
Baltimore, MD  21210
tenders at loyola.edu<mailto:tenders at loyola.edu>
Office- 410-617-2542
Fax - 410-617-6658
www.loyola.edu
<http://www.twitter.com/LoyolaMaryland>

<http://www.twitter.com/LoyolaMaryland>

________________________________
From: users <users-bounces at shibboleth.net> on behalf of Cantor, Scott <cantor.2 at osu.edu>
Sent: Tuesday, September 1, 2020 12:44 PM
To: Shib Users <users at shibboleth.net>
Subject: Re: IDP3 Occasionally failing to generate user attributes

On 9/1/20, 12:39 PM, "users on behalf of Timothy Enders" <users-bounces at shibboleth.net on behalf of tenders at loyola.edu> wrote:

> These (at least some of the ones I've checked) do appear to be actual users who did have a successful auth through
> Azure. In that case, is this somehow still Azure returning a "null" value (that's actually that string) every so often when
> someone logs in?

I can't see any other explanation when the log line immediately follows an explicit null check for the field being logged.

>    I assume that the further error about the Attribute Definition script not running correctly is maybe caused by the fact
> that the IDP can't look up the user in LDAP at all, instead of a communication issue with LDAP. Does that make any
> sense?

And the fact your LDAP lookup is programmed to treat no results as success, causing another script to run that's probably sourcing data from a resolved attribute with no values.

The whole resolver stack is implicated.

-- Scott

--
For Consortium Member technical support, see https://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fwiki.shibboleth.net%2Fconfluence%2Fx%2FcoFAAg&data=02%7C01%7Ctenders%40loyola.edu%7C6e907dad0004487ad1f208d84e964081%7C30ae0a8f3cdf44fdaf34278bf639b85d%7C0%7C0%7C637345754521169193&sdata=iShsEVg8H5vKZw9MWjfGKb9FR5DFqAwYDxcaWti1n4g%3D&reserved=0
To unsubscribe from this list send an email to users-unsubscribe at shibboleth.net
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20200901/c35f13bb/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Outlook-1518788691.jpg
Type: image/jpeg
Size: 8726 bytes
Desc: Outlook-1518788691.jpg
URL: <http://shibboleth.net/pipermail/users/attachments/20200901/c35f13bb/attachment.jpg>