Logging Inside IdP Views

Velocity is a light-weight template engine for producing user interface views, and it's generally easier to use than JSP, but one thing it doesn't handle is access to Java objects, creating new objects, etc., anything that generally relies on unanticipated access to the Java runtime. Logging is one of the things that isn't directly supported because of that limitation, but it's easy to do this.

The main hook for any use case involving this sort of thing is the $custom Velocity variable that is supplied by the IdP into most of the templates at runtime. This variable simply points to any Java bean you define with the name shibboleth.CustomViewContext, which is conventionally defined in conf/global.xml so that it's visible to all the views in the system. By default there isn't such a bean, so you have to define it.

It's particularly common to want to expose more than one different bean to different views at the same time to accomodate different use cases, so the convention is typically to define that bean as a Java Map object that you can access different entries of to get at different custom objects by name.

This example illustrates that technique, and shows how to use it to define a logging object and use it in a view.

There's a set of cases during error handling where this mechanism doesn't work, because various low-level error conditions trigger outside of Spring Web Flow actually running our code, so they happen without our control and don't get the necessary objects injected into Velocity. As an example, a lot of the back button errors you'll see cause low-level exceptions and the error view wouldn't have a $custom variable defined, nor most of the rest we populate.

The step by step:

Define a map bean in conf/global.xml containing a logging category bean.
Access the bean in one of your views.

First define the map and the logging object:

<!-- ... somewhere in global.xml... -->

<util:map id="shibboleth.CustomViewContext">
	<entry key="Logger">
		<bean class="org.slf4j.LoggerFactory" factory-method="getLogger" c:_0="com.example.thing" />
	</entry>
</util:map>

To use the logger in a Velocity template:

## somewhere in a view template...
$custom["Logger"].debug("A thing happened...")

If you adjust the "com.example.thing" level to DEBUG, the idp-process log will contain:

12:36:55.855 - 192.168.1.1 - DEBUG[com.example.thing:-2] - A thing happened...