Pre-Authentication Looping Behavior

[Chris Woods]

Hi-
A small subset (roughly 1%) of our users have experienced a looping
situation when attempting their first login from our new IDP 4 server. In
some cases, it ends after a short amount of time and the user can
successfully authenticate (see sample below); in others, we've let it run
for more than 30 minutes with no end. Clearing cache or switching to
incognito mode or a different browser usually works, and the fix will stick
for a while, but the problem returns. We have not been able to replicate in
a controlled environment. It has been observed on Chrome and Safari
browsers. We have SSO enabled and use Tomcat9 on Ubuntu 20.04LTS.
Below is a sample of our Tomcat access log during one such instance. The
extra field at the end of the line is the contents of shib_idp_session
cookie if one is set. Nothing that corresponds to this appears in the
idp-process.log, even with DEBUG-level logging.

100.100.100.100 - - [11/Nov/2020:13:29:22 -0500] "GET
/idp/profile/SAML2/Redirect/SSO?SAMLRequest=lVLf...Wg%3D%3D HTTP/1.1" 302 -
"https://disco.example.edu/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36" -
100.100.100.100 - - [11/Nov/2020:13:29:22 -0500] "GET
/idp/profile/SAML2/Redirect/SSO?execution=e1s1 HTTP/1.1" 200 3107 "
https://disco.example.edu/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.183 Safari/537.36" -
100.100.100.100 - - [11/Nov/2020:13:29:23 -0500] "POST
/idp/profile/SAML2/Redirect/SSO?execution=e1s1 HTTP/1.1" 200 3107 "
https://login.example.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s1"
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/86.0.4240.183 Safari/537.36" -
100.100.100.100 - - [11/Nov/2020:13:29:23 -0500] "POST
/idp/profile/SAML2/Redirect/SSO?execution=e1s1 HTTP/1.1" 200 3107 "
https://login.example.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s1"
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/86.0.4240.183 Safari/537.36" -
100.100.100.100 - - [11/Nov/2020:13:29:23 -0500] "POST
/idp/profile/SAML2/Redirect/SSO?execution=e1s1 HTTP/1.1" 200 3107 "
https://login.example.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s1"
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/86.0.4240.183 Safari/537.36" -
--Terminated by user
At 14:37:19, the same user returned, and the log looks identical to begin
with, except for the contents of the SAMLRequest. However, at 14:38:09, the
POST returns a 302, and then it goes through an authentication cycle and
the session is established.
100.100.100.100 - - [11/Nov/2020:14:38:09 -0500] "POST
/idp/profile/SAML2/Redirect/SSO?execution=e1s1 HTTP/1.1" 200 3107 "
https://login.example.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s1"
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/86.0.4240.183 Safari/537.36" -
100.100.100.100 - - [11/Nov/2020:14:38:09 -0500] "POST
/idp/profile/SAML2/Redirect/SSO?execution=e1s1 HTTP/1.1" 302 - "
https://login.example.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s1"
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/86.0.4240.183 Safari/537.36" -
100.100.100.100 - - [11/Nov/2020:14:38:09 -0500] "GET
/idp/profile/SAML2/Redirect/SSO?execution=e1s2 HTTP/1.1" 200 2396 "
https://login.example.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s1"
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/86.0.4240.183 Safari/537.36" -
100.100.100.100 - - [11/Nov/2020:14:38:45 -0500] "POST
/idp/profile/SAML2/Redirect/SSO?execution=e1s2 HTTP/1.1" 302 - "
https://login.example.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s2"
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/86.0.4240.183 Safari/537.36" -
100.100.100.100 - - [11/Nov/2020:14:38:45 -0500] "GET
/idp/profile/SAML2/Redirect/SSO?execution=e1s3 HTTP/1.1" 200 4565 "
https://login.example.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s2"
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/86.0.4240.183 Safari/537.36"
8b59f7effff2275bdb1570695297186cef9afa360dff9b1c96cb02a92e4d9b9e
100.100.100.100 - - [11/Nov/2020:14:38:46 -0500] "POST
/idp/profile/SAML2/Redirect/SSO?execution=e1s3 HTTP/1.1" 200 16629 "
https://login.example.edu/idp/profile/SAML2/Redirect/SSO?execution=e1s3"
"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/86.0.4240.183 Safari/537.36"
8b59f7effff2275bdb1570695297186cef9afa360dff9b1c96cb02a92e4d9b9e

>From idp-process.log at the same time:
2020-11-11 14:38:45,218 - 100.100.100.100 - INFO
[net.shibboleth.idp.authn.impl.LDAPCredentialValidator:145] - Credential
Validator ldap: Login by 'username' succeeded
Has anyone seen similar behavior or does anyone have a suggestion as to
where we can look to find more information?
Thanks very much.

-Chris
---
Chris Woods
Systems Administrator
Mount Holyoke College
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20201111/46f13bf0/attachment.htm>