Spring 의 TransactionalEventListener 실행 순서

사건의 시작

나는 회사에서 특정 상황에 처음으로 TransactionalEventListener 를 사용해본 뒤 유용하다는것을 알고 회사 동료분들에게 이런게 있다고 알려드렸다. 그러던 어느 날 한 회사 동료분이 나에게 물었다.

"와잼님 TransactionalEventListener 를 여러개 쓰면 어떤게 먼저 실행되나요?"

 

나는 답변으로

"몇번 테스트 해보고 사용해본바로는 TransactionalEventListener 에 phase 라는게 존재해서 Before Commit, After Commit, After Rollback, After Completion 이 있으며 성공이면 Before Commit 으로 시작해 After Commit -> 
After Completion , 실패면 After Rollback -> After Completion 가 있습니다, 그리고 같은 phase 를 가진 TransactionalEventListener 를 써본적이 없어서 같은 phase 에 대해서는 잘 모르겠습니다."

 

라고 답변했다. 같은 phase 일땐 어떤것이 어떻게 먼저 실행될까 호기심이 생긴 나는 동료분과 함께 같이 알아봤는데 그 결과가 충격적이었다. 고작 몇번의 테스트와 production 환경에서 우연히 버그가 생기지 않았기에 믿었던, 내가 알고 있는 정보가 잘못되었다는 사실을 알게 되었다. 덕분에 에러가 생기기전에 오류를 바로 잡을 수 있었지만 다른분들도 이런 실수를 저지르지 않았으면 하는 마음에 이 글을 적는다.

 

사전준비

Publisher

@Component
@RequiredArgsConstructor
@Slf4j
public class EventPublisher {
    private final ApplicationEventPublisher applicationEventPublisher;
    private final TempRepository tempRepository;

    @Transactional
    public void publish() {
        log.info("Start publish method");
        Temp saved = tempRepository.save(new Temp());
        applicationEventPublisher.publishEvent(new TestEvent(saved.getId(), saved.getCreatedAt()));
        log.info("End publish method");
    }

}

Subscriber

@Component
@Slf4j
public class EventSubscriber {
    
    @TransactionalEventListener(phase = TransactionPhase.AFTER_COMMIT)
    public void afterCommitSubscribe(TestEvent event) {
        log.info("AFTER COMMIT " + event.detail());
    }
    @TransactionalEventListener(phase = TransactionPhase.AFTER_COMPLETION)
    public void afterCompletionSubscribe(TestEvent event) {
        log.info("AFTER COMPLETION " + event.detail());
    }
    @TransactionalEventListener(phase = TransactionPhase.AFTER_ROLLBACK)
    public void afterRollbackSubscribe(TestEvent event) {
        log.info("AFTER ROLLBACK " + event.detail());
    }
    @TransactionalEventListener(phase = TransactionPhase.BEFORE_COMMIT)
    public void beforeCommitSubscribe(TestEvent event) {
        log.info("BEFORE COMMIT " + event.detail());
    }
    
}

Event

public record TestEvent(Long id, LocalDateTime createAt) {
    public String detail() {
        return String.format(
                "temp%s saved at %s",
                id,
                createAt.format(DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss"))
        );
    }
}

 

파헤치기

코드를 실행해보면 재미있는 사실을 알 수 있다. publish 메서드를 몇번 실행하다보면 총 두가지의 경우가 나온다.

2023-07-09T21:14:13.079+09:00  INFO 8392 --- [    Test worker] com.min.yjm.EventPublisher               : Start publish method
Hibernate: insert into temp (created_at,id) values (?,default)
2023-07-09T21:14:13.138+09:00  INFO 8392 --- [    Test worker] com.min.yjm.EventPublisher               : End publish method
2023-07-09T21:14:13.139+09:00  INFO 8392 --- [    Test worker] com.min.yjm.EventSubscriber              : BEFORE COMMIT temp1 saved at 2023-07-09 21:14:13
2023-07-09T21:14:13.147+09:00  INFO 8392 --- [    Test worker] com.min.yjm.EventSubscriber              : AFTER COMMIT temp1 saved at 2023-07-09 21:14:13
2023-07-09T21:14:13.147+09:00  INFO 8392 --- [    Test worker] com.min.yjm.EventSubscriber              : AFTER COMPLETION temp1 saved at 2023-07-09 21:14:13

 

2023-07-09T21:16:56.819+09:00  INFO 10068 --- [    Test worker] com.min.yjm.EventPublisher               : Start publish method
Hibernate: insert into temp (created_at,id) values (?,default)
2023-07-09T21:16:56.880+09:00  INFO 10068 --- [    Test worker] com.min.yjm.EventPublisher               : End publish method
2023-07-09T21:16:56.881+09:00  INFO 10068 --- [    Test worker] com.min.yjm.EventSubscriber              : BEFORE COMMIT temp1 saved at 2023-07-09 21:16:56
2023-07-09T21:16:56.887+09:00  INFO 10068 --- [    Test worker] com.min.yjm.EventSubscriber              : AFTER COMPLETION temp1 saved at 2023-07-09 21:16:56
2023-07-09T21:16:56.888+09:00  INFO 10068 --- [    Test worker] com.min.yjm.EventSubscriber              : AFTER COMMIT temp1 saved at 2023-07-09 21:16:56

재미있는 점은 AFTER COMMIT 과 AFTER COMPLETION 의 순서가 고정되어있지 않다는 점이다. 어떻게 이런결과가 나오는걸까? 알아보기 위해 디버깅을 해보았다. 찾다보니 AbstractPlatformTransactionManager 의 triggerAfterCompletion 메서드를 호출하는 부분까지 올 수 있었다.

AbstractPlatformTransactionManage - triggerAfterCompletion

AbstractPlatformTransactionManage - invokeAfterCompletion

해당 메서드는 TransactionSynchronizationUtils 에게 TransactionSynchronizationManager 가 가진 synchronizations 과 completionStatus 를 넘겨준다. 

TransactionSynchronizationUtils - invokeAfterCompletion

TransactionSynchronizationUtils 은 넘겨받은 synchronizations 를 순회하며 각 원소의 afterCompletion 메서드를 실행시킨다. synchronizations 안에는 어떤것들이 담겨 있을까?

synchronizations 의 내부

synchronizations 내부에는 아까 만든 EventSubscriber 의 TransactionalEventListener 4가지에 대한 정보들이 있는데 해당 synchronization 의 listener 안의 내용을보면 order 라는 값이 있고 전부 Integer.MAX_VALUE 값으로 설정되어있다. 그렇다는것은 TransactionalEventListener 를 등록할때 순서를 정할 수 있고 정하지 않으면 Integer.MAX_VALUE 가 default 이며 order 가 같을 경우 어떤것이 먼저 실행될지 알 수 없다는 것을 유추할 수 있다.

 

더 들어가보자면 TransactionSynchronizationManager 에서의 registerSynchronization 메서드에 디버깅을 걸고 확인해보면 applicationEventPublisher.publishEvent 를 호출할때 TransactionalApplicationListenerMethodAdapter 의 onApplicationEvent 가 호출되며 그 안에서 new 를 통해 TransactionalApplicationListenerSynchronization 를 생성하고 TransactionSynchronizationManager 에게 registerSynchronization 메서드를 통해 넘겨주어 ThreadLocal<Set<TransactionSynchronization>> 에 넣는다는것 등등..을 확인 할 수 있지만 글이 삼천포로 빠지는것 같아 궁긍하다면 직접 디버깅 해보며 확인해보길 추천한다.

 

아주 당연하지만 TransactionalEventListener 의 docs 를 확인해보면 순서에 관한 이야기도 나온다.

Adding @Order to your annotated method allows you to prioritize that listener amongst other listeners running before or after transaction completion.

 

Spring이 지원하고 있는 @Order 를 통해 순서를 결정 할 수 있다. 라는 말이 대문짝만하게 쓰여있다. 나는 멍청하게도 당연히 확인해야할 docs 를 보지 않고 몇번의 테스트만으로 착각을 해버린것이다.

 

실제로 같은 phase 를 몇가지 추가하고 @Order 를 적용하고 나서 synchronizations 를 확인해보면 @Order 의 순서대로 들어가있는것을 확인 할 수 있다.

@Component
@Slf4j
public class EventSubscriber {

    @Order(4)
    @TransactionalEventListener(phase = TransactionPhase.AFTER_COMMIT)
    public void afterCommitSubscribeNo4(TestEvent event) {
        log.info("NO.4 AFTER COMMIT " + event.detail());
    }
    
    @Order(3)
    @TransactionalEventListener(phase = TransactionPhase.AFTER_COMMIT)
    public void afterCommitSubscribeNo3(TestEvent event) {
        log.info("NO.3 AFTER COMMIT " + event.detail());
    }
    
    @Order(1)
    @TransactionalEventListener(phase = TransactionPhase.AFTER_COMPLETION)
    public void afterCompletionSubscribeNo1(TestEvent event) {
        log.info("NO.1 AFTER COMPLETION " + event.detail());
    }
    
    @Order(2)
    @TransactionalEventListener(phase = TransactionPhase.AFTER_COMPLETION)
    public void afterCompletionSubscribeNo2(TestEvent event) {
        log.info("NO.2 AFTER COMPLETION " + event.detail());
    }
    
    @TransactionalEventListener(phase = TransactionPhase.AFTER_ROLLBACK)
    public void afterRollbackSubscribe(TestEvent event) {
        log.info("AFTER ROLLBACK " + event.detail());
    }

    @Order(5)
    @TransactionalEventListener(phase = TransactionPhase.BEFORE_COMMIT)
    public void beforeCommitSubscribe(TestEvent event) {
        log.info("BEFORE COMMIT " + event.detail());
    }

}

2023-07-10T00:12:56.550+09:00  INFO 18160 --- [    Test worker] com.min.yjm.EventPublisher               : Start publish method
Hibernate: insert into temp (created_at,id) values (?,default)
2023-07-10T00:12:56.610+09:00  INFO 18160 --- [    Test worker] com.min.yjm.EventPublisher               : End publish method
2023-07-10T00:12:56.611+09:00  INFO 18160 --- [    Test worker] com.min.yjm.EventSubscriber              : BEFORE COMMIT temp1 saved at 2023-07-10 00:12:56
2023-07-10T00:12:56.618+09:00  INFO 18160 --- [    Test worker] com.min.yjm.EventSubscriber              : NO.1 AFTER COMPLETION temp1 saved at 2023-07-10 00:12:56
2023-07-10T00:12:56.618+09:00  INFO 18160 --- [    Test worker] com.min.yjm.EventSubscriber              : NO.2 AFTER COMPLETION temp1 saved at 2023-07-10 00:12:56
2023-07-10T00:12:56.619+09:00  INFO 18160 --- [    Test worker] com.min.yjm.EventSubscriber              : NO.3 AFTER COMMIT temp1 saved at 2023-07-10 00:12:56
2023-07-10T00:12:56.619+09:00  INFO 18160 --- [    Test worker] com.min.yjm.EventSubscriber              : NO.4 AFTER COMMIT temp1 saved at 2023-07-10 00:12:56

 

 

결론

TransactionalEventListener 순서를 요약하자면 이렇다.

1. COMMIT 의 경우 BEFORE_COMMIT 이후 AFTER_COMMIT 과 AFTER_COMPLETION 이 실행되는데 이 두가지의 순서는 보장되지 않는다.
2. ROLLBACK 의 경우 AFTER_ROLLBACK 과 AFTER_COMPLETION 이 실행되는데 이 두가지의 순서는 보장되지 않는다.
3. 순서의 보장을 위해선 @Order 를 해당 TransactionalEventListener 메서드에 달아줘야 한다.
4. 같은 phase 는 @Order 를 통해 순서를 결정 할 수 있다.

 

마치며

나는 개발을 하며 많은것들을 배우고 또한 그것들을 사람들과 이야기하는것을 좋아한다. 하지만 이 사건을 통해 내가 알고 있는 지식을 누군가에게 알려줄땐 제대로 확인하고 알려주는 습관이 필요하다는 것을 깨달았다. 또한, 고작 몇번의 테스트는 우연이 겹쳐 성공할 수 있지만 어느순간에는 실패할 수 있다는 것도 알았다. 아무리 바쁘더라도 docs 를 확인하는 습관이 필요하며 때로는 깊이 파고들어 확인하는 시간이 필요하다 생각한다.