Tom has posted 1 posts at DZone. View Full User Profile

Monitoring Declarative Transactions in Spring

12.01.2008
| 45152 views |
  • submit to reddit

Designing a Solution with Logging

Class Loading

A transaction logging solution can be easily implemented for either Log4J or Java Logging, provided we watch out for class loading issues. Java Logging and typically Log4J are installed in a low-level class loader that does not have direct access to the Spring Framework classes needed to observe transaction status. Fortunately for us, Spring classes are accessible at runtime from the 'context class loader' attached to each thread. Using the context class loader and a little reflection, it's possible to invoke methods on TransactionSynchronizationManager to determine transaction status. The code below demonstrates how to determine the status for the current thread via reflection:

public class TransactionIndicatingUtil {
private final static String TSM_CLASSNAME = "org.springframework.transaction.support.TransactionSynchronizationManager";

public static String getTransactionStatus(boolean verbose)
{
String status = null;

try {
ClassLoader contextClassLoader = Thread.currentThread().getContextClassLoader();
if (contextClassLoader != null)
{
Class tsmClass = contextClassLoader.loadClass(TSM_CLASSNAME);
Boolean isActive = (Boolean) tsmClass.getMethod("isActualTransactionActive", null).invoke(null, null);
if (!verbose) {
status = (isActive) ? "[+] " : "[-] ";
}
else {
String transactionName = (String) tsmClass.getMethod("getCurrentTransactionName", null).invoke(null, null);
status = (isActive) ? "[" + transactionName + "] " : "[no transaction] ";
}
}
else
{
status = (verbose) ? "[ccl unavailable] " : "[x ]";
}
} catch (Exception e) {
status = (verbose) ? "[spring unavailable] " : "[x ]";
}
return status;
}
The method TransactionIndicatingUtil .getTransactionStatus above is suitable for our logging solution because does not directly reference the Spring Framework code. The next step is to invoke it from within the logging framework.

Plugging into Log4J

The ideal point to plug into the Log4J framework is at the Filter level. Filters intercept logging messages before they reach an Appender in Log4J (i.e., ConsoleAppender, FileAppender). We can create a filter that adds information to the MappedDiagnosticContext, or MDC, of the logging event. The MDC is essentially a Map of name/value pairs that are available to an Appender for output. Here's our filter implementation that adds a 'xaName' and 'xaStatus' property to the MDC: 

import static com.skillcorp.transactionlogger.TransactionIndicatingUtil.*;
...
public class TransactionIndicatingFilter extends Filter {
@Override
public int decide(LoggingEvent loggingEvent) {
loggingEvent.setProperty("xaName", getTransactionStatus(true) );
loggingEvent.setProperty("xaStatus", getTransactionStatus(false) );
return Filter.NEUTRAL;
}
}

 

To configure Log4J to use the new filter, edit the log4j.xml configuration file similar to the following (note use of %X{} in the conversion pattern):
   <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
<param name="Target" value="System.out"/>
<param name="Threshold" value="INFO"/>
<layout class="org.apache.log4j.PatternLayout">
<!-- The default pattern: Date Priority [Category] Message\n -->
<param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %X{xaStatus}- %m%n"/>
</layout>
<filter class="com.skillcorp.transactionlogger.log4j.TransactionIndicatingFilter"/>
</appender>
If your application uses log4j.properties rather than the xml configuration file, then another step is required. The log4j.properties format does not support configuration of filters. A workaround is to create a custom appender suited to the application, for instance, a custom ConsoleAppender:
public class TransactionIndicatingConsoleAppender extends org.apache.log4j.ConsoleAppender {
public TransactionIndicatingConsoleAppender()
{
addFilter(new TransactionIndicatingFilter());
}
}

Plugging into Java Logging

The logging framework built into Java also has a Filter layer that can be leveraged to insert our transaction decoration, but it does not have an analog to the MappedDiagnosticContext used with Log4J. To add our decoration in this case requires that we directly modify the application message in the logging record:

import static com.skillcorp.transactionlogger.TransactionIndicatingUtil.*;
public class TransactionIndicatingFilter implements Filter {
...
@Override
public boolean isLoggable(LogRecord record) {
record.setMessage(getTransactionStatus(isVerbose()) + record.getMessage());
return true;
}
...
}

 

Configuration is an additional wrinkle for the Java Logging filter. The transaction status can be indicated in either a terse or verbose format, selectable by the argument to getTransactionStatus(). In the Log4J filter above, the system simply adds both terse and verbose status fields to the MDC, and allows the appender / formatter to determine the correct log output. Since the MDC is not available in Java Logging, the filter must be configured to choose the correct output. The LogManager class exposes properties from the logging configuration file (default location: $JRE_HOME/lib/logging.properties)

    public TransactionIndicatingFilter() {
String $verbose = LogManager.getLogManager().getProperty(TransactionIndicatingFilter.class.getName() + ".verbose");
if ($verbose != null) {
verbose = Boolean.parseBoolean($verbose);
}
}
The logging.properties file should be configured as follows:

java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.ConsoleHandler.filter = com.skillcorp.transactionlogger.jdklog.TransactionIndicatingFilter
com.skillcorp.transactionlogger.jdklog.TransactionIndicatingFilter.verbose=true

An Implementation

You can access a Maven-based project with the source code and test cases for demonstrating the decorated output for each logging framework. A binary of the logging solution is also available here

Legacy
Published at DZone with permission of its author, Tom Cellucci.

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Comments

Yaozong Zhu replied on Mon, 2008/12/01 - 4:49am

This is quite a good idea indeed. I usually assume Spring transaction working for my apps without verifying it properly. Another idea comes up with from my little brain is to use Spring AOP, and all of your work could be done just in Spring configuration file instead.

Hoikin Wong replied on Mon, 2008/12/01 - 9:55am

Why not just enable spring's logger to monitor the transaction ?

Tom Cellucci replied on Mon, 2008/12/01 - 10:08am in response to: Yaozong Zhu

Using Spring AOP was an option that I considered as a solution, but it had a couple of negatives that swayed me towards the logging.  The first problem is that Spring AOP is just as 'magical' as the declarative transaction management itself, and therefore as prone to misconfiguration.  The second was that it's a little more intrusive to modify the spring configuration for an app after it's deployed; the typical WAR would have to be opened, modified and redeployed with the changes.  Certainly a viable solution though, not a bad idea at all if AOP's in your toolkit and you're implementing prior to deployment. 

-Tom

Tom Cellucci replied on Mon, 2008/12/01 - 10:18am in response to: Hoikin Wong

You certainly can turn on Spring's logging and get some output that indicates where the transactions start and stop.  The problem is that this output can end up far, far away from the logging output of code that is of interest.  In my experience a web application will open a transaction via filter when the request is recieved, and commit/rollback when it's done.  For significant applications, there can be many layers of logging between those points that obscure the transaction origin.  Compounding the problem is multi-threaded output, where the 'begin' or 'commit' logging that's immediately visible may not be from the thread executing the code of interest.  The solution proposed here decorates the logging statements your application already emits, so its transactional status is immediately obvious.

Yaozong Zhu replied on Mon, 2008/12/01 - 12:33pm in response to: Tom Cellucci

I can understand your point. It's like introducing a mechanism to monitor the same mechanism. It's just a quick and one-place-setting way to verify if transaction is working or not.

 

Our projects use JMX to adapt logging on the fry, which could be an backup solution for existing jmx-enabled system to turn on or off loggers retrieving relevant information with a plenty of irrevant one as you mentioned.

Paul Hixson replied on Mon, 2008/12/01 - 1:48pm

Nice article.  Reminds me of the time I spent a couple of days figuring out the a client needed record versioning in Hibernate.  Spring is so nice and quiet that it is hard to tell when something like TM is misconfigured. 

I like the logging solution personally, since, once you find something like this, it's always a prime suspect in future problems.  Logging quickly let's you prove the solution is still working.

Also, you're a better man than I am for plumbing the depths of Log4j **shudders**.

Rick Hightower replied on Mon, 2008/12/01 - 10:28pm

Nice. Good stuff! Thanks Tom.

Paul Grove replied on Wed, 2008/12/03 - 3:32am

Have you considered doing an example for LogBack? Log4j is no longer under active development and it seems to me SL4J with LogBack is starting to gain traction and will be the next evolution in Java logging. No more class loader issues of JCL!

Nice example thou cheers 

Tom Cellucci replied on Wed, 2008/12/03 - 10:43am in response to: Paul Grove

I worked up a quick example that uses Logback and SLF4J; it's present in the attachments.

Jan Novotný replied on Tue, 2008/12/09 - 12:34am

We have come to the same solution. I have published article (http://blog.novoj.net/2008/09/20/testing-aspect-pointcuts-is-there-an-easy-way/) on the same topic several months ago and ended up with the similar recommendation as you. The difference is, that I examine standard logging output of transaction advice (as well as other possible advices we want to check) instead of calling API on advised objects as you do. This way I am able to easily check even other Aspects than just Spring transaction Aspect, but on the other hand I am somewhat depending on advice internals - such as logging messages. I am trying to get over that issue with encapsulation of log messages checker. If you want to know details of my solutions, please go check it there: http://blog.novoj.net/2008/09/20/testing-aspect-pointcuts-is-there-an-easy-way/ (it's in English).

Carla Brian replied on Sun, 2012/07/29 - 5:28am

The ideas here are nice. At least I have learned new this day. This could really be helpful in the future. Good job on this. - Instant Tax Solutions Ratings

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.