Simplify Shibboleth IdP Debugging: Quickly Identify Related Log Entries

Why isn’t it possible to easily identify all log messages belonging to particular user that authenticated at a Shibboleth Identity Provider?” This question was asked at the SWITCH Shibboleth Training in June 2015. Many other Shibboleth Identity Provider (IdP) administrators acknowledged they miss such a useful feature too. It would make debugging Shibboleth login issues easier since parallel user logins at the IdP result in many log entries that become a challenge to analyze. By default, the IdP does not provide enough log information to identify all related log entries  for a particular login attempt.

The answer to this question is: This is possible! It’s in Shibboleth already and it’s easy to use but it is a bit hidden. There are two key ingredients needed to activate this.

The first key ingredient to achieve the above goal is to know how to adapt the Shibboleth logging configuration. For the Shibboleth IdP 2.x, the logging configuration is defined in the file shibboleth-idp/conf/logging.xml. For the Shibboleth IdP 3.x it is in shibboleth-idp/conf/logback.xml. The logging configuration allows defining what and how log messages are created, formatted and stored. Therefore, this file is crucial for our mission.

The second key ingredient is to mark all log entries of a particular user session. So we have to add a unique identifier to log entries of each user session.  How to do this is described in the Shibboleth Wiki on the Logging Configuration (for IdP v3) page. In the section ‘Mapped Diagnostic Context’ it says about Logback, Shibboleth’s logging component:

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:

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.

What does this mean? It means that the Identity Provider logging configuration can easily be modified to include the above information in every log message. To identify all log messages that belong to a particular user session, one just has to edit the Shibboleth Identity Provider logback.xml. More precisely, one of the following strings has to be added to a log pattern:

Shibboleth Identity Provider 2.x Shibboleth Identity Provider 3.x
 IP Address [%mdc{clientIP}] [%mdc{idp.remote_addr}]
 Java Session ID [%mdc{JSESSIONID}] [%mdc{idp.jsessionid}]

Even though it might be tempting to use the IP address to be added for all log messages, this alone might not be ideal in case users are behind proxy servers and thus share the same IP address. Therefore, a more reasonable choice is to mark all log messages with the Java Session ID that is unique and set per client. The Java Session ID is stored in a client-side cookie and therefore also available for each HTTP request.

Now let’s use these two ingredients and the information above in a reasonable real-world example.

Example:

To identify all log messages of a particular user in the xshibd.log file (the Shibboleth IdPs’ main log file) perform the following steps for a Shibboleth Identity Provider 3.x:

  1. Open the logging configuration file shibboleth-idp/conf/logback.xml
  2. Look for the the element <Pattern> within the element <appender> with name="IDP_PROCESS"
  3. Insert the string “[%mdc{idp.jsessionid}]” in the log pattern such that it looks for example like this:
    <Pattern>%date{ISO8601} - %level [%logger:%line] - [%mdc{idp.jsessionid}] - %msg%n%ex{short}</Pattern>
  4. Restart the Shibboleth Identity Provider (e.g. by restarting Tomcat or Jetty)
  5. Do a test login and then check the /opt/shibboleth-idp/shibd.log file

The above steps are very similar for a Shibboleth IdP 2.x

After the restart, log entries for a login with default log level INFO then should look like (date removed for styling purposes) this:

INFO [org.ldaptive.auth.Authenticator:259] - [1D2571E58C1661044B57117BB17EDC6D] - Authentication succeeded for dn: cn=Test1 Student,ou=People,dc=example,dc=org
INFO [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:182] - [1D2571E58C1661044B57117BB17EDC6D] - Profile Action ValidateUsernamePasswordAgainstLDAP: Login by 'student1' succeeded
INFO [Shibboleth-Audit.SSO:241] - [1D2571E58C1661044B57117BB17EDC6D] - 20150611T134936Z|urn:mace:shibboleth:2.0:profiles:AuthnRequest|_3d72c0b9-c691-481f-99b4-ff7b9bb81bdd|https://attribute-viewer.aai.switch.ch/shibboleth|http://shibboleth.net/ns/profiles/saml2/sso/browser|https://aai-login.example.org/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_b8ab17261415bdd17214e5fee9a754a7|student1|urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport|eduPersonAffiliation,email,eduPersonScopedAffiliation,eduPersonTargetedID|AAdzZWNyZXQxHQIbyM7MO5vWe7OHs3+0TV94xKTbkwmQ3klI9ds8j94ZuS/VEti+HU2DgrpABHfcZfhfUokB61KykblTTN5m9sEnKDviohb7NPBIWq9A90ijVkB+xykxwTkTDZlZ72rF/eFwHCNbzUrkofNi85kHlfiuZKAMPy1j|_3aa759795107af4f5f4846f5218d719e

Increasing the log level to DEBUG will produce a lot more log entries (ensure there is sufficient hard disk space available for that and don’t forget to reduce the log level after debugging) including the same Java Session ID. Notice the Java Session ID (in blue) that now allows to easily identify all log requests for that user session, e.g. by using a command like:

grep 1D2571E58C1661044B57117BB17EDC6D shibd.log"

Taking this one step further, one might also add the Java Session ID to Apache log entries. To do that add the following string to the LogFormat directive of a suitable Apache logging facility, as is described on the Apache Logging documentation page:

\"%{JSESSIONID}C\"

The above will basically add the value of the Java Session ID cookie (named JSESSIONID) to all log entries if available. However, there is one limitation: The Java Session ID – and its cookie – is created only after the first request by a client, i.e. after the very first HTTP request sent by the client. Therefore, the first request of a client cannot be logged with the Java Session ID value. If one adds the Java Session ID as well as the client IP address, it should be easy to also associate the first request by the user to the rest of the requests.

Author: Lukas Hämmerle

I'm a member of the SWITCHaai team, the Swiss edu-ID team and task leader in the GÉANT project.

Comments are closed.