⚠️ 문제 상황
- 로그인 시 user entity의 lastLoginAt 필드를 update 후 repository.save()
- hibernate의 PostUpdateEventListener 구현한 EntityUpdateEventListener에서 에러 발생
- Reflection을 사용할 때, stackTrace의 모든 경로를 찾는데, 동적 클래스 로딩으로 생성된 클래스는 JVM 메소드 영역에 저장되며 GC 대상이 되기 때문에 GC에 의해 제거되어 Class.forName 에서 클래스를 찾지 못하여 발생한 exception이라고 예상됨.
@Component class EntityUpdateEventListener( private val logService: LogService, ) : PostUpdateEventListener { private fun isScheduledMethodInvoked(): Boolean { Thread.currentThread().stackTrace.map { stackTraceElement -> runCatching { val methods = ReflectionUtils.getUniqueDeclaredMethods(Class.forName(stackTraceElement.className)) methods.map { method -> if (method.isAnnotationPresent(Scheduled::class.java)) { return true } } } } return false } override fun onPostUpdate( event: PostUpdateEvent ) { if (isScheduledMethodInvoked()) { return } ... } }
- Reflection을 사용할 때, stackTrace의 모든 경로를 찾는데, 동적 클래스 로딩으로 생성된 클래스는 JVM 메소드 영역에 저장되며 GC 대상이 되기 때문에 GC에 의해 제거되어 Class.forName 에서 클래스를 찾지 못하여 발생한 exception이라고 예상됨.
- 재 로그인 시, pessimistic lock 에러 발생함. hikariCP에서 maxLifeTime의 default 값인 30분이 지나도 에러는 유지됨.
org.springframework.dao.PessimisticLockingFailureException: could not execute statement; SQL [n/a]; nested exception is org.hibernate.PessimisticLockException: could not execute statement
...
Caused by: org.hibernate.PessimisticLockException: could not execute statement
...
Caused by: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
...
🔎 원인 분석
1. 문제 시점 분석
- 서버 restart 직후는 정상동작
- 그러나 4번째 로그인 시도 시 에러 발생 후 재 로그인 시 PessimisticLockingFailureException이 발생한다.
- 에러 시점 분석
- EntityUpdateEventListener 에서 에러가 발생하고, 이후에 database에서 SELECT ... FOR UPDATE 로 조회 시 pending으로 lock을 잡고 있다.
SELECT *
FROM users
WHERE id = {USER_ID}
FOR UPDATE;2. 문제 코드 분석
- EntityListener를 Hibernate의 공식문서에 명시된 방법으로 추가했을 때는 정상 동작함. [공식 문서]
1. Entity에 @PostUpdate 추가하는 방법
@PostUpdate
fun postUpdate() {
throw Exception()
}
2. Entity에 @EntityListeners 추가하는 방법
@EntityListeners(TestUserListener::class)
class UserEntity(
- PostUpdateEventListener 를 구현한 Listener를 global로 (억지로) 추가했을 때만 문제가 생김
@Component
class HibernateListenerConfig(
private val entityUpdateEventListener: EntityUpdateEventListener
) {
@PersistenceUnit
private val emf: EntityManagerFactory? = null
@PostConstruct
private fun init() {
val sessionFactory = emf!!.unwrap(SessionFactoryImpl::class.java)
val registry = sessionFactory.serviceRegistry.getService(
EventListenerRegistry::class.java
)
registry.getEventListenerGroup(EventType.POST_UPDATE).appendListener(entityUpdateEventListener)
}
}
3. 원인 분석
- 첫번째 가설
- 가설
- update query가 commit 되지 않아서 lock을 잡고 있는 것 아닌가? 어떤 이유로 commit을 실패하나?
- 검증
- EntityListener 가 동작하는 시점 분석
- UserService.save()
→ JpaTransactionManager.doCommit()
→ JdbcResourceLocalTransactionCoordinatorImpl.commit()
→ JdbcCoordinatorImpl.beforeTransactionCompletion()
→ DefaultFlushEventListener.onFlush()
→ EntityUpdateAction.postUpdate()
→ PostUpdateEventListener.onPostUpdate()
- UserService.save()
- 분석하면, repository.save() 실행 시, update 쿼리를 생성하고 실행한다. 이후에 commit을 찍는 작업을 진행하는데, 이를 JpaTransactionManager 가 수행한다.
// JdbcResourceLocalTransactionCoordinatorImpl.java 281 lines ... @Override public void commit() { ... JdbcResourceLocalTransactionCoordinatorImpl.this.beforeCompletionCallback(); jdbcResourceTransaction.commit(); JdbcResourceLocalTransactionCoordinatorImpl.this.afterCompletionCallback( true ); } catch (RollbackException e) { throw e; } catch (RuntimeException e) { try { rollback(); } catch (RuntimeException e2) { log.debug( "Encountered failure rolling back failed commit", e2 ); } throw e; } ... - 위 코드를 보면, 실제 transaction에 commit을 찍기 전에 어떤 작업이 있다는 것을 확인해볼 수 있다. 예상하듯이, beforeCompletionCallback 은 entity가 flush 될 때 동작을 핸들링하는 DefaultFlushEventListener 를 호출하고, 이로 인해 PostUpdateEventListener 에 정의한 onPostUpdate() 함수가 실행된다.
그렇다면 jdbcResourceTransaction.commit(); 코드는 정말 database에 commit 요청하는 함수가 맞는가?
해당 함수의 구현 코드를 확인하면 알 수 있다. -
// AbstractLogicalConnectionImplementor.java 83 lines @Override public void commit() { try { log.trace( "Preparing to commit transaction via JDBC Connection.commit()" ); getConnectionForTransactionManagement().commit(); status = TransactionStatus.COMMITTED; log.trace( "Transaction committed via JDBC Connection.commit()" ); } catch( SQLException e ) { status = TransactionStatus.FAILED_COMMIT; throw new TransactionException( "Unable to commit against JDBC Connection", e ); } afterCompletion(); } - 위 코드에서 getConnectionForTransactionManagement().commit(); 코드가 commit 담당으로 보인다. 해당 코드의 구현체를 확인해보자.
-
// ConnectionImpl.java 795 lines @Override public void commit() throws SQLException { ... this.session.execSQL(null, "commit", -1, null, false, this.nullStatementResultSetFactory, null, false); ...
위 코드에서 알 수 있듯이, commit SQL을 요청하는 것을 확인할 수 있다.
- EntityListener 가 동작하는 시점 분석
- 정리
JPA에서 commit을 찍을 때 3가지 단계를 거친다.- 사전작업
commit 전, 수행되어야 하는 작업을 실행한다.
ex) PostUpdateEventListener 실행 - commit
database에 commit SQL을 실제로 요청한다. - connection 정리
리소스를 release 하는 등의 작업을 한다
- 사전작업
- 해석
사전작업, 즉 EntityEventListener 등에서 에러가 발생하면 commit 단계까지 도달하지 못하고, transaction을 종료하지 못한다.
라고 결론을 짓기에는, JPA와 Hibernate가 이렇게 허술하게 코드를 짜지 않을 것 같아서 찜찜하다..
그래서 좀 더 찾아본 결과, JdbcResourceLocalTransactionCoordinator에서 에러가 발생하면 try/catch로 에러를 잡아 rollback() 함수를 실행하는 것을 확인할 수 있다. 그럼 어디가 문제인걸까?
- 가설
- 두 번째 가설
- 가설
- RuntimeException이 아니라, Exception 클래스로 에러가 발생하여 에러 핸들링을 하지 못하나? 위 코드에서도 RuntimeException만 핸들링 하는 것으로 보이네!
- 검증
실제 코드에서 발생하는 에러는 ClassNotFoundException으로, RuntimeException을 상속하지 않는 클래스이다.
따라서 try/catch에 잡히지 않기 때문에 rollback이 되지 않고 에러를 뱉어서 commit까지 가지 않는 것이다. 그래서 lock을 계속 잡고 있는 것이다.
그럼 여기서 한가지 의문이 든다. 왜 Entity에 PostUpdate 혹은 Listener를 추가했을 때 동일하게 ClassNotFoundException 으로 exception을 발생시켜도 문제가 되지 않는가? (실제로 해봤는데 정상 동작한다!)
그 이유는 JPA에서 exception을 랩핑하여 전파하기 때문이다. 코드를 확인해보자.
// ListenerCallback.java 52 lines @Override public boolean performCallback(Object entity) { try { callbackMethod.invoke( listenerManagedBean.getBeanInstance(), entity ); return true; } catch (InvocationTargetException e) { //keep runtime exceptions as is if ( e.getTargetException() instanceof RuntimeException ) { throw (RuntimeException) e.getTargetException(); } else { throw new RuntimeException( e.getTargetException() ); } } catch (RuntimeException e) { throw e; } catch (Exception e) { throw new RuntimeException( e ); } }
여기서 주목할 점은 Exception 클래스도 RuntimeException으로 변환하여 다시 throw 한다는 것이다.
그럼 모든 exception이 RuntimeException으로 변환될 것이고, 변환된 exception들은 모두 정상 동작하기 때문에 문제가 없는 것이다.
- 가설
✏️ 해결 방법
PostUpdateEventListener의 onPostUpdate() 함수를 예외처리 문으로 감싸서 에러를 방지하도록 하면 문제는 쉽게 해결된다.
override fun onPostUpdate(
event: PostUpdateEvent
) {
runCatching {
...
}
}
번외
그렇다면 왜 Lock이 계속 유지될까? 에러 상황에서 언급했듯이, hikariCP에서 maxLifeTime의 default 값인 30분이 지나도 lock은 계속 유지되고 있었다. connection이 생존시간을 넘어가면 자연스럽게 lock도 풀려야하지 않나?
이는 hikariCP 동작 방식을 보면 이해할 수 있다. hikari는 실행 중인 connection은 동작이 완료될 때까지 종료하지 않는다. 위 상황처럼 에러가 발생해 connection을 제대로 종료하지 못한 경우에는 connection이 계속 유효하다고 판단한다.
따라서 lock이 계속 유지되는 상황이 발생하는 것이다.
그럼 hibernate 버그 아닌가?
개인적인 생각으로는 코틀린이기 때문에 발생했다고 생각한다. java에서는 RuntimeException을 상속하지 않는 Exception들은 checked Exception으로 반드시 예외처리가 되어야 한다. 그러나 kotlin에서는 checked Exception과 uncheckedException의 구분이 없기 때문에 핸들링 하지 않았고, 해당 에러가 발생할 수 있었던 것이다.
문제가 됐던 Class.forName 함수 코드를 확인해보면 ClassNotFoundException을 상위 메서드로 던지고 있다.
public static Class<?> forName(String className)
throws ClassNotFoundException {
Class<?> caller = Reflection.getCallerClass();
return forName0(className, true, ClassLoader.getClassLoader(caller), caller);
}
java 였으면 에러 핸들링이 없어서 컴파일 단계에서 에러가 발생 할 것이다.
'JPA' 카테고리의 다른 글
| 무서운 @OneToMany (0) | 2024.08.16 |
|---|---|
| @UpdateTimestamp의 비밀 (1) | 2023.04.30 |
