Shibboleth questions on a new Leaf deployment

[artgoldberg]

Dear Leaf folks

I'm deploying Leaf 3.11 on Centos with Apache 2.4 and shibd. Two problems are occuring:

1. No records are being written to the Shibboleth logs:
   
   This problem seems to have started last Nov. Shibboleth SP logging should be controlled by /etc/shibboleth/shibd.logger, which I attach below, and by /etc/shibboleth/native.logger. The former indicates a correct name for the log file in this line:

log4j.appender.shibd_log.fileName=/var/log/shibboleth/shibd.log

2. Accessing Leaf throws an error which returns this text in the browser:

Unknown or Unusable Identity Provider
The identity provider supplying your login credentials is not authorized for use with this service or does not support the necessary capabilities.

To report this problem, please contact the site administrator at [Arthur.p.Goldberg@mssm.edu](mailto:Arthur.p.Goldberg@mssm.edu).

Please include the following error message in any email:

Identity provider lookup failed at (https://omop-leaf-temp.hpc.mssm.edu/)

EntityID: https://sts.windows.net/77e89d61-570f-43b0-b9e4-634f462e34b8/

opensaml::saml2md::MetadataException: Unable to locate metadata for identity provider (https://sts.windows.net/77e89d61-570f-43b0-b9e4-634f462e34b8/)Unknown or Unusable Identity Provider
The identity provider supplying your login credentials is not authorized for use with this service or does not support the necessary capabilities.

To report this problem, please contact the site administrator at [Arthur.p.Goldberg@mssm.edu](mailto:Arthur.p.Goldberg@mssm.edu).

Please include the following error message in any email:

Identity provider lookup failed at (https://omop-leaf-temp.hpc.mssm.edu/)

EntityID: https://sts.windows.net/<redacted>/

opensaml::saml2md::MetadataException: Unable to locate metadata for identity provider (https://sts.windows.net/<redacted>/)

The httpd log contains these errors:

Jun 30 15:48:42 omop-leaf-temp shibboleth[85859]: ERROR Shibboleth.Listener [85859] shib_check_user [default]: remoted message returned an error: Unable to locate metadata for identity provider (https://sts.windows.net/77e89d61-570f-43b0-b9e4-634f462e34b8/)
Jun 30 15:48:42 omop-leaf-temp shibboleth[85859]: ERROR Shibboleth.Apache [85859] shib_check_user: Unable to locate metadata for identity provider (https://sts.windows.net/77e89d61-570f-43b0-b9e4-634f462e34b8/)

I think that 2 will be easier to solve after 1 is solved.

As always, thank you

Arthur

# set overall behavior
log4j.rootCategory=DEBUG, shibd_log, warn_log

# fairly verbose for DEBUG, so generally leave at INFO
log4j.category.XMLTooling.XMLObject=INFO
log4j.category.XMLTooling.XMLObjectBuilder=INFO
log4j.category.XMLTooling.KeyInfoResolver=INFO
log4j.category.Shibboleth.IPRange=INFO
log4j.category.Shibboleth.PropertySet=INFO

# raise for low-level tracing of SOAP client HTTP/SSL behavior
log4j.category.XMLTooling.libcurl=INFO

# useful categories to tune independently:
#
# tracing of SAML messages and security policies
#log4j.category.OpenSAML.MessageDecoder=DEBUG
#log4j.category.OpenSAML.MessageEncoder=DEBUG
#log4j.category.OpenSAML.SecurityPolicyRule=DEBUG
#log4j.category.XMLTooling.SOAPClient=DEBUG
# interprocess message remoting
#log4j.category.Shibboleth.Listener=DEBUG
# mapping of requests to applicationId
#log4j.category.Shibboleth.RequestMapper=DEBUG
# high level session cache operations
#log4j.category.Shibboleth.SessionCache=DEBUG
# persistent storage and caching
#log4j.category.XMLTooling.StorageService=DEBUG

# logs XML being signed or verified if set to DEBUG
log4j.category.XMLTooling.Signature.Debugger=INFO, sig_log
log4j.additivity.XMLTooling.Signature.Debugger=false
log4j.ownAppenders.XMLTooling.Signature.Debugger=true

# the tran log blocks the "default" appender(s) at runtime
# Level should be left at INFO for this category
log4j.category.Shibboleth-TRANSACTION=INFO, tran_log
log4j.additivity.Shibboleth-TRANSACTION=false
log4j.ownAppenders.Shibboleth-TRANSACTION=true

# uncomment to suppress particular event types
#log4j.category.Shibboleth-TRANSACTION.AuthnRequest=WARN
#log4j.category.Shibboleth-TRANSACTION.Login=WARN
#log4j.category.Shibboleth-TRANSACTION.Logout=WARN

# define the appenders

log4j.appender.shibd_log=org.apache.log4j.RollingFileAppender
log4j.appender.shibd_log.fileName=/var/log/shibboleth/shibd.log
log4j.appender.shibd_log.maxFileSize=1000000
log4j.appender.shibd_log.maxBackupIndex=10
log4j.appender.shibd_log.layout=org.apache.log4j.PatternLayout
log4j.appender.shibd_log.layout.ConversionPattern=%d{%Y-%m-%d %H:%M:%S} %p %c %x: %m%n

log4j.appender.warn_log=org.apache.log4j.RollingFileAppender
log4j.appender.warn_log.fileName=/var/log/shibboleth/shibd_warn.log
log4j.appender.warn_log.maxFileSize=1000000
log4j.appender.warn_log.maxBackupIndex=10
log4j.appender.warn_log.layout=org.apache.log4j.PatternLayout
log4j.appender.warn_log.layout.ConversionPattern=%d{%Y-%m-%d %H:%M:%S} %p %c %x: %m%n
log4j.appender.warn_log.threshold=WARN

log4j.appender.tran_log=org.apache.log4j.RollingFileAppender
log4j.appender.tran_log.fileName=/var/log/shibboleth/transaction.log
log4j.appender.tran_log.maxFileSize=1000000
log4j.appender.tran_log.maxBackupIndex=20
log4j.appender.tran_log.layout=org.apache.log4j.PatternLayout
log4j.appender.tran_log.layout.ConversionPattern=%d{%Y-%m-%d %H:%M:%S}|%c|%m%n

log4j.appender.sig_log=org.apache.log4j.FileAppender
log4j.appender.sig_log.fileName=/var/log/shibboleth/signature.log
log4j.appender.sig_log.layout=org.apache.log4j.PatternLayout
log4j.appender.sig_log.layout.ConversionPattern=%m

[ndobb]

@mh2727 can you weigh in on this one?

[mh2727]

@artgoldberg,

I think it might help to set up some time to review this on Zoom so we can quickly debug.

I have some questions in the mean time.

1. Was Shibboleth running even after the logs stopped in Nov. 2021?
2. It shouldn't make a difference, but have you tried with INFO? Trying to see if it logs for other options.
   a. log4j.rootCategory=INFO, shibd_log, warn_log
3. Do you have any example of a working Shibboleth configuration in your department? We can check for differences.

Have you also tried checking the Shibboleth service to see if there are any errors systemctl status shibd.service?

Lastly, were any files moved into the /etc/shibboleth directory? It will help to confirm the SELinux labels to make sure they're all appropriate (ls -laZ).

[artgoldberg]

Thanks @ndobb and @mh2727

I appreciate your offer to review and debug on Zoom. I'll email some proposed times.
RE your questions:

1. Yes, but in the Leaf 3.9 release VM.
2. No. I'll try INFO before we meet and write back.
3. Yes. The Leaf 3.9 release which I did works & uses Shibboleth. This one is based on that, but modified for Leaf 3.11. Reviewing changes is a good idea.

systemctl status shibd doesn't report errors. But systemctl status httpd does:

I need to answer your last question later.

Thanks again
Arthur

[artgoldberg]

@mh2727 and @ndobb , I have a hypothesis about why the shibd logs are not growing. Three of the logs have a maxFileSize=1000000 specified in /etc/shibboleth/shibd.logger:

And all of the logs except 2 have sizes that are slightly larger than 1,000,000:

My hypothesis is that almost all of the logs have hit this size limit, and they're not properly rolling over, or do whatever they're supposed to do.

[artgoldberg]

These changes fix the problem:

• Permissions

  • Make the shibd account and group the user and group of the directory storing shibboleth log files.
  • Set drwxr-xr-x permissions on the directory storing shibboleth log files.

• Configuration of shibboleth logging in shibd.logger

  • Cannot use MB suffix for maxFileSize, despite what the log4j RollingFileAppender documentation says.
  • Set log4j.rootCategory = INFO, shibd_log, warn_log in shibd.logger.

Thank you @mh2727 and @ndobb !

Arthur

[ndobb]

This is fantastic news, @artgoldberg , thanks for letting us know!!