The Shibboleth IdP V4 software will leave support on September 1, 2024.
LoggingConfiguration
File(s): conf/logback.xml
Format: Logback
Overview
All logging is done through an abstract API called SLF4J that allows for a choice of logging implementation at runtime. The software ships and installs with a logging implementation called Logback. We do not at present have any examples of replacing this implementation.
The Logback manual provides an exhaustive summary of the many options and features that may be configured. We do not attempt here to replicate this information but instead provide information specific to the IdP and instructions for performing simple, common, adjustments. An AdvancedLogging page is also available to capture more advanced examples.
General Configuration
The default logging configuration is located in conf/logback.xml and is wrapped with a reloadable service to add flexibility (though you can also cause logback itself to poll for changes). The reloadability means that you can keep the logging level at WARN until a problem occurs and then change the logging to DEBUG to get more information if the problem persists, without restarting the IdP.
The advantages to letting the IdP manage the polling and reloading are that you can monitor the state of this configuration through the status page and trigger reloads on demand when necessary.
There are several additional settings that involve the AuditLoggingConfiguration specifically and are discussed in that subtopic.
Variables and Properties
The default file makes use of a property-like feature of logback called Variable Substitution. Variables are essentially properties and can be declared inline, imported as property files, or declared as system properties. By default, the only properties used that are declared elsewhere are idp.home and a handful of properties for controlling F-TICKS logging, but we do import the conf/idp.properties file for you so that you can choose to declare any custom properties there. Note that other property files are not imported for you unless you do so directly. Also note that unlike most of the IdP configuration using Spring, this property replacement requires the ${property} syntax.
The following properties are declared for you:
Variable | Default | Function |
|---|---|---|
idp.logfiles | ${idp.home}/logs | Location of log files |
idp.loghistory | 180 | Number of days of logs to keep |
idp.process.appender | IDP_PROCESS | Appender to use for diagnostic log (set to ASYNC_PROCESS for high volume DEBUG logging) |
idp.loglevel.idp | INFO | Log level for the IdP proper |
idp.loglevel.ldap | WARN | Log level for LDAP events |
idp.loglevel.messages | INFO | Set to DEBUG for protocol message tracing |
idp.loglevel.encryption | INFO | Set to DEBUG to log cleartext versions of encrypted content |
idp.loglevel.opensaml | INFO | Log level for OpenSAML library classes |
idp.loglevel.props | INFO | Set to DEBUG to log runtime properties during startup |
idp.loglevel.spring | ERROR | Log level for Spring Framework (very chatty) |
idp.loglevel.container | ERROR | Log level for Tomcat/Jetty (very chatty) |
idp.loglevel.xmlsec | INFO | Set to DEBUG for low-level XML Signing/Encryption logging |
Log Files
By default there are three classes of log file produced:
diagnostic logs (idp-process.log, idp-warn.log)
general audit log (idp-audit.log)
consent audit log (idp-consent-audit.log)
The latter two are discussed in the AuditLoggingConfiguration subtopic.
The diagnostic log contain messages logged during normal operation of the software. It is meant to be human-readable and records information about the IdP is doing, warnings and errors encountered, etc. It is designed to record a relatively limited amount of useful intelligence on INFO (the default logging level), and a large amount of detail on DEBUG.
The idp-warn.log is a filtered view of idp-process.log that includes only messages logged at WARN or higher.
An additional, optional log is used for capturing F-TICKS records, a special audit format. See the dedicated topic on FTICKSLoggingConfiguration.
Note that some sources of diagnostic messages, Active Directory in particular, will embed non-ASCII data in the messages, which makes the log binary. The IdP supports a Java system property (org.ldaptive.response.encodeCntrlChars) you can set (using whatever mechanism you use to pass system properties to the servlet container) to clean that data, with a small cost in extra processing.
Rolling and Compression
The default configuration causes all the log files to be "rolled over" at midnight each night, if the IdP is running, or the next time the IdP starts up afterward. We suggest letting logback handle this and not attempting to use utilities like logrotate for this purpose.
Archived log files are automatically compressed (due to the ".gz" suffix in the <FileNamePattern> of each log file appender). The "zip" suffix may be used if desired. Consult the the Logback documentation for further information on other options available.
Asynchronous Logging
Logback has a feature allowing a log appender (like a file) to be wrapped with a buffer that catches the events and writes them out asynchronously. This carries a small risk of event loss (the chance of which can be adjusted) but greatly improves IdP performance at high logging levels. While we do not suggest logging that much in production in most cases, if this becomes necessary for short periods, using this feature is advisable. You can automatically handle diagnostic events asynchronously by setting the idp.process.appender variable to ASYNC_PROCESS (this is commented out by default) and reloading the logging service.
Logging Categories
For the most part, logging is performed on a Java class basis, so a given class will log to a category matching its classname. Logging levels can be adjusted at either the class level, or package level to capture a wider net.
For convenience, a number of variables are provided (see above) to abstract out the logging categories required for various common needs.
One way to figure out what you need is to test a little with the root logging level set to DEBUG and then adjust by turning that back down and adding new <logger> elements for your needs.
Some examples of useful categories follow:
Category | Description |
|---|---|
Shibboleth-Audit, Shibboleth-Consent-Audit | Categories to which audit messages are written, allowing them to be captured by additional logging destinations |
Shibboleth-FTICKS | Category for F-TICKS logging messages. |
PROTOCOL_MESSAGE | A logger for incoming and outgoing XML protocol messages, not active by default |
org.opensaml.saml | Messages related only to receiving, parsing, evaluating security of, producing, and encoding SAML messages (this produces a lot of log messages, especially at IdP startup) |
org.opensaml.saml.saml2.encryption.Encrypter | Logs unencrypted SAML content at DEBUG level, not active by default |
org.opensaml.saml.metadata.resolver | Information regarding metadata loading, refresh, and querying |
net.shibboleth.idp | Messages related to all the IdP's functions, profile handling, authentication, attribute resolution and filtering |
net.shibboleth.idp.authn | Messages related only to authentication |
net.shibboleth.idp.attribute | Messages related to attribute resolution and filtering |
org.ldaptive | Messages related to LDAP library processing (applies to both authentication or attribute lookup) |
The default configuration includes additional loggers that are either commented out or are hardwired to particular levels. Adjusting these categories may result in a lot of additional noise, but also may be useful to diagnose very low-level problems (or you might be asked to in order to help diagnose a problem).
Logging Levels
The logback system defines 5 logging levels (TRACE, DEBUG, INFO, WARN, ERROR). As you progress from the highest level (ERROR) to the lowest level (TRACE) the amount of information logged increases (dramatically so on the DEBUG and TRACE levels). Each level also logs all messages of the levels above it. For example, INFO also logs WARN and ERROR messages.
Mapped Diagnostic Context
Logback supports a feature known as the Mapped Diagnostic Context (MDC). Information stored in the MDC is available to every logging message (after the point the information is stored) and can be accessed in an event string with the format %mdc{KEY}. Currently the IdP makes the following information available via the MDC:
MDC KEY | Description |
|---|---|
idp.jsessionid | The servlet container's JSESSIONID attribute |
idp.remote_addr | The IP address of the remote user-agent. This is the user's browser for front-channel requests and the SP for back-channel requests. |
idp.server_hostname | The host name of the server to which the current request was sent |
idp.server_port | The port number to which the current request was sent |
Example Logging Pattern using the Container Session ID
<Pattern>%date{HH:mm:ss.SSS} - %level [%logger:%line] - [%mdc{idp.jsessionid}] - %msg%n</Pattern>Other Examples
Preventing Audit Log Entry Duplication
Because the appender associated with the idp-process.log is attached to the root logger, any messages logged to any logger will be output there by default. This includes entries logged to the audit categories, which will by default be duplicated in the process log.
To prevent duplication of the audit log entries, you can add the attribute additivity="false" to those loggers:
<logger name="Shibboleth-Audit" level="ALL" additivity="false">
<appender-ref ref="IDP_AUDIT" />
</logger>
<logger name="Shibboleth-Consent-Audit" level="ALL" additivity="false">
<appender-ref ref="IDP_CONSENT_AUDIT"/>
</logger>
<logger name="Shibboleth-FTICKS" level="ALL" additivity="false">
<appender-ref ref="IDP_FTICKS_SYSLOG"/>
</logger>Notes
The biggest difficulty with noise in these logs relates to the very common occurrence of network connection issues that affect essentially any web server because of factors outside the software's control. These connection issues will typically result in a lot of extraneous ERROR content in both logs that eventually becomes fairly uninteresting to look at.
A second class of common issues is caused by clients that may timeout during the flow of a request because of user inactivity, leaving mid-transaction to go to lunch, etc. These will also eventually become noise.
Still another is the use of the back button.
You may eventually wish to apply filtering to the log events that are recorded, perhaps adding an additional appender to catch just those events and record them separately in the rare circumstance that you need the information.