Intermittent Shibboleth failure

Mon May 27 09:49:08 EDT 2019

dear folks,

I have a working SP install running on a Centos7 box. It usually connects
fine the various IDp providers we authenticate with. However, from time to
time, (every 2-3 weeks) our users get a white screen of death:

OpenSAML::FatalProfileException
.
.
Unable to establish security of incoming assertion.

The short-term fix is just to restart the shibd daemon on the server, and
all starts running again. But I want to know what might be causing this in
the first place.

Before restarting the daemon this time, I checked a few logs to see what was
happening on the machine:

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

> tail /var/log/shibboleth/shbd_warn.log

2019-05-27 05:35:31 WARN OpenSAML.MetadataProvider [1419] [default]: ignored
expired metadata instance for (https://registry.shibboleth.ox.ac.uk/idp)
2019-05-27 05:35:31 WARN OpenSAML.MessageDecoder.SAML2 [1419] [default]: no
metadata found, can't establish identity of issuer
(https://registry.shibboleth.ox.ac.uk/idp)
2019-05-27 05:35:31 WARN OpenSAML.MetadataProvider [1419] [default]: ignored
expired metadata instance for (https://registry.shibboleth.ox.ac.uk/idp)
2019-05-27 05:35:31 WARN Shibboleth.SSO.SAML2 [1419] [default]: no metadata
found, can't establish identity of issuer
(https://registry.shibboleth.ox.ac.uk/idp)
2019-05-27 05:35:31 WARN Shibboleth.SSO.SAML2 [1419] [default]: detected a
problem with assertion: Unable to establish security of incoming assertion.
2019-05-27 05:35:31 WARN Shibboleth.SSO.SAML2 [1419] [default]: error
processing incoming assertion: Unable to establish security of incoming
assertion.
2019-05-27 08:15:12 WARN OpenSAML.MetadataProvider [1437] [default]: ignored
expired metadata instance for (https://registry.shibboleth.ox.ac.uk/idp)
2019-05-27 08:15:12 WARN Shibboleth.SessionInitiator.SAML2 [1437] [default]:
unable to locate metadata for provider
(https://registry.shibboleth.ox.ac.uk/idp)
2019-05-27 08:22:05 WARN OpenSAML.MetadataProvider [1442] [default]: ignored
expired metadata instance for (https://registry.shibboleth.ox.ac.uk/idp)
2019-05-27 08:22:05 WARN Shibboleth.SessionInitiator.SAML2 [1442] [default]:
unable to locate metadata for provider
(https://registry.shibboleth.ox.ac.uk/idp)

and checking the status of httpd:

> service shibd statusservice httpd status
Redirecting to /bin/systemctl status httpd.service
● httpd.service - The Apache HTTP Server
   Loaded: loaded (/usr/lib/systemd/system/httpd.service; enabled; vendor
preset: disabled)
   Active: active (running) since Wed 2019-05-01 07:58:51 CDT; 3 weeks 5
days ago
     Docs: man:httpd(8)
           man:apachectl(8)
  Process: 38999 ExecReload=/usr/sbin/httpd $OPTIONS -k graceful
(code=exited, status=0/SUCCESS)
 Main PID: 23448 (/usr/sbin/httpd)
   Status: "Total requests: 0; Current requests/sec: 0; Current traffic:   0
B/sec"
   CGroup: /system.slice/httpd.service
           ├─18211 /usr/sbin/httpd -DFOREGROUND
           ├─20110 /usr/sbin/httpd -DFOREGROUND
           ├─22506 /usr/sbin/httpd -DFOREGROUND
           ├─23448 /usr/sbin/httpd -DFOREGROUND
           ├─23493 /usr/sbin/httpd -DFOREGROUND
           ├─27356 /usr/sbin/httpd -DFOREGROUND
           ├─29489 /usr/sbin/httpd -DFOREGROUND
           ├─29519 /usr/sbin/httpd -DFOREGROUND
           ├─33747 /usr/sbin/httpd -DFOREGROUND
           ├─34076 /usr/sbin/httpd -DFOREGROUND
           └─34077 /usr/sbin/httpd -DFOREGROUND

May 27 05:34:33 865289-App1.qgateway shibboleth[20130]: ERROR
Shibboleth.Listener [20130] shib_handler [default]: remoted message
return...rtion.
May 27 05:34:33 865289-App1.qgateway shibboleth[20130]: ERROR
Shibboleth.Apache [20130] shib_handler: Unable to establish security of
in...rtion.
May 27 05:35:03 865289-App1.qgateway shibboleth[17722]: ERROR
Shibboleth.Listener [17722] shib_handler [default]: remoted message
return...rtion.
May 27 05:35:03 865289-App1.qgateway shibboleth[17722]: ERROR
Shibboleth.Apache [17722] shib_handler: Unable to establish security of
in...rtion.
May 27 05:35:09 865289-App1.qgateway shibboleth[14176]: ERROR
Shibboleth.Listener [14176] shib_handler [default]: remoted message
return...rtion.
May 27 05:35:09 865289-App1.qgateway shibboleth[14176]: ERROR
Shibboleth.Apache [14176] shib_handler: Unable to establish security of
in...rtion.
May 27 05:35:31 865289-App1.qgateway shibboleth[20188]: ERROR
Shibboleth.Listener [20188] shib_handler [default]: remoted message
return...rtion.
May 27 05:35:31 865289-App1.qgateway shibboleth[20188]: ERROR
Shibboleth.Apache [20188] shib_handler: Unable to establish security of
in...rtion.
May 27 08:15:12 865289-App1.qgateway shibboleth[29519]: ERROR
Shibboleth.Listener [29519] shib_handler [default]: remoted message
return...k/idp)
May 27 08:15:12 865289-App1.qgateway shibboleth[29519]: ERROR
Shibboleth.Apache [29519] shib_handler: Unable to locate metadata for
iden...k/idp)

And checking the status of the shibd daemon:

>ps aux | grep shibd

shibd     3036  0.0  1.6 2627800 541132 ?      Ssl  May10   9:14
/usr/sbin/shibd -f -F
root     33892  0.0  0.0 112712   936 pts/0    S+   08:16   0:00 grep
--color=auto shibd

> service shibd status

Redirecting to /bin/systemctl status shibd.service
● shibd.service - Shibboleth Service Provider Daemon
   Loaded: loaded (/usr/lib/systemd/system/shibd.service; disabled; vendor
preset: disabled)
   Active: active (running) since Fri 2019-05-10 07:27:55 CDT; 2 weeks 3
days ago
     Docs: https://wiki.shibboleth.net/confluence/display/SP3/Home
 Main PID: 3036 (shibd)
   CGroup: /system.slice/shibd.service
           └─3036 /usr/sbin/shibd -f -F

Warning: Journal has been rotated since unit was started. Log output is
incomplete or unavailable.
----------------------------------------------------------------------------------------------------------------

Restarting the httpd service does not resolve the issue; I have to restart
shibd.

As you can see, the shidb service appears to be running on the machine, but
just not working properly. The warnings about expired and missing metadata
and certificates are bogus, since after a restart, they are no longer
"expired". Presumably the shibd daemon is for some reason unable to access
these files which is why is why it is having a problem with them. 

Does anyone have any ideas as to what may be causing this problem? The
sledge hammer approach would probably be to set a systemd timer to restart
shibd every 24 hours, but that does not tell me what the underlying issue
is.

Kind regards,

Charles de Bueger

--
Sent from: http://shibboleth.1660669.n2.nabble.com/Shibboleth-Users-f1660767.html