Rushing to Judgement

Customizing Logging Output with ColdFusion and Log4j

In the first part of this series, I introduced you to integration of ColdFusion with the Apache Log4j framework using the open-source CFLog4j package. By the end of my second article, we were writing our logs to a database of our choice. If you're like me, you spent quite a bit of time on trial and error learning the basics of using these technologies together, reading a lot of log files in the process! You may have noticed the profound lack of detailed fields available to you in your log output; somehow, concatenating several fields into a single message feels like cramming a square peg into a round hole.

In this article, I will show you how easy it is to customize your logging output to include whatever information you deem relevant!

Nested Diagnostic Contexts

Log4j provides an implementation of Nested Diagnostic Context (NDC), which is a fancy way of saying that we can record customized contextual attributes which allow the logs to be distinguished when multiple transactions occur near-simultaneously. Since NDCs are managed on a per-thread basis, we can safely use them to store identifying information along with our log payload. Additionally, Log4j provides a Mapped Data Context (MDC) which is based on a map, a structure that underlies the ColdFusion struct concept. In my example I will use the MDC for storing data that we want to record to the logs to help identify it better.

Extending CFLog4j

I decided that the best way to add extra attributes to the logs is be pass in a struct containing the additional key/value pairs into the top-level logging methods. In order to do this, we must override all four of the logging methods (info(), debug(), warn(), and error()) must be modified to accept an additional argument and pass it on to the logMessage() method, which also will be overridden to operate with this data. Once this is completed we can create a struct containing things like user name, IP address, or even the name of the event that caused the log entry to be recorded. I am working on another post that addresses continual verbose logging in Mach-II applications that employs just this technique.

Included here is the code for MyLog4j.cfc, which extends the base CFLog4j component to include the contextual logging functionality. You will notice that I've created three additional variables to process the extended attributes we are logging. Thanks to Qasim's excellent work on CFLog4j, I am able to use his class loader to create an instance of the org.apache.log4j.MDC object, which I then use to put() all of the extended attributes. At this point the call to logger.log() is the same as before; the object will be aware of the MDC and will be able to access the properties stored inside it. Finally, as a cleanup step I remove all of the values loaded into the MDC with remove(). At this point the only thing left to do is to configure the Log4j properties file, so that we can tell the Appender that it should record our additional information.

<cfcomponent displayname="MyLog4j" 
			 hint="Custom CFLog4j Object to write extended properties" 
			 extends="com.cflog4j.CFLog4j" 
			 output="false">
				 
	<cffunction name="info" returntype="void" access="public" output="false" hint="">
		<cfargument name="logger" type="any" required="true" hint="Logger" />
		<cfargument name="message" type="string" required="true" hint="message to be logged." />
		<cfargument name="extendedAttributes" type="struct" required="false" default="#structNew()#" hint="Key/value pairs of additional properties" />
		<cfset logMessage( arguments.logger, 'info', arguments.message , arguments.extendedAttributes ) />
	</cffunction>
	
	<cffunction name="debug" returntype="void" access="public" output="false" hint="">
		<cfargument name="logger" type="any" required="true" hint="Logger" />
		<cfargument name="message" type="string" required="true" hint="message to be logged." />
		<cfargument name="extendedAttributes" type="struct" required="false" default="#structNew()#" hint="Key/value pairs of additional properties" />
		<cfset logMessage( arguments.logger, 'debug', arguments.message , arguments.extendedAttributes ) />
	</cffunction>
	
	<cffunction name="warn" returntype="void" access="public" output="false" hint="">
		<cfargument name="logger" type="any" required="true" hint="Logger" />
		<cfargument name="message" type="string" required="true" hint="message to be logged." />
		<cfargument name="extendedAttributes" type="struct" required="false" default="#structNew()#" hint="Key/value pairs of additional properties" />
		<cfset logMessage( arguments.logger, 'warn', arguments.message , arguments.extendedAttributes ) />
	</cffunction>
	
	<cffunction name="error" returntype="void" access="public" output="false" hint="">
		<cfargument name="logger" type="any" required="true" hint="Logger" />
		<cfargument name="message" type="string" required="true" hint="message to be logged." />
		<cfargument name="extendedAttributes" type="struct" required="false" default="#structNew()#" hint="Key/value pairs of additional properties" />
		<cfset logMessage( arguments.logger, 'error', arguments.message , arguments.extendedAttributes ) />
	</cffunction>
	
	<!--- Private Methods --->
	<cffunction name="logMessage" returntype="void" access="private" output="false" hint="">
		<cfargument name="logger" type="any" required="true" hint="Logger" />
		<cfargument name="type" type="string" required="true" hint="" />
		<cfargument name="message" type="string" required="true" hint="message to be logged." />
		<cfargument name="extendedAttributes" type="struct" required="true" hint="Additional attributes to log" />
		<cfset var priority = createClassFromLog4jarLoader( 'org.apache.log4j.Priority' ).toPriority( arguments.type )>
		
		<cfset var key = "" />
		<cfset var value = "" />		
		<cfset var MDC = createClassFromLog4jarLoader( 'org.apache.log4j.MDC' ) />
		
		<cfloop collection="#arguments.extendedAttributes#" item="key">
			<cfset value = arguments.extendedAttributes[key] />
			<cfset MDC.put( key , value ) />
		</cfloop>		
		
		<cfif canLog( arguments.logger, priority, arguments.type )>
			<cfset arguments.logger.log( priority, arguments.message ) />
		</cfif>
		
		<cfloop collection="#arguments.extendedAttributes#" item="key">
			<cfset value = arguments.extendedAttributes[key] />
			<cfset MDC.remove( key ) />
		</cfloop>		
		
	</cffunction>
</cfcomponent>

Updating the Log4j Properties File

The properties file that you update depends on whether or not your application records logs to a database. If so, you'll also need to ensure that the extra columns that will contain these properties have been created and update the SQL statement accordingly. I am only showing an example for disk-based logging at this point but it should be straightforward to update the SQL statement to allow for the additional attributes.

For each attribute you add to the extendedAttributes struct you will need to update the ConversionPattern in the properties file. Log4j lets you specify the names of the properties with %X{attribute name}. So, if you created an attribute in the code that calls the logging method named 'username', to specify it in the ConversionPattern you would write %X{username}. This will cause the logfile to contain that information in addition to whatever else was in your ConversionPattern string to begin with.

Below is a short program listing that contains an updated version of the testCFLogger.cfm template included with the CFLog4j package. I am also including an updated properties file that shows the usage outlined above. Combined with the MyLog4j.cfc code, this is enough for you to build a working example in your development environment.

<!---- Initialize CFLogger as a singelton in application scope. --->
<!---
<cfif not structkeyexists( application, 'init' )>
--->
	<!--- create the CFLog4j Config object. --->
	<cfset CFLog4jConfigPath = '/var/www/cflog4j/config/cflog4j.xml' />

	<cfset CFLog4jConfig = createobject( 'component', 'com.cflog4j.CFLog4jConfig' ).init( CFLog4jConfigPath )>
	<cfset application.CFLog4J = createobject( 'component', 'com.cflog4j.MyLog4j' ).init( CFLog4jConfig ) />
	<cfset application.init = true />
<!---
</cfif>
--->
<!--- get a category instance from CFLog4j. those instances can be defined in cflog4j.properties file. --->
<cfset logger = application.CFLog4J.getCategoryInstance()>


<cfset extendedAttributes = structNew() />
<cfset extendedAttributes['username'] = 'domainSername' />
<cfset extendedAttributes['ipaddress'] = cgi.remote_host />


<cfset application.CFLog4J.info( logger, "It's hard enough to find an error in your code when you're looking for it; it's even harder when you've assumed your code is error-free (Steve McConnell).", extendedAttributes )>
<!--- This will not show up unless you change the Category level to DEBUG in properties file --->
<cfset application.CFLog4J.debug( logger, "It's hard enough to find an error in your code when you're looking for it; it's even harder when you've assumed your code is error-free (Steve McConnell).", extendedAttributes )>

Closing Thoughts

When I first developed this approach, I started to go crazy with logging statements in my application. IP address, user name, Mach-II event name, event arguments, etc. While there's nothing wrong with being verbose if you can afford the disk space, there's definitely a performance penalty for logging what amounts to every detail of a user click. Additionally, I ran into unexpected database errors when I shared a datasource between the logging function and the other features in the app. At a minimum, I recommend setting up a separate datasource and doing all of your logging against that instead of mixing logging and business queries in your app's main datasource.

Even when using separate data sources, you may find that application performance becomes sluggish as every action is logged to the database. Fortunately, as of ColdFusion 8, event gateways are available to all versions of CF. I have had success migrating my logging to an asychronous model, where my application code throws the logging operation over the wall and allows it to happen behind the scenes. I will be writing about this in an upcoming post.

Once again, Happy Logging!