Opengrok: Logging

This is an example, how we setup opengrok to use LOGBack as the logging backend instead of the Java/Opengrok default loggers when running it from the command line (CLI).

Why should the logger be changed ?

Basically the Java Utils Logging API/Implementation (often referred as JUL) has been designed to just provided the absolute minimum, which is required for logging. The designer's hope was, that thirdparty products will provide richer frameworks based on JUL, but because of its shortcomings, maybe overengineered design, performance, cumbersome configuration, etc. nobody took seriously the ball. So what we see is:

developers don't care, just use the JUL API and passing the ball to the customer (i.e. do the painful config for Java included Loggers and live with it[s very limited options])
developers re-invent the wheel again and again by implementing their own JUL based Logger stuff, which than is usually even more painful, broken, limited than the original (e.g. like the OpenGrokLogger.java) and even leads to absolutely wrong usage (like in opengrok), which removes the last bit of the flexibility, the original framework usually provides.
developers use a much simpler, really lightweight Logging API (like SLF4J) and let the customer choose the backend which provides the perfomance and flexebility they need (like LOGBack or JUL)
customers use a bridging implementation, which just "routes" all JUL logging "messages" to the logging framework/backend of choice. This is often implemented by usinging a custom JUL Handler, which transforms the incoming LogRecord into something, what the backend understands and than passing it to the backend[s]. So it may have the same bad or even a little bit worse performance as the original JUL!

However, since we have no choice, don't have the time to fix opengrok logging, the last thing is the only route, we can take for now.

Default Logging Configuration

Per default opengrok uses the JUL mechanism to configure logging. But since logging is completely messed up, often log messages are logged to the logger named "org.opensolaris.opengrok", only and thus makes fine grained/target oriented logging impossible. Furthermore it does a really stupid thing: as soon as one specifies the CLI option[s] -q or -v, it overwrites blindly the log level of all non-"org.opensolaris.opengrok" Console Loggers with Level.WARNING or Level.INFO respectively.

So, if you want logging behave as you specified in logging configuration, make sure to NOT use any of the -q or -v CLI options!!!

Last but not least, the logging configuration file: The one which comes with Opengrok really smells, and uses Opengrok's own Formatters. These Formatters do nothing but limitting the log format to a not very useful, fixed format and preventing you to configure, what stack trace should actually be logged - I call this logfile flooding (so another example of re-inventing the wheel very badly).

So, avoid using Opengrok's Formatters, which are org.opensolaris.opengrok.SimpleFileLogFormatter and org.opensolaris.opengrok.SimpleConsoleFormatter!

Finally, considering all points mentioned above, a better logging.properties file may look like this:

# logging handlers to use
handlers = java.util.logging.FileHandler, java.util.logging.ConsoleHandler

# default logging level for everything
.level=INFO

##############################################################################
# file handler default properties:
##############################################################################
# max. filesize = 5MB
java.util.logging.FileHandler.limit = 52428800
# if more than 3 file, delete the oldest one
java.util.logging.FileHandler.count = 3
# log everything, what gets passed to it
java.util.logging.FileHandler.level = ALL
# formatter to use to format LogRecords
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
# filename pattern format
java.util.logging.FileHandler.pattern = /data/opengrok/log/opengrok%g.%u.log
# encoding to use, when writing out the formatted String
java.util.logging.ConsoleHandler.encoding = UTF-8

##############################################################################
# console handler default properties:
##############################################################################
# don't log stuff less than level INFO (like CONFIG, FINE*)
java.util.logging.ConsoleHandler.level = INFO
# formatter to use to format LogRecords
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
# encoding to use, when writing out the formatted String
#java.util.logging.ConsoleHandler.encoding = UTF-8

##############################################################################
# Formatter properties
##############################################################################
# how the SimpleFormatter should format LogRecords
java.util.logging.SimpleFormatter.format = %1$tF %1$tT.%1$tL  %4$7s [%3$s] - %5$s%6$s%n

##############################################################################
# fine-grained logging
##############################################################################
# pass Indexer's log messages with level FINE to the configured handlers, too
# NOTE: depending on their configuration, they can still drop the log message!
org.opensolaris.opengrok.index.Indexer.level = FINE

For more information see:

SimpleFormatter API
FileHandler API
ConsoleHandler API
Log Levels API
OpenGrok's opengrok to check, which classes may bypass your configuration, by logging just to the "org.opensolaris.opengrok"-Logger instead of ${classname}-Logger - ignore the */management/* stuff (probably not used by anybody)
Or OpenGrok's opengrok to check, for which classes fine grained logging works

Test these settings, and if you are happy with it, you are done. ;-)

Bridging to LOGBack

If you are not happy with the very limitted JUL stuff, you may use SLF4J's BridgeHandler to redirect JUL message to an SLF4J backend like LOGBack (the successor of the wellknown Log4J logging framework).

The following examples assume, that opengrok is installed in /opt/opengrok/ and logging configuration file[s] go into /data/opengrok/etc/. Wrt. the default OpenGrok script the OPENGROK_INSTANCE_BASE would be /data/opengrok and the LOGGER_CONFIG_FILE = etc/logging.properties .

# change to a "garbage" directory
cd /tmp
# get slf4j via http://www.slf4j.org/download.html
wget http://www.slf4j.org/dist/slf4j-1.6.6.tar.gz
# unpack the archive
gunzip -c slf4j-1.6.6.tar.gz | tar xvf -
# copy the API and bridging lib into opengrok's lib directory
cp slf4j-1.6.6/jul-to-slf4j-1.6.6.jar slf4j-1.6.6/slf4j-api-1.6.6.jar \
	/opt/opengrok/lib/lib/
# get logback via http://logback.qos.ch/download.html
wget http://logback.qos.ch/dist/logback-1.0.6.tar.gz
# unpack the archive
gunzip -c logback-1.0.6.tar.gz | tar xvf -
# copy the relevant archives into opengrok's lib directory (logback-access*
# is optional - allows one to log into a database)
cp logback-1.0.6/logback-core-1.0.6.jar logback-1.0.6/logback-classic-1.0.6.jar \
	logback-1.0.6/logback-access-1.0.6.jar /opt/opengrok/lib/lib/
# remove the garbage
rm -rf logback-1.0.6 slf4j-1.6.6

# modify the opengrok.jar to pickup the new libraries as well
cp -p /opt/opengrok/lib/opengrok.jar /opt/opengrok/lib/opengrok.jar.orig
jar xf /opt/opengrok/lib/opengrok.jar.orig META-INF/MANIFEST.MF
cat META-INF/MANIFEST.MF | tr -d '\r' | nawk -F: \
	'/^Class-Path:/ { N=$0; getline; \
		while (NF == 1) { N = N substr($0,2) ; getline } \
	} \
	END { print N " lib/slf4j-api-1.6.6.jar lib/jul-to-slf4j-1.6.6.jar" \\
		" lib/logback-core-1.0.6.jar lib/logback-classic-1.0.6.jar" }' \
	> manifest.tmp
jar umf manifest.tmp /opt/opengrok/lib/opengrok.jar
rm -rf manifest.tmp META-INF

Of course the new log backend needs to be configured. To explore all the details and available features, please have a look at the LOGBack manual. As a starting point, save the content of the following example into a file named logback.xml and put it in the same directory, where your logging.properties for opengrok is stored.

<configuration debug="false">
	<!-- beeing able to switch the log level on the fly is not a bad idea ;-) -->
	<jmxConfigurator />

	<appender name="CONS" class="ch.qos.logback.core.ConsoleAppender">
		<!-- log entry formatting -->
		<encoder>
			<pattern>%date{HH:mm:ss.SSS} %highlight(%level): %message%n%rootException{short}</pattern>
			<immediateFlush>true</immediateFlush>
		</encoder>
		<!-- don't wanna clutter/flood console -->
		<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
			<level>INFO</level>
		</filter>
	</appender>
	<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
		<file>/data/opengrok/log/${HOSTNAME}.log</file>
		<!-- when log rotation should happen -->
		<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
			<maxFileSize>5MB</maxFileSize>
		</triggeringPolicy>
		<!-- how log rotation should be done -->
		<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
			<fileNamePattern>/data/opengrok/log/%i:${HOSTNAME}.log</fileNamePattern>
			<minIndex>0</minIndex>
			<maxIndex>3</maxIndex>
		</rollingPolicy>
		<!-- log entry formatting -->
		<encoder>
			<pattern>%date{HH:mm:ss.SSS} %level [%thread, %file:%line] - %message%n%rootException</pattern>
			<immediateFlush>true</immediateFlush>
		</encoder>
	</appender>
	<contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
		<resetJUL>true</resetJUL>
	</contextListener>

	<root level="WARN">
		<!-- catch all warning+ messages, no matter who sends it -->
		<appender-ref ref="FILE"/>
	</root>
	<logger name="org.opensolaris.opengrok">
		<!-- console should get log messages from opengrok classes, too -->
		<appender-ref ref="CONS" />
		<!-- in addition we wanna see opengrok related INFO messages as well -->
		<level value="INFO"/>
	</logger>
	<!--
		misc loggers, where it might be worth to enable DEBUG on demand
	    NOTE: one may specify packages as well (i.e. w/o classname)
	-->
	<!--
	<logger name="org.opensolaris.opengrok.index.IndexDatabase">
		<level value="DEBUG"/>
	</logger>
	<logger name="org.opensolaris.opengrok.index.IndexChangedListener">
		<level value="DEBUG"/>
	</logger>
	<logger name="org.opensolaris.opengrok.util.Executor">
		<level value="DEBUG"/>
	</logger>
	<logger name="org.opensolaris.opengrok.history.RepositoryFactory">
		<level value="DEBUG"/>
	</logger>
	<logger name="org.opensolaris.opengrok.history.SubversionHistoryParser">
		<level value="DEBUG"/>
	</logger>
	-->
</configuration>

As you can see in file log, now the log contains the file location of the log message emitter as well as the related line number - at least for developers a really big improvement wrt. JUL. Furthermore we are able to define different log formats for the file and console, which is for the normal user a good things because less cluttered with data, which don't make sense to him, anyway. Last but not least, restricting what goes to console is possible as well as in JUL (see console log), but more fine grained algorithms are available out of the box, if needed.

Well, almost done. What we still need to do is to tell LOGBack, where to find its configuration file. The most flexible way is to set the JVM property logback.configurationFile, but it is also possible to just add the directory, which contains the logback.xml to the classpath. The following command might be used to replace/insert the appropriate setting:

cp -p /opt/opengrok/bin/OpenGrok /opt/opengrok/bin/OpenGrok.orig
gsed -i -e '/LOGGER_PROPERTIES=/ s,-Dlogback.configurationFile=[^[:space:]"]*[[:space:]]*,,' \
	-e '/LOGGER_PROPERTIES=/ s,-,-Dlogback.configurationFile=/data/opengrok/etc/logback.xml -,' \
	/opt/opengrok/bin/OpenGrok

Finally create a logging property file, which sets the SLF4J BridgeHandler as the only JUL handler. If you wanna just test it, or want to be able to switch between plain JUL and SLF4J based loggin, just choose another file name (e.g. etc/slf4j-logging.properties) and set your LOGGER_CONFIG_FILE variable to the corresponding value. All it needs to contain is:

handlers = org.slf4j.bridge.SLF4JBridgeHandler
org.slf4j.bridge.SLF4JBridgeHandler.level=ALL

That's it!

If you don't like what you see or want to test, what JUL would give you, just set your LOGGER_CONFIG_FILE back to the original value, and you are done. I.e. there is no need to undo all modifications you made :).