How to solve transactional logging in Java?

Question

I want to achieve the following:

Inside of a transaction I want to generate multiple log messages. These log messages should be written only if the transaction gets committed successfully. If the transaction gets rolled back the log messages mustn't be logged.

I couldn't find anything to achieve this (using spring, hibernate, atomikos), so I wrote this little wrapper (I left out a couple of convenience-methods):

public class TransactionLogger {
    private Logger logger;
    private Map<Long, LinkedList<LogRecord>> threadBuffers =
        new HashMap<Long, LinkedList<LogRecord>>();

    public TransactionLogger(Logger logger) {
        this.logger = logger;
    }

    private void addRecord(LogRecord rec) {
        LinkedList<LogRecord> list =
            threadBuffers.get(Thread.currentThread().getId());
        if (list == null) {
            list = new LinkedList<LogRecord>();
            threadBuffers.put(Thread.currentThread().getId(), list);
        }
        list.add(rec);
    }

    private LinkedList<LogRecord> getRecords() {
        if (threadBuffers.containsKey(Thread.currentThread().getId())) {
            return threadBuffers.remove(Thread.currentThread().getId());
        } else {
            return new LinkedList<LogRecord>();
        }
    }

    public void commit() {
        for (LogRecord rec : getRecords()) {
            rec.setLoggerName(logger.getName());
            logger.log(rec);
        }
    }

    public void rollback() {
        getRecords();
    }

    /**
     * If the resulting log entry should contain the sourceMethodName
     * you should use logM(Level,String,String) instead,
     * otherwise TransactionLogger.commit() will get
     * inferred as sourceMethodName.
     */
    public void log(Level l, String sourceClassName, String msg) {
        LogRecord rec = new LogRecord(l, msg);
        rec.setSourceClassName(sourceClassName);
        addRecord(rec);
    }

    /**
     * Same as log(Level,String,String), but the sourceMethodName gets set.
     */
    public void logM(Level l, String sourceClassName, String msg) {
        StackTraceElement[] trace = Thread.currentThread().getStackTrace();
        LogRecord rec = new LogRecord(l, msg);
        rec.setSourceClassName(sourceClassName);
        if (trace != null && trace.length > 1) {
            rec.setSourceMethodName(trace[2].getMethodName());
        }
        addRecord(rec);
    }
}

What do you think of this approach? Are there any major or minor flaws or problems with it? Or even better, are there any ready-to-use solutions for this?

UPDATE:

Since I am using JTA as well, I got a new idea. Would implementing the TransactionLogger as a receiver of a transaction-aware message queue solve the time issue or would it just make things more complex?

UPDATE:

I think logging to a database and then periodically writing log entries from that database into a file in a periodic task as suggested in the comments, is a very good solution to this problem:

PROs:

• Normal implementation afford
• integrates with TransactionManager
• Log entries in the log files may be ordered by timestamp

CONs:

• Log files are not up to date (depending of periodic-task-interval)
• database-structure dependent
• logging of simple non-transactional events becomes dbconnection-dependent
• probably bigger overall logging overhead

Here are the pros and cons I see with the wrapper I posted:

PROs:

• database and framework independent
• simple implementation
• log files are always up to date

CONs:

• Log entries in the log files are not ordered by event-timestamp but by "transaction-completition"-timestamp (long transactions lead to very mixedup log files.
• rollback() and commit() have to be invoked "manually", which can lead to programming errors (and possible OutOfMemoryError if invoking these methods is forgotten)

I think a combination of those two, like buffering log records in the "wrapper"-approach are worse than using one of the two mentioned approaches, because of the possible inconsistent log files (forgotten log entries due to an application crash).

My decision now is keeping my "wrapper". The following reasons are crucial for this decision (in order of importance):

1. I prefer log files that are always up to date over perfectly ordered log entries
2. Long transactions are very rare in my case
3. I am able to reduce the usage of rollback() and commit() to only a few methods.
4. This solution already exists by now.

By the way: I'd like to improve my english. So if you notice any mistakes in my article, I will be glad if you point them out.

UPDATE:

Simplyfied I'm using it like this:

/*
 * This objects contains one or more TransactionLogger(s) and exposes rollback()
 * and commit() through rollbackLogs() and commitLogs().
 */
@Autowired
private ITransactionalServer server;

public void someMethod(String someParam) {
    boolean rollback = false;
    try {
        /*
         * This method is for example annotated with @Transactional.
         */
        return server.someTransactionalMethod(someParam);
    } catch (Exception ex) {
        logError(ex);
        rollback = true;
    } finally {
        if (rollback) {
            server.rollbackLogs();
        } else {
            server.commitLogs();
        }
    }
}

Still this isn't perfect, but right now it seems a "good-enough-solution" to me. The next step will be using aspects to decorate my transactional methods.

UPDATE:

I'm adding this in my question, because I felt bad about accepting my own answer, although someone other got me on the way.

I am now using an AOP-approach basically with the following Logger. (In my real application I have more than one Logger like this and all those Loggers are managed by a custom singleton-manager.):

public class AopLogger extends Logger {

    public static AopLogger getLogger(String name) {
        LogManager manager = LogManager.getLogManager();
        Object l = manager.getLogger(name);
        if (l == null) {
            manager.addLogger(new AopLogger(name));
        }
        l = manager.getLogger(name);
        return (AopLogger)l;
    }

    private Map<Long, LinkedList<LogRecord>> threadBuffers = new HashMap<Long, LinkedList<LogRecord>>();

    public AopLogger(String name) {
        super(name, null);
    }

    public void beginTransaction() {
        LinkedList<LogRecord> list = threadBuffers.get(Thread.currentThread().getId());
        if (list == null) {
            list = new LinkedList<LogRecord>();
            threadBuffers.put(Thread.currentThread().getId(), list);
        }
    }

    private void addRecord(LogRecord rec) {
        LinkedList<LogRecord> list = threadBuffers.get(Thread.currentThread().getId());
        if (list != null) {
            list.add(rec);
        } else {
            super.log(record);
        }
    }

    private LinkedList<LogRecord> getRecords() {
        if (threadBuffers.containsKey(Thread.currentThread().getId())) {
            return threadBuffers.remove(Thread.currentThread().getId());
        } else {
            return new LinkedList<LogRecord>();
        }
    }

    public void commit() {
        for (LogRecord rec : getRecords()) {
            rec.setMillis(System.currentTimeMillis());
            super.log(rec);
        }
    }

    public void rollback() {
        getRecords();
    }

    public void log(LogRecord record) {
        addRecord(record);
    }
}

and this Aspect:

import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.core.Ordered;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Service;

@Service
@Aspect
@Order(10)
public class AopLogManager implements Ordered {

    @Autowired
    private AopLogger logger;
    private Logger errorLogger = Logger.getLogger("ExceptionLogger");

    @Around("@annotation(org.springframework.transaction.annotation.Transactional)")
    public Object logTransaction(ProceedingJoinPoint pjp) throws Throwable {
        logger.beginTransaction();
        Exception ex = null;
        try {
            return pjp.proceed();
        } catch (Exception e) {
            ex = e;
            throw e;
        } finally {
            if (ex != null) {
                logger.rollback();
                errorLogger.severe(ex.getMessage());
            } else {
                logger.commit();
            }
        }
    }

    private int mOrder;

    @Override
    public int getOrder() {
        return mOrder;
    }

    public void setOrder(int order) {
        mOrder = order;
    }
}

In my applicationContext.xml I have the following lines:

<aop:aspectj-autoproxy />
<tx:annotation-driven transaction-manager="springTransactionManager" order="5"/>

This works fine until now.

PROs:

• database and framework independent
• simple implementation
• log files are always up to date
• rollback() and commit() are invoked automatically after each transaction

CONs:

• (Log entries in the log files are not ordered by event-timestamp but by "transaction-completition"-timestamp. I think this is not a big disadvantage, as the DB-actions realy take place the time the transaction is commited and the LogRecords of one transaction are still ordered correctly.)

Answer 1

If you want a Logger only "commit" its log messages when the transaction is commited, then your best solution would be to have your Logger be a XAResource and use XA transactions. This means your XALogger receives a prepare/commit notification from the transaction manager. This way your XAResource becomes a "Resource Manager" participating in an XA transation. Your XALogger needs to be registered with the transaction manager just like JMS and JDBC resources are registered. You can either write a JCA implementation, or (easier) just register your XALogger with the current java.transaction.Transaction

transaction.enlistResource(myXALogger)

and have it implement XAResource (JavaDoc)