Plague of jar files

One of the development app servers that we recently upgraded to Java 6 and JBoss 5.0.0.GA’s hard drive filled up.  I emptied 4GB out of the Recycle Bin, which let a build complete Friday, but by this morning it was full again.

A diligent co-worker discovered a server\default\tmp\vfs-nested.tmp\ directory containing 67,444 hexadecimally-named jar files totalling 16GB in size.

The Research

A quick search turned up this in the JBoss 5.0.0.Beta4 Release Notes:

Excessive nestedjarNNN.tmp files in the tmp directory. The VFS unwraps nested jars by extracting the nested jar into a tmp file in the java tmp directory. This can result in a large number of files that fill up the tmp directory. You can disable this behavior by setting -Djboss.vfs.forceNoCopy=true on command line used to start jboss. This will be enabled by default in a future release, JBAS-4389.

That was 5.0.0 Beta 4.  In 5.0.0.CR1, JBAS-4389 made NoCopy the default behavior.  Also in CR1 though, JBAS-5262 replaced the jboss.vfs.forceNoCopy setting with a jboss.vfs.forceCopy setting defaulting to false; and JBAS-5633 enabled jboss.vfs.forceCopy by default, if unspecified.

SO THAT… by the time you get to the JBoss 5.0.0.GA Release Notes, we see:

JBoss VFS provides a set of different switches to control it’s internal behavior. JBoss AS sets jboss.vfs.forceCopy=true by default.

A Workaround

I gather that to turn off the copying for JBoss5.0.0.GA, we would set


on the JBoss command line.

Update: It looks like when we set the forceCopy flag to false, the heap space may fill up in memory instead.  We may need a better solution!

Update 2: In this JBoss forum thread, alesj says:

I’ve got the fix locally, just need to create some proper long running tests.  But this will be definitely included in the up-coming 5.0.1.

A problem that didn’t show up until later

Earlier this fall, a problem showed up when the database guys first contributed Hibernate mappings.  It was unclear how the Hibernate mappings could be causing the error we were getting — and it turned out that they weren’t; rather, they were exposing a different error that had previously been there, undetected.

I find these types of things really annoying before they’re figured out, and fascinating afterward.  Here’s an email I sent out afterward:

From: Daniel Meyer
Sent: Wednesday, September 24, 2008 3:42 PM
Subject: RE: Build Failures: resolved

The “deployment fails the second time” issue has been resolved, and the CI servers are back in business.

For those who may be interested, the problem turned out to be a Maven config issue in [the functional test project]’s pom file.

(Note: you may need your techno-gibberish decoder goggles for the next details: )

In making ojdbc available to Liquibase for when we deliver schema changes, the ojdbc jar file got included in the war file.  The config has been this way for several weeks, but we didn’t notice it until we just in the last few days got to the point of contributing Hibernate mappings, which starts the Persistence service, which needs ojdbc to actually work.  At that time, the ojdbc jar in the war file fought with the ojdbc jar in JBoss’s server/default/lib directory, and just like when you were fighting with your sister over that cookie, nobody won and we got the NoClassDefFoundError.

(Or something vaguely similar to that.)

Thanks to [those who helped] for their help with this!

Now back to our regular programming…


The versioning isn’t happening, part 4a: phone a friend

This post is part 5 in a 9-part series on Envers, Spring, and JTA. The next post is beforeCompletion, I need to figure this out, and the previous post is The versioning isn’t happening, part 4: Registering with the wrong transaction?

The time had come to ask my questions at the Spring Data Access forum.  Following is a copy of that forum post (Whew, does it take work to try to ask a question well!) :

Sychronization hook not called when using JTA txmgr

We’re using Spring 2.5.5 on JBoss 4.2.2.GA, along with JBoss envers version 1.1.0.GA. (Envers uses Hibernate’s onPostInsert() hook to register a javax.transaction.Synchronization callback that’s called during transaction commit, to write audit records about records that were created during that transaction.)When we use Spring’s HibernateTransactionManager and write a record, the registered envers javax.transaction.Synchronization.beforeCompletion () event handler fires as expected, but when we use Spring’s jta-transaction-manager, the registered envers beforeCompletion() event handler does not fire. In this post, after sketching our configuration, I discuss what I see working the same and different between the HibernateTransactionManager and jta-transaction-manager scenarios, and close by pointing out where I think the problem might be in Spring.

Our Configuration
We’ve configured the Hibernate sessionFactory bean to hook it up to envers’ VersionsEventListener (which implements org.hibernate.event.PostInsertEventListener):

<bean id="versionsEventListener" class="org.jboss.envers.event.VersionsEventListener" />
	<bean id="sessionFactory" class="org.springframework.orm.hibernate3.annotation.AnnotationSessionFactoryBean">
<property name="eventListeners">
				<entry key="post-insert">
					<ref local="versionsEventListener" />

With this configuration, every time a new row is inserted into the main table,

  1. org.jboss.envers.event.VersionsEventListener.onPos tInsert(PostInsertEvent event) is called
  2. onPostInsert() passes event.getSession() to org.jboss.envers.synchronization.VersionsSyncManag er.get(EventSource)
  3. VersionsSyncManager.get() then calls getTransaction() (which returns a JDBCTransaction) on the EventSource
  4. Finally, VersionsSyncManager.get() calls registerSynchronization() on this transaction to register a javax.transaction.Synchronization object whose beforeCompletion() method should be called during the transaction commit.

It is the code in this beforeCompletion() method that does the writing of the versioning records.

HibernateTransactionManager vs. JtaTransactionManager
When I set up my .war project’s Spring beans to use the Hibernate transaction manager:

<bean id="transactionManager" class="org.springframework.orm.hibernate3.HibernateTransactionManager">
<property name="sessionFactory" ref="sessionFactory" />

then the VersionsEventListener.onPostInsert() call happens as I have descibed, and later the registered beforeCompletion() hook is called and envers writes my audit records to the database. But when I remove the above bean and use the JTA transaction manager:

	<tx:jta-transaction-manager />

the VersionsEventListener.onPostInsert() call still happens and I do see registerSynchronization() being called; but this time the envers beforeCompletion() hook never gets called (and thus the audit records are not written to the database).

Registering with a JDBCTransaction, Committing a UserTransaction?
That’s the main symptom. I’ll now speculate on the cause… : )

When I’m using the HibernateTransactionManager, I notice that its doCommit() method makes this call:


Here, getTransaction() returns an org.hibernate.transaction.JDBCTransaction (the same one that envers called registerSynchronization() on earlier). As part of this commit(), the JDBCTransaction calls its notifyLocalSynchsBeforeTransactionCompletion() method, which calls the javax.transaction.Synchonization.beforeCompletion( ) registered by envers. So I see how the hook works on the HibernateTransactionManager side. On the JtaTransactionManager side though, org.springframework.transaction.jta.JtaTransaction Manager.doCommit() makes this call:


Here, getUserTransaction() returns the javax.transaction.UserTransaction, and then we call commit() on that. This commit() call does not result in the envers javax.transaction.Synchronization.beforeCompletion () being called. Something I notice here is that envers’ onPostInsert() method caused registerSynchronization() to be called on a JDBCTransaction object, not the UserTransaction object. This JDBCTransaction object appears to be unused for the purposes of committing.

Why I think it might be an issue in Spring
Envers’ VersionsEventListener.onPostInsert(PostInsertEvent event) method receives an org.hibernate.event.PostInsertEvent, and it is from this event that envers eventually calls (effectively):


Envers is registering its Synchronization object with the transaction given to it by the PostInsertEvent — I don’t immediately see how it could do any differently (though I’m far from an expert at these things)…Meanwhile, I don’t see where Spring is informing the UserTransaction about these registered synchronizations, and I don’t see Spring taking care of them itself either. It seems to my uneducated eyes that Spring should be doing one or the other of these, so that the registered callbacks aren’t just lost. Is there something I’m missing?

Thank you for your patience with this long post!

The versioning isn’t happening, part 4: Registering with the wrong transaction?

This post is part 4 in a 9-part series on Envers, Spring, and JTA. The next post is The versioning isn’t happening, part 4a: phone a friend, and the previous post is The versioning isn’t happening, part 3: it’s in UserTransaction?

Looky here:

While looking at the javadoc for javax.transaction.Synchronization earlier, I had noticed this:

Using the registerSynchronization method, the application server registers a Synchronization object for the transaction currently associated with the target Transaction object.

Now, the only registerSynchronization() method I see is javax.transaction.Transaction’s registerSynchronization() method, and the one place that registerSynchronization() is called from the envers code is in org.jboss.envers.synchronization.VersionsSyncManager.get(EventSource).

Here’s an interesting thing: when I set a breakpoint on VersionsSyncManager.get(EventSource) and start stepping through the code, the first thing it does (line 47) is do a session.getTransaction().  I expected that underneath, this would be our javax.transaction.UserTransaction (since we’re running in JTA mode), but instead when we call transaction.registerSynchronization() I see that we have a org.hibernate.transaction.JDBCTransaction.

Wrong Number?

So to step back a moment, what we have here is a Synchronization being registered with a JDBCTransaction, when the actual work will be done by a javax.transaction.UserTransaction.  It seems plausible that when the UserTransaction goes to commit, it won’t run these registered synchronizations (since it seems it wouldn’tknow about them).

Why does EventSource.getTransaction() return a JDBCTransaction instead of the UserTransaction?

EventSource extends org.hibernate.Session, and the javadoc for org.hibernate.Session.getTransaction() has this interesting tidbit:

The class of the returned Transaction object is determined by the property hibernate.transaction_factory.

The closest to this that I see in the AnnotationConfig is:


So what does SpringTransactionFactory do?

Hmm: org.springframework.orm.hibernate3.SpringTransactionFactory.createTransaction(JDBCContext, Context) returns a new JDBCTransaction, even if we’re in JTA mode.  That is the transaction that is returned (I think) by org.hibernate.Session.getTransaction().  Is that a bug?  Or alternatively, is the problem that Spring’s JtaTransactionManager calls commit() on the UserTransaction directly, without taking into account the synchronizations registered on the companion JDBCTransaction object?  It seems that one way or another, someone should be taking responsibility for getting those registered callbacks called!

(Next: Time to ask for help!)

The versioning isn’t happening, part 3: it’s in UserTransaction?

This post is part 3 in a 9-part series on Envers, Spring, and JTA. The next post is The versioning isn’t happening, part 4: Registering with the wrong transaction?, and the previous post is The versioning isn’t happening, part 2: beforeCompletion.

We’re trying to figure out why the envers versioning records are not created when our project uses a JTA transaction manager — it creates the versioning records just fine when we’re using local Hibernate transactions.

In part 2, we discovered that while org.jboss.envers.synchronization.VersionsSync.beforeCompletion() is called when we’re running in Hibernate mode, it is not getting called when we’re in JTA mode, even though onPostInsert is being called just like in Hibernate mode.

To dig farther toward the root of this, let’s see where the call to beforeCompletion() comes from when we’re in Hibernate mode…

1. Hibernate mode

I deployed the hibernate-mode version again and sent a message with a method-entry breakpoint on the VersionsSync beforeCompletion() call.  This time, I set breakpoints on the lines farther up the call stack — the last six entries in the chain of calls yielding the call to beforeCompletion().  My list of breakpoints now looks like this:

AbstractPlatformTransactionManager [line: 678] - commit(TransactionStatus)
AbstractPlatformTransactionManager [line: 709] - processCommit(DefaultTransactionStatus)
HibernateTransactionManager [line: 655] - doCommit(DefaultTransactionStatus)
JDBCTransaction [line: 109] - commit()
JDBCTransaction [line: 228] - notifyLocalSynchsBeforeTransactionCompletion()
TransactionAspectSupport [line: 321] - commitTransactionAfterReturning(TransactionInfo)
VersionsSync [entry] - beforeCompletion()

Now we’ll run it in jta mode and see if we get to any of these breakpoints.

2. JTA mode

We do break at TransactionInterceptor(TransactionAspectSupport).commitTransactionAfterReturning(TransactionAspectSupport$TransactionInfo) line: 321 (but… ohhhh, I stepped too slowly and the transaction timed out, yielding a stack trace!  Trying again…)

We’re at JtaTransactionManager(AbstractPlatformTransactionManager).commit(TransactionStatus) line: 678 and then JtaTransactionManager.doCommit(DefaultTransactionStatus)… so far this is just like Hibernate mode.  org.springframework.transaction.jta.JtaTransactionManager.doCommit(DefaultTransactionStatus) mainly just does txObjext.getUserTransaction().commit() (line 1028) — this is still analogous to what we see on the Hibernate-mode side (there, it’s org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(DefaultTransactionStatus), which mainly just calls txObject.getSessionHolder().getTransaction().commit() (line 655).)

2.1. A closer look at the Hibernate-mode commit() call

Let’s look more closely at this call:


The getTransaction() call returns a org.hibernate.transaction.JDBCTransaction object, which we then call commit() on.  And it is this commit() method that calls org.hibernate.transaction.JDBCTransaction.notifyLocalSynchsBeforeTransactionCompletion(), which calls the beforeCompletion() method.

2.2. The Difference on the JTA Side

The call mentioned in step 1.2.1. is what causes beforeCompletion() to be called (which creates the envers versioning records) when we’re in Hibernate mode.  The analogous call when we’re in JTA mode is:


(Called by org.springframework.transaction.jta.JtaTransactionManager.doCommit(DefaultTransactionStatus) on line 1028.)

Now, getUserTransaction() returns the javax.transaction.UserTransaction from JBoss; and then we call commit() on that.  Somewhere inside that commit() call, javax.transaction.Synchronization.beforeCompletion()* is not being called.

*VersionsSync implements javax.transaction.Synchronization; any beforeCompletion() call in an app server’s UserTransaction would reference the javax.transaction.Synchronization interface rather than org.jboss.envers.synchronization.VersionsSync, I’m sure!

In our next installment, let’s look into why UserTransaction is not calling beforeCompletion().

The versioning isn’t happening, part 2: beforeCompletion

This post is part 2 in a 9-part series on Envers, Spring, and JTA. The next post is The versioning isn’t happening, part 3: it’s in UserTransaction?, and the previous post is The versioning isn’t happening, part 1: wanderings.

We’re trying to figure out why the envers versioning records are not created when our project uses a JTA transaction manager — it creates the versioning records just fine when we’re using local Hibernate transactions.

Our approach last time was to see what differences there might be in the Hibernate configuration.  I ended up that post with

Perhaps next I should capture the values of the rest of AnnotationConfiguration’s 47 fields, and compare them all between jta mode and Hibernate mode.

-1. The Other 47 Fields

After I stopped writing last time, I did go on to capture the 47 AnnotationConfiguration fields’ values when running in Hibernate mode and when running in JTA mode, and… they were the same!  (Keith suspected they would be.)

0. No Other Apparent Magic During JBoss Startup

Still running in Hibernate mode, I followed the control flow after the creation of the Hibernate SessionFactory bean, but I didn’t see anything interesting-looking.  It’s hard to let the idea go that something’s different at startup time, but I think next I need to take a closer look at what happens during a save to the database.

1. A list of work to do later

Let’s see where the envers onPostInsert() hook gets called from, in hibernate mode (i.e., where things are working correctly). Here’s the call stack:

Daemon Thread [http-] (Suspended (entry into method onPostInsert in VersionsEventListener))
VersionsEventListener.onPostInsert(PostInsertEvent) line: 88
EntityInsertAction.postInsert() line: 131
EntityInsertAction.execute() line: 110
ActionQueue.execute(Executable) line: 279
ActionQueue.executeActions(List) line: 263
ActionQueue.executeActions() line: 167
DefaultFlushEventListener(AbstractFlushingEventListener).performExecutions(EventSource) line: 298
DefaultFlushEventListener.onFlush(FlushEvent) line: 27
SessionImpl.flush() line: 1000
GreetingDAO(GenericDAO<PO,PK>).create(PO) line: 66
GreetingDBSvcImpl.saveGreeting(GreetingPTO) line: 25
GreetingSvcImpl.saveGreeting(GreetingDTO) line: 21
HelloWorldSvcImpl.writeGreetingToDatabase(Greeting) line: 24
NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]
NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39

1.1. It’s all the same in JTA mode

I set breakpoints at most of these places.  Let’s try it in jta mode:

  • We get to the session.flush() in GreetingDAO(GenericDAO<PO,PK>).create(PO) line: 66
  • We get to DefaultFlushEventListener.onFlush(FlushEvent) line: 27
  • We get to DefaultFlushEventListener(AbstractFlushingEventListener).performExecutions(EventSource) line: 298
  • We get to ActionQueue.executeActions() line: 167 with 1 element in our insertions ArrayList to do, just like in hibernate mode
  • We get to EntityInsertAction.execute() line: 110
  • We get into EntityInsertAction.postInsert(), with a org.jboss.envers.event.VersionsEventListener and a the postInsertEventListener[] array
  • We even get into VersionsEventListener.onPostInsert(PostInsertEvent)!

So why doesn’t the versioning happen?

It turns out that VersionsEventListener.onPostInsert() isn’t where the real work is done.

1.2. What VersionsEventListener.onPostInsert() is responsible for


VersionsEventListener.onPostInsert() adds a VersionsWorkUnit to a list, to be picked up and performed later.  It doesn’t actually do the work.


org.jboss.envers.event.VersionsEventListener.onPostInsert(PostInsertEvent) does is to add the to the org.jboss.envers.synchronization.VersionsSync.workUnits linked list (VersionsSync is the class that implements javax.transaction.Synchronization).

3. Who picks up the work unit?

Who is responsible for picking up the work unit, then?  I notice that the javax.transaction.Synchronization specifies two methods: beforeCompletion() and afterCompletion(int).  Let’s see if anyone calls beforeCompletion() when we’re in Hibernate mode… setting breakpoints on these two methods and re-running my hibernate mode test, we break at beforeCompletion() with this call stack:

Daemon Thread [http-] (Suspended (entry into method beforeCompletion in VersionsSync))
VersionsSync.beforeCompletion() line: 125
JDBCTransaction.notifyLocalSynchsBeforeTransactionCompletion() line: 228
JDBCTransaction.commit() line: 109
HibernateTransactionManager.doCommit(DefaultTransactionStatus) line: 655
HibernateTransactionManager(AbstractPlatformTransactionManager).processCommit(DefaultTransactionStatus) line: 709
HibernateTransactionManager(AbstractPlatformTransactionManager).commit(TransactionStatus) line: 678
TransactionInterceptor(TransactionAspectSupport).commitTransactionAfterReturning(TransactionAspectSupport$TransactionInfo)line: 321
TransactionInterceptor.invoke(MethodInvocation) line: 116
ReflectiveMethodInvocation.proceed() line: 171
ExposeInvocationInterceptor.invoke(MethodInvocation) line: 89
ReflectiveMethodInvocation.proceed() line: 171
JdkDynamicAopProxy.invoke(Object, Method, Object[]) line: 204
$Proxy68.writeGreetingToDatabase(Greeting) line: not available
NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]
NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39
DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25
Method.invoke(Object, Object...) line: 585
JAXWSMethodInvoker(AbstractInvoker).performInvocation(Exchange, Object, Method, Object[]) line: 136
JAXWSMethodInvoker(AbstractInvoker).invoke(Exchange, Object, Method, List<Object>) line: 82
JAXWSMethodInvoker.invoke(Exchange, Object, Method, List<Object>) line: 97
JAXWSMethodInvoker(AbstractInvoker).invoke(Exchange, Object) line: 68
ServiceInvokerInterceptor$ line: 56
SynchronousExecutor.execute(Runnable) line: 37
ServiceInvokerInterceptor.handleMessage(Message) line: 92
PhaseInterceptorChain.doIntercept(Message) line: 221
ChainInitiationObserver.onMessage(Message) line: 78
ServletDestination.invoke(ServletContext, HttpServletRequest, HttpServletResponse) line: 92
ServletController.invokeDestination(HttpServletRequest, HttpServletResponse, ServletDestination) line: 279
ServletController.invoke(HttpServletRequest, HttpServletResponse) line: 161
CXFServlet(AbstractCXFServlet).invoke(HttpServletRequest, HttpServletResponse) line: 174
CXFServlet(AbstractCXFServlet).doPost(HttpServletRequest, HttpServletResponse) line: 152
CXFServlet(HttpServlet).service(HttpServletRequest, HttpServletResponse) line: 710
CXFServlet(HttpServlet).service(ServletRequest, ServletResponse) line: 803
ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) line: 290
ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) line: 206
ReplyHeaderFilter.doFilter(ServletRequest, ServletResponse, FilterChain) line: 96
ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) line: 235
ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) line: 206
StandardWrapperValve.invoke(Request, Response) line: 230
StandardContextValve.invoke(Request, Response) line: 175
SecurityAssociationValve.invoke(Request, Response) line: 179
JaccContextValve.invoke(Request, Response) line: 84
StandardHostValve.invoke(Request, Response) line: 127
ErrorReportValve.invoke(Request, Response) line: 102
CachedConnectionValve.invoke(Request, Response) line: 157
StandardEngineValve.invoke(Request, Response) line: 109
CoyoteAdapter.service(Request, Response) line: 262
Http11Processor.process(Socket) line: 844
Http11Protocol$Http11ConnectionHandler.process(Socket) line: 583
JIoEndpoint$ line: 446 line: 595

So VersionsSync.beforeCompletion() does indeed get called when we’re in Hibernate mode.

3.1. Sidenote: The Point Where the Records Appear in the Tables

After some more lines of code, we get to org.hibernate.transaction.JDBCTransaction.commitAndResetAutoCommit(), which does a  jdbcContext.connection().commit().  Before this line is executed, neither the main record nor the versioning record appear in the table; after that line, the records do appear.

4. JTA mode: no beforeCompletion call made

Next we’ll re-run the test we did in step 3 with the jta version deployed and with all the same breakpoints, to see if org.jboss.envers.synchronization.VersionsSync.beforeCompletion() gets called…

It doesn’t.

Tune in next time for an exploration of why VersionsSync.beforeCompletion() isn’t getting called in JTA mode!

Remote debugging in JBoss

Have you ever wished you could debug your war project in Eclipse while it was deployed and running on JBoss? This is called remote debugging, and here’s how you set up to do it (on JBoss 4.2.2.GA running on Java 5, anyway):

  1. Make a backup copy of your current JBoss run.bat
  2. Open run.bat and find the lines that look like this:
    rem JPDA options. Uncomment and modify as appropriate to enable remote debugging.
    rem set JAVA_OPTS=-Xdebug -Xrunjdwp:transport=dt_socket,address=8787,server=y,suspend=y %JAVA_OPTS%
  3. Uncomment the second line, and save.
  4. Start Jboss. (It won’t do much until you connect a debugger to it.)
  5. In Eclipse, open your project, and on the toolbar click on the debugger bug arrow, then Open Debug Dialog.
  6. Choose Remote Java Application, right-click, New… and update the port to the address in the line you uncommented (possibly 8787).
  7. Click Debug
  8. Set a breakpoint somewhere in your code or a library that has source attached
  9. Exercise your project (via a web service, for instance) and when it hits one of your breakpoints, it will break in Eclipse.

Note to self: Avoid remote debugging for my own code — I should be adding log messages instead!

It wasn’t JBoss’s fault

I saved my changes to jboss-log4j.xml and waited for JBoss to notice the new file… but it never seemed to notice it, and my advice.log kept not showing up in the log directory.  I immediately suspected JBoss.  “Why isn’t it watching server/default/conf/jboss-log4j.xml like it’s supposed to be?”

Then I remembered that I was editing a copy of jboss-log4j.xml in my Eclipse workspace, so I’d have the benefit of Eclipse’s local history feature.  Oops!

I copied jboss-log4j.xml from my Eclipse workspace out to JBoss’s server/default/conf directory, and sure enough… JBoss noticed the changes.  : )

Customizing log4j logging on JBoss

I want to turn up the logging level on JBoss so that I can verify that the transactional AOP advice runs before the Spring-security-context-populatin’ advice.  The reason being, I want to make sure we’re already in a transaction if something goes wrong in the security context advice, so the message will get rolled back onto the queue.

To be more precise, I want to turn up the logging level on the right categories of classes — my server/default/log/server.log is already 190MB today, and Notepad and Eclipse are having trouble opening it.

The Packages I want to log about

For the first round, I want to see DEBUG-level messages for my Spring-security-context-populatin’ advice (the com.ontsys.advice package in my prototype) and the org.springframework.transaction.jta package.

Adding Logging to my Class

First, I need to add logging to my class — it currently doesn’t log any messages.

Adding logging to a class is simple:

import org.apache.log4j.Logger;
public class MyClass {
    private static final Logger LOGGER = Logger.getLogger(MyClass.class); 

    public void decombobulate() {

Configuring jboss-log4j.xml

The Logging Conventions chapter of the JBoss Development Process Guide (see also the Logging page on the JBoss Wiki) explains how to log certain categories to a different file.

Only instead of  ${jboss.server.home.dir}/log/ I’ll use more elegant ${jboss.server.log.dir}/ .

Everything in its Proper Place

Note that according to the log4j 1.2.15 DTD, the elements have to be ordered with all appenders first, followed by categories, and then the root element:

<!ELEMENT log4j:configuration (renderer*, appender*,plugin*, (category|logger)*,root?,


Note also that there is an additivity attribute you can use on the on the appenders.  The section called Redirecting Category Output has this to say about the additivity attribute:

The additivity attribute controls whether output continues to go to the root category appender. If false, output only goes to the appenders referred to by the category.

That would explain why my main server/default/log/server.log was so small the other time I tried adding a category appender — I think I had additivity=”false” from an example configuration I found somewhere, without understanding what it meant — so output that was going to my special log file was no longer going to my server.log file.

The DTD says that the additivity attribute defaults to “true” though, which is what I want, so I’m leaving it out.

My Changes to jboss-log4j.xml

Here’s what I eventually came up with:

<appender name="AdviceLog" class="org.apache.log4j.FileAppender">
<errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler" />
<param name="Append" value="false" />
<param name="File" value="${jboss.server.log.dir}/advice.log" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %-5p &#91;%c&#93; %m%n" />
<category name="com.ontsys.advice">
<priority value="DEBUG" />
<appender-ref ref="AdviceLog" />
<category name="org.springframework.transaction.jta">
<priority value="DEBUG" />
<appender-ref ref="AdviceLog" />


This worked great!  Only stuff from the com.ontsys.advice and org.springframework.transaction.jta packages in the advice.log, at the DEBUG level.

For Next Time

At first the advice.log file was getting way too much information… but we’ll stop here for the moment!

The mysteriously necessary sessionTransacted=true

I’ve encountered this before, but just ran into it again: Despite suggestions to the contrary, it is necessary (at least with Spring 2.5.5, ActiveMQ 5.1.0, and JBoss 4.2.2.GA) to set sessionTransacted=true in the DefaultMessageListenerContainer even when it’s set up to connect to an external JTA transaction manager. If I set sessionTransacted=true, then when my messageListener throws a RuntimeException, the message is rolled back onto the queue; if I don’t, it doesn’t.

This has been documented elsewhere regarding Atomikos, but not ActiveMQ. I’ve posted a question to the Spring Remoting and JMS forum. We’ll see what comes of it!