Shibboleth Developers

["Howard Gilbert" <>]

[background]

There is a hierarchy of Logger objects. A class either creates a new Logger or locates an existing one by calling the Logger.getLogger(String name) function. Any two classes that use the same name get back the same Logger object. Loggers are arranged in a tree formed by dot separated elements of the name. The Logger named "shibboleth" would be a parent of one named "shibboleth.initialization" which would be a parent of "shibboleth.initialization.XMLparser". There is a unique root Logger object that is the parent of all Loggers and has no name.

 

It is a common convention to obtain the names by using the fully qualified name of the class. This is a good idea if the package name hierarchy follows the logical structure of the program and if all methods of a class follow the same logging concerns, but this is not always the case.

 

A log statement is generated by calling a method of a logger. Whether the statement is actually written to the log is determined by comparing the Level of the message to the Level criterion set for the current Logger, or if it doesn't have a set Level, then for its nearest parent in the tree that does. Once the decision has been made to write it, however, the message is written to every Appender (file, console, socket) attached to every parent Logger node all the way up to the root, even when the Level of the Logger to which the Appender is attached is more selective and would not have included the message had it been written directly to that parent. Thus a remote child Logger set to DEBUG generates debug messages in a file attached to the Root even though the Root itself was set to ERROR.

 

[Shibboleth]

Shibboleth code generally followed the "name your logger the same as your class" philosophy. I have attempted to modify this by creating an artificial Logger name hierarchy prefixed by "shibboleth.init" for initialization operations. The objective is to collect messages arising from the setup of parsers and schemas, the parsing of XML configuration file, the loading and initialization of plugins, and so on. Although these things tend to occur first and therefore would be at the beginning of a comprehensive log, there is provision for a configuration file to be reloaded if it changes in the middle of the day. Obviously if you replace the Metadata at 3:00 PM and discover a problem with an IdP at 4:30, it is important that the update not be buried as a couple of lines in the middle of routine request processing. Giving them their own log makes them harder to miss.

 

Some classes have an initialization method and then some normal processing methods. Such a class can simply define two Loggers, one based on the ordinary package-class name and one based on the artificial "shibboleth.init" name. The initialization method uses the init Logger, and the other methods use the logger based on package name. This distinction cannot be always drawn perfectly, but when in doubt log to both Loggers.

 

Tomcat has special support for Log4J. If there is a WEB-INF/classes/log4j.properties file in the WAR, it will parse it and establish a logging environment before running anything in the application. Rather than relying on this, the SP has been designed so that someone deploying the code can add their own WEB-INF/classes/log4j.properties file, and set up an environment that the SP inherits and adds to. Rather than depending on an external configuration file, the additional SP configuration is done by code in the ContextListener.

 

The Java SP inherits from C++ a logger= attribute on the SPConfig main element of the configuration file. By the time this attribute is parsed, the XSD files have been compiled and some other initialization has been done. A decision had to be made what to do, and the current implementation treats the SPConfig logger= as an override. The previous logging hierarchy is completely replaced by a new hierarchy defined by this file.

 

The Tomcat approach is better, but it is Tomcat specific. The SPConfig logger works in all Servlet containers.

 

To successfully use the SPConfig logger feature, a user must be informed by the documentation that logging can occur under the edu.internet2 package tree, or the org.opensaml package tree, but in addition there is a "shibboleth.init" artificial tree for SP initialization.  Of course, for raw debugging the user is free to just configure the root Logger and get everything dumped in one location.

 

This brings up the problem of JUnit tests. JUnit runs in its own environment and if logging has not been setup, then the first log.xxx() method encountered generates an error message on the console. Although one could manually set up logging with Java code as part of the test setup method, a simpler alternative is to add a log4j.properties file to the "tests" subdirectory of the java part of the shibboleth CVS tree where all the log4j tests reside.

 

This now exposes an issue for Eclipse. If you have configured Eclipse to generate its output to the {shib}/webApplication/WEB-INF/classes location (a common trick in Eclipse), then it uses this as the destination of all Source directories including both /src and /test. If you are not careful to clean and recompile, JUnit tests can end up in the WAR. This is not a Shibboleth problem but rather the conflict of a number of different project structure conventions in wide use across many Java projects. I will update my developer documentation to suggest that Eclipse compile source only into a separate /build subdirectory (an alternate common Eclipse convention). This means that the Ant build.xml will always recompile the source separate from the Eclipse compile, but that guarantees that the JUnit tests only compile to /build and never show up in the WAR. This also means that the /test/log4j.properties file to configure logging during JUnit tests never accidentally gets copied to the WEB-INF/classes/log4j.properties location where Tomcat will process it for code running under the Web Server.