{"type":"doc","content":[{"type":"paragraph","content":[{"text":"File(s):","type":"text","marks":[{"type":"strong"}]},{"text":" ","type":"text"},{"text":"conf/logback.xml","type":"text","marks":[{"type":"em"}]},{"type":"hardBreak"},{"text":"Format:","type":"text","marks":[{"type":"strong"}]},{"text":" ","type":"text"},{"text":"Logback","type":"text","marks":[{"type":"link","attrs":{"href":"http://logback.qos.ch/manual/index.html"}}]}]},{"type":"extension","attrs":{"layout":"default","extensionType":"com.atlassian.confluence.macro.core","extensionKey":"toc","parameters":{"macroParams":{"minLevel":{"value":"1"},"maxLevel":{"value":"3"},"outline":{"value":"false"},"type":{"value":"list"},"printable":{"value":"false"}},"macroMetadata":{"macroId":{"value":"51f325a9-de67-47e1-b92c-6381c3c7990d"},"schemaVersion":{"value":"1"},"title":"Table of Contents"}},"localId":"24fd8475-8b97-41fa-84d1-15c688fc3535"}},{"type":"heading","attrs":{"level":2},"content":[{"text":"Overview","type":"text"}]},{"type":"paragraph","content":[{"text":"All logging is done through an abstract API called ","type":"text"},{"text":"SLF4J","type":"text","marks":[{"type":"link","attrs":{"href":"http://slf4j.org/"}}]},{"text":" that allows for a choice of logging implementation at runtime. The software ships and installs with a logging implementation called ","type":"text"},{"text":"Logback","type":"text","marks":[{"type":"link","attrs":{"href":"http://logback.qos.ch/"}}]},{"text":". We do not at present have any examples of replacing this implementation.","type":"text"}]},{"type":"paragraph","content":[{"text":"The ","type":"text"},{"text":"Logback manual","type":"text","marks":[{"type":"link","attrs":{"href":"http://logback.qos.ch/manual/index.html"}}]},{"text":" 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 ","type":"text"},{"text":"AdvancedLogging","type":"text","marks":[{"type":"link","attrs":{"href":"https://shibboleth.atlassian.net/wiki/spaces/IDP5/pages/3199501036"}}]},{"text":" page is also available to capture more advanced examples.","type":"text"}]},{"type":"heading","attrs":{"level":2},"content":[{"text":"General Configuration","type":"text"}]},{"type":"paragraph","content":[{"text":"The default logging configuration is located in ","type":"text"},{"text":"conf/logback.xml","type":"text","marks":[{"type":"em"}]},{"text":" and is wrapped with a ","type":"text"},{"text":"reloadable service","type":"text","marks":[{"type":"link","attrs":{"href":"https://shibboleth.atlassian.net/wiki/spaces/IDP5/pages/3199507931"}}]},{"text":" to add flexibility (though you can also cause logback itself to ","type":"text"},{"text":"poll for changes","type":"text","marks":[{"type":"link","attrs":{"href":"http://logback.qos.ch/manual/configuration.html#autoScan"}}]},{"text":"). 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.","type":"text"}]},{"type":"paragraph","content":[{"text":"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.","type":"text"}]},{"type":"paragraph","content":[{"text":"There are several additional settings that involve the ","type":"text"},{"text":"AuditLoggingConfiguration","type":"text","marks":[{"type":"link","attrs":{"href":"https://shibboleth.atlassian.net/wiki/spaces/IDP5/pages/3199509698"}}]},{"text":" specifically and are discussed in that subtopic.","type":"text"}]},{"type":"heading","attrs":{"level":3},"content":[{"text":"Variables and Properties","type":"text"}]},{"type":"paragraph","content":[{"text":"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 ","type":"text"},{"text":"idp.home","type":"text","marks":[{"type":"strong"}]},{"text":" and a handful of properties for controlling ","type":"text"},{"text":"F-TICKS","type":"text","marks":[{"type":"link","attrs":{"href":"https://shibboleth.atlassian.net/wiki/spaces/IDP5/pages/3199509739"}}]},{"text":" logging, but we do import the ","type":"text"},{"text":"conf/idp.properties","type":"text","marks":[{"type":"em"}]},{"text":" file for you so that you can choose to declare any custom properties there. Note that other property files are ","type":"text"},{"text":"not","type":"text","marks":[{"type":"strong"}]},{"text":" imported for you unless you do so directly. Also note that unlike most of the IdP configuration using Spring, this property replacement requires the ","type":"text"},{"text":"${property","type":"text","marks":[{"type":"code"}]},{"text":"} syntax.","type":"text"}]},{"type":"paragraph","content":[{"text":"The following properties are declared for you:","type":"text"}]},{"type":"table","attrs":{"layout":"full-width","width":1244.0,"localId":"04d692c8-6639-4b39-9e4d-de8b9a3e7823"},"content":[{"type":"tableRow","content":[{"type":"tableHeader","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"Variable","type":"text"}]}]},{"type":"tableHeader","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"Default","type":"text"}]}]},{"type":"tableHeader","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Function","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.logfiles","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"${idp.home}/logs","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Location of log files","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.loghistory","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"180","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Number of days of logs to keep","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.process.appender","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"IDP_PROCESS","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Appender to use for diagnostic log (set to ASYNC_PROCESS for high volume DEBUG logging)","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.loglevel.idp","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"INFO","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Log level for the IdP proper","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.loglevel.ldap","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"WARN","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Log level for LDAP events","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.loglevel.messages","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"INFO","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Set to DEBUG for protocol message tracing","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.loglevel.encryption","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"INFO","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Set to DEBUG to log cleartext versions of encrypted content","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.loglevel.opensaml","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"INFO","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Log level for OpenSAML library classes","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.loglevel.props","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"INFO","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Set to DEBUG to log runtime properties during startup","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.loglevel.spring","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"ERROR","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Log level for Spring Framework (very chatty)","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.loglevel.container","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"ERROR","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Log level for Tomcat/Jetty (very chatty)","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[220.0]},"content":[{"type":"paragraph","content":[{"text":"idp.loglevel.xmlsec","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[166.0]},"content":[{"type":"paragraph","content":[{"text":"INFO","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[858.0]},"content":[{"type":"paragraph","content":[{"text":"Set to DEBUG for low-level XML Signing/Encryption logging","type":"text"}]}]}]}]},{"type":"heading","attrs":{"level":2},"content":[{"text":"Log Files","type":"text"}]},{"type":"paragraph","content":[{"text":"By default there are three classes of log file produced:","type":"text"}]},{"type":"bulletList","content":[{"type":"listItem","content":[{"type":"paragraph","content":[{"text":"diagnostic logs (","type":"text"},{"text":"idp-process.log, idp-warn.log","type":"text","marks":[{"type":"em"}]},{"text":")","type":"text"}]}]},{"type":"listItem","content":[{"type":"paragraph","content":[{"text":"general audit log (","type":"text"},{"text":"idp-audit.log","type":"text","marks":[{"type":"em"}]},{"text":")","type":"text"}]}]},{"type":"listItem","content":[{"type":"paragraph","content":[{"text":"consent audit log (","type":"text"},{"text":"idp-consent-audit.log","type":"text","marks":[{"type":"em"}]},{"text":")","type":"text"}]}]}]},{"type":"paragraph","content":[{"text":"The latter two are discussed in the ","type":"text"},{"text":"AuditLoggingConfiguration","type":"text","marks":[{"type":"link","attrs":{"href":"https://shibboleth.atlassian.net/wiki/spaces/IDP5/pages/3199509698"}}]},{"text":" subtopic.","type":"text"}]},{"type":"paragraph","content":[{"text":"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.","type":"text"}]},{"type":"paragraph","content":[{"text":"The ","type":"text"},{"text":"idp-warn.log","type":"text","marks":[{"type":"em"}]},{"text":" is a filtered view of ","type":"text"},{"text":"idp-process.log","type":"text","marks":[{"type":"em"}]},{"text":" that includes only messages logged at WARN or higher.","type":"text"}]},{"type":"paragraph","content":[{"text":"An additional, optional log is used for capturing F-TICKS records, a special audit format. See the dedicated topic on ","type":"text"},{"text":"FTICKSLoggingConfiguration","type":"text","marks":[{"type":"link","attrs":{"href":"https://shibboleth.atlassian.net/wiki/spaces/IDP5/pages/3199509739"}}]},{"text":".","type":"text"}]},{"type":"paragraph","content":[{"text":"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 ","type":"text"},{"text":"(org.ldaptive.response.encodeCntrlChars)","type":"text","marks":[{"type":"strong"}]},{"text":" 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.","type":"text"}]},{"type":"heading","attrs":{"level":3},"content":[{"text":"Rolling and Compression","type":"text"}]},{"type":"paragraph","content":[{"text":"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.","type":"text"}]},{"type":"paragraph","content":[{"text":"Archived log files are automatically compressed (due to the \".gz\" suffix in the ","type":"text"},{"text":"","type":"text","marks":[{"type":"code"}]},{"text":" of each log file appender). The \"zip\" suffix may be used if desired. Consult the the ","type":"text"},{"text":"Logback documentation","type":"text","marks":[{"type":"link","attrs":{"href":"http://logback.qos.ch/manual/appenders.html#RollingFileAppender"}}]},{"text":" for further information on other options available.","type":"text"}]},{"type":"heading","attrs":{"level":3},"content":[{"text":"Asynchronous Logging","type":"text"}]},{"type":"paragraph","content":[{"text":"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 ","type":"text"},{"text":"idp.process.appender","type":"text","marks":[{"type":"strong"}]},{"text":" variable to ASYNC_PROCESS (this is commented out by default) and reloading the logging service.","type":"text"}]},{"type":"heading","attrs":{"level":2},"content":[{"text":"Logging Categories","type":"text"}]},{"type":"paragraph","content":[{"text":"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.","type":"text"}]},{"type":"paragraph","content":[{"text":"For convenience, a number of variables are provided (see above) to abstract out the logging categories required for various common needs.","type":"text"}]},{"type":"paragraph","content":[{"text":"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 ","type":"text"},{"text":"","type":"text","marks":[{"type":"code"}]},{"text":" elements for your needs.","type":"text"}]},{"type":"paragraph","content":[{"text":"Some examples of useful categories follow:","type":"text"}]},{"type":"table","attrs":{"layout":"full-width","width":1244.0,"localId":"6207894f-cc61-40b1-a668-696f415f0d0f"},"content":[{"type":"tableRow","content":[{"type":"tableHeader","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"Category","type":"text"}]}]},{"type":"tableHeader","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"Description","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"Shibboleth-Audit, Shibboleth-Consent-Audit","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"Categories to which audit messages are written, allowing them to be captured by additional logging destinations","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"Shibboleth-FTICKS","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"Category for F-TICKS logging messages.","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"PROTOCOL_MESSAGE","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"A logger for incoming and outgoing XML protocol messages, not active by default","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"org.opensaml.saml","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"Messages related only to receiving, parsing, evaluating security of, producing, and encoding SAML messages (this produces ","type":"text"},{"text":"a lot","type":"text","marks":[{"type":"strong"}]},{"text":" of log messages, especially at IdP startup)","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"org.opensaml.saml.saml2.encryption.Encrypter","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"Logs unencrypted SAML content at DEBUG level, not active by default","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"org.opensaml.saml.metadata.resolver","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"Information regarding metadata loading, refresh, and querying","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"net.shibboleth.idp","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"Messages related to all the IdP's functions, profile handling, authentication, attribute resolution and filtering","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"net.shibboleth.idp.authn","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"Messages related only to authentication","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"net.shibboleth.idp.attribute","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"Messages related to attribute resolution and filtering","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[355.0]},"content":[{"type":"paragraph","content":[{"text":"org.ldaptive","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[889.0]},"content":[{"type":"paragraph","content":[{"text":"Messages related to LDAP library processing (applies to both authentication or attribute lookup)","type":"text"}]}]}]}]},{"type":"paragraph","content":[{"text":"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).","type":"text"}]},{"type":"heading","attrs":{"level":2},"content":[{"text":"Logging Levels","type":"text"}]},{"type":"paragraph","content":[{"text":"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.","type":"text"}]},{"type":"heading","attrs":{"level":2},"content":[{"text":"Mapped Diagnostic Context","type":"text"}]},{"type":"paragraph","content":[{"text":"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 ","type":"text"},{"text":"%mdc{KEY","type":"text","marks":[{"type":"code"}]},{"text":"}. Currently the IdP makes the following information available via the MDC:","type":"text"}]},{"type":"paragraph","content":[{"text":"There are properties defined to provide some additional control over how this feature works:","type":"text"}]},{"type":"bulletList","content":[{"type":"listItem","content":[{"type":"paragraph","content":[{"text":"idp.logging.MDC.enabled","type":"text","marks":[{"type":"strong"}]}]},{"type":"bulletList","content":[{"type":"listItem","content":[{"type":"paragraph","content":[{"text":"Can be set to false to turn off the Java filter that populates the MDC if not used.","type":"text"}]}]}]}]},{"type":"listItem","content":[{"type":"paragraph","content":[{"text":"idp.logging.MDC.createSession","type":"text","marks":[{"type":"strong"}]}]},{"type":"bulletList","content":[{"type":"listItem","content":[{"type":"paragraph","content":[{"text":"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.","type":"text"}]}]}]}]}]},{"type":"table","attrs":{"layout":"wide","width":1242.0,"localId":"dad8ec73-27bc-438a-bfd8-2b606a43c7fe"},"content":[{"type":"tableRow","content":[{"type":"tableHeader","attrs":{"colspan":1,"rowspan":1,"colwidth":[237.0]},"content":[{"type":"paragraph","content":[{"text":"MDC KEY","type":"text"}]}]},{"type":"tableHeader","attrs":{"colspan":1,"rowspan":1,"colwidth":[1005.0]},"content":[{"type":"paragraph","content":[{"text":"Description","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[237.0]},"content":[{"type":"paragraph","content":[{"text":"idp.version","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[1005.0]},"content":[{"type":"paragraph","content":[{"text":"The IdP version string","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[237.0]},"content":[{"type":"paragraph","content":[{"text":"idp.jsessionid ","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[1005.0]},"content":[{"type":"paragraph","content":[{"text":"The servlet container's JSESSIONID attribute","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[237.0]},"content":[{"type":"paragraph","content":[{"text":"idp.remote_addr","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[1005.0]},"content":[{"type":"paragraph","content":[{"text":"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.","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[237.0]},"content":[{"type":"paragraph","content":[{"text":"idp.server_hostname","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[1005.0]},"content":[{"type":"paragraph","content":[{"text":"The host name of the server to which the current request was sent","type":"text"}]}]}]},{"type":"tableRow","content":[{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[237.0]},"content":[{"type":"paragraph","content":[{"text":"idp.server_port","type":"text"}]}]},{"type":"tableCell","attrs":{"colspan":1,"rowspan":1,"colwidth":[1005.0]},"content":[{"type":"paragraph","content":[{"text":"The port number to which the current request was sent","type":"text"}]}]}]}]},{"type":"heading","attrs":{"level":5},"content":[{"text":"Example Logging Pattern using the Container Session ID","type":"text","marks":[{"type":"strong"}]}]},{"type":"codeBlock","content":[{"text":"%date{HH:mm:ss.SSS} - %level [%logger:%line] - [%mdc{idp.jsessionid}] - %msg%n","type":"text"}]},{"type":"paragraph","content":[{"text":"V5.1+ also supports extracting arbitrary HTTP request headers into MDC keys using a map defined in a bean named ","type":"text"},{"text":"shibboleth.MDCHeaders","type":"text","marks":[{"type":"strong"}]},{"text":". The map keys define the MDC keys to create and the values define the header name to read in:","type":"text"}]},{"type":"codeBlock","content":[{"text":"\n \n","type":"text"}]},{"type":"panel","attrs":{"panelType":"warning"},"content":[{"type":"paragraph","content":[{"text":"Notably, using the header feature creates some degree of risk from logging content created by the client and thus subject to manipulation. This may be a particularly risky choice when sending logs to external systems or operating on it in some way, so this feature is probably best limited to occasional use while debugging problems.","type":"text"}]}]},{"type":"heading","attrs":{"level":2},"content":[{"text":"Other Examples","type":"text"}]},{"type":"heading","attrs":{"level":3},"content":[{"text":"Preventing Audit Log Entry Duplication","type":"text"}]},{"type":"paragraph","content":[{"text":"Because the appender associated with the ","type":"text"},{"text":"idp-process.log","type":"text","marks":[{"type":"em"}]},{"text":" 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.","type":"text"}]},{"type":"paragraph","content":[{"text":"To prevent duplication of the audit log entries, you can add the attribute ","type":"text"},{"text":"additivity=\"false\"","type":"text","marks":[{"type":"code"}]},{"text":" to those loggers:","type":"text"}]},{"type":"codeBlock","content":[{"text":"\n \n\n\n\n \n\n\n\n \n","type":"text"}]},{"type":"heading","attrs":{"level":2},"content":[{"text":"Notes","type":"text"}]},{"type":"paragraph","content":[{"text":"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.","type":"text"}]},{"type":"paragraph","content":[{"text":"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.","type":"text"}]},{"type":"paragraph","content":[{"text":"Still another is the use of the back button.","type":"text"}]},{"type":"paragraph","content":[{"text":"You may eventually wish to apply ","type":"text"},{"text":"filtering","type":"text","marks":[{"type":"link","attrs":{"href":"http://logback.qos.ch/manual/filters.html"}}]},{"text":" 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.","type":"text"}]}],"version":1}