Spring MDC Transaction Logging - Vlad Mihalcea (2024)

Introduction

In this article, we are going to see how to configure a Spring application to use MDC (Mapped Diagnostic Context) for transaction logging.

This technique is going to help us inject the Persistence Context information as well as the associated database transaction identifier in all the log entries emitted from within a @Transactional service method.

MDC (Mapped Diagnostic Context)

As I explained in this article, MDC is for application logging what the ThreadLocal context is to Java threads.

In short, MDC allows us to register key/value sets that are bound to a given thread and can be referenced by the logging framework when printing a given log message.

To use MDC, the logging framework needs to reference the key of the MDC key/value set in the log message pattern, as illustrated by the following example:

<appender name="console" class="ch.qos.logback.core.ConsoleAppender"> <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> <level>TRACE</level> </filter> <encoder> <Pattern>%-5p [%t]:%X{txId} %c{1} - %m%n</Pattern> <charset>UTF-8</charset> </encoder></appender>

Once we have the txId MDC variable reference by the Logback message pattern, when running the following code snippet:

try(MDC.MDCCloseable mdc = MDC .putCloseable( "txId", String.format( " Persistence Context Id: [%d], DB Transaction Id: [%s]", 123456, 7890 ) )) { LOGGER.info("Fetch Post by title");}

Logback is going to print the following message:

2022-12-21 14:51:38,823 INFO [main]: Persistence Context Id: [123456], DB Transaction Id: [7890] c.v.b.h.s.t.m.SpringMdcTest - Update Post entity

That’s great, but we need to automate how the Persistence Context identifier and the actual database transaction id are bound to the txId MDC variable.

Spring MDC Transaction Logging

So, to achieve our goal, we need to intercept the following JPA actions:

• when the JPA Persistence Context is open, we need to assign a Persistence Context identifier
• after a statement is executed, we check whether the relational database has assigned a transaction identifier
• after the JPA transaction ends, we remove the transaction identifier
• after the JPA Persistence Context is closed, we remove the txId variable from the MDC logging context

Luckily, both Spring and Hibernate are extremely customizable, so we can intercept all those actions and apply the MDC transition logging.

First, we need to configure the Spring LocalContainerEntityManagerFactoryBean to use some custom Hibernate settings:

@Beanpublic LocalContainerEntityManagerFactoryBean entityManagerFactory() { LocalContainerEntityManagerFactoryBean entityManagerFactoryBean = new LocalContainerEntityManagerFactoryBean(); ... entityManagerFactoryBean.setJpaVendorAdapter( new HibernateJpaVendorAdapter() ); entityManagerFactoryBean.setJpaProperties(properties()); return entityManagerFactoryBean;}protected Properties properties() { Properties properties = new Properties(); properties.setProperty( AvailableSettings.CONNECTION_PROVIDER_DISABLES_AUTOCOMMIT, Boolean.TRUE.toString() ); properties.put( AvailableSettings.AUTO_SESSION_EVENTS_LISTENER, TransactionInfoSessionEventListener.class.getName() ); return properties;}

The CONNECTION_PROVIDER_DISABLES_AUTOCOMMIT property allows Hibernate to acquire the database connection lazily, as opposed to when you enter the @Transactional method. For more details about this setting, check out this article.

The AUTO_SESSION_EVENTS_LISTENER setting allows us to provide a SessionEventListener that can intercept various Hibernate actions.

Next, we are going to see how we can intercept Hibernate actions using the awesome SessionEventListener mechanism.

Intercepting Hibernate actions using the SessionEventListener

The TransactionInfoSessionEventListener looks as follows:

public class TransactionInfoSessionEventListener extends BaseSessionEventListener { private final TransactionInfo transactionInfo; private EntityManager entityManager; /** * Executes when a JPA EntityManager is created. */ public TransactionInfoSessionEventListener() { transactionInfo = new TransactionInfo(); } /** * Executes after a JDBC statement was executed. */ @Override public void jdbcExecuteStatementEnd() { if (!transactionInfo.hasTransactionId()) { resolveTransactionId(); } } /** * Executes after the commit or rollback was called * on the JPA EntityTransaction. */ @Override public void transactionCompletion(boolean successful) { transactionInfo.setTransactionId(null); } /** * Executes after JPA EntityManager is closed. */ @Override public void end() { transactionInfo.close(); } private EntityManager getEntityManager() { if (entityManager == null) { entityManager = SpringTransactionUtils.currentEntityManager(); } return entityManager; } private void resolveTransactionId() { EntityManager entityManager = getEntityManager(); SessionFactoryImplementor sessionFactory = entityManager .getEntityManagerFactory() .unwrap(SessionFactoryImplementor.class); entityManager.unwrap(Session.class).doWork(connection -> { try (Statement statement = connection.createStatement(); ResultSet resultSet = statement.executeQuery( Database.of(sessionFactory.getJdbcServices().getDialect()) .dataSourceProvider() .queries() .transactionId() )) { if (resultSet.next()) { transactionInfo.setTransactionId(resultSet.getString(1)); } } }); }}

A new TransactionInfoSessionEventListener object is created whenever a new JPA EntityManager is instantiated, so we use this opportunity to create a new TransactionInfo object, which we are going to use to hold the current transaction information.

In the jdbcExecuteStatementEnd callback, we check whether the database transaction identifier was previously resolved, and if it was not, we try to resolve it.

In the transactionCompletion callback, we reset the database transaction identifier since the associated database transaction was ended.

And, in the end callback, which is called when the JPA EntityManager is closed, we also close the associated TransactionInfo object.

The TransactionInfo object looks as follows:

class TransactionInfo { private final Long persistenceContextId; private String transactionId; private MDC.MDCCloseable mdc; public TransactionInfo() { this.persistenceContextId = TsidUtils.randomTsid().toLong(); setMdc(); } public boolean hasTransactionId() { return transactionId != null; } public TransactionInfo setTransactionId(String transactionId) { this.transactionId = transactionId; setMdc(); return this; } private void setMdc() { this.mdc = MDC.putCloseable( "txId", String.format( " Persistence Context Id: [%d], DB Transaction Id: [%s]", persistenceContextId, transactionId ) ); } public void close() { if(mdc != null) { mdc.close(); } }}

The persistenceContextId stores the Persistence Context identifier. While we could use the Hibernate Session UUID identifier, I prefer using a time-sorted Tsid instead.

The transactionId stores the database transaction identifier.

The mdc variable references the MDC.MDCCloseable object that we can use to reset the MDC logging variable we bound for the currently executing Thread.

That’s it!

Testing time

Assuming we have the following addComment service method:

@Transactionalpublic void addComment(Long postId, String review) { Post post = postRepository.lockById( postId, LockModeType.OPTIMISTIC ); postCommentRepository.persist( new PostComment() .setReview(review) .setPost(post) ); postRepository.lockById( postId, LockModeType.PESSIMISTIC_READ );}

When calling the addComment method on PostgreSQL:

forumService.addComment(postId, "Awesome");

The following log messages are printed:

Persistence Context Id: [393424039441824927], DB Transaction Id: [null] o.h.e.t.i.TransactionImpl - beginPersistence Context Id: [393424039441824927], DB Transaction Id: [null] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select p1_0.id,p1_0.slug,p1_0.title,p1_0.version from post p1_0 where p1_0.id=?"], Params:[(1)]Persistence Context Id: [393424039441824927], DB Transaction Id: [null] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:0, Success:True, Type:Statement, Batch:False, QuerySize:1, BatchSize:0, Query:["SELECT CAST(pg_current_xact_id_if_assigned() AS text)"], Params:[]Persistence Context Id: [393424039441824927], DB Transaction Id: [null] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select nextval('post_comment_SEQ')"], Params:[()]Persistence Context Id: [393424039441824927], DB Transaction Id: [null] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:0, Success:True, Type:Statement, Batch:False, QuerySize:1, BatchSize:0, Query:["SELECT CAST(pg_current_xact_id_if_assigned() AS text)"], Params:[]Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select id from post where id =? and version =? for share"], Params:[(1, 0)]Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] o.h.e.t.i.TransactionImpl - committingPersistence Context Id: [393424039441824927], DB Transaction Id: [431894] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:2, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["insert into post_comment (post_id, review, id) values (?, ?, ?)"], Params:[(1, Awesome, 1)]Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select version as version_ from post where id =?"], Params:[(1)]Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] o.h.r.j.i.AbstractLogicalConnectionImplementor - LogicalConnection#beforeTransactionCompletionPersistence Context Id: [393424039441824927], DB Transaction Id: [431894] o.h.r.j.i.AbstractLogicalConnectionImplementor - Preparing to commit transaction via JDBC Connection.commit()Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] o.h.r.j.i.AbstractLogicalConnectionImplementor - Transaction committed via JDBC Connection.commit()

While the Persistence Context identifier is available right from the start, the database transaction id is only assigned after PostgreSQL executes an INSERT, UPDATE or DELETE statement.

Awesome, right?

If you enjoyed this article, I bet you are going to love my Book and Video Courses as well.

Conclusion

MDC logging is a very useful feature as it allows you to customize your log messages using context-specific information.

While the article shows you how you can add the transaction information to your logs using a Hibernate SessionEventListener, this solution is not limited to Spring. You can also use it with Jakarta EE or Java EE. The only thing you need to do is change the way you are passing the AUTO_SESSION_EVENTS_LISTENER Hibernate property.

Related