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:

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:

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:

There are properties defined to provide some additional control over how this feature works:

• idp.logging.MDC.enabled

  • Can be set to false to turn off the Java filter that populates the MDC if not used.

• idp.logging.MDC.createSession

  • Can be set to false to prevent the Java filter from actually creating a servlet session in accessing the session ID, if it doesn’t already exist. Note that almost all uses of the IdP end up creating that session anyway.

Example Logging Pattern using the Container Session ID

V5.1+ also supports extracting arbitrary HTTP request headers into MDC keys using a map defined in a bean named shibboleth.MDCHeaders. The map keys define the MDC keys to create and the values define the header name to read in:

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:

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.