Spring JPA 영속성 컨텍스트 그리고 OSIV

장애일지

Spring JPA 영속성 컨텍스트 그리고 OSIV

kimjambo 2023. 1. 10. 00:31

회사 블로그에 이미 기재한 글이지만 2023년 한 달에 두 번 글쓰기라는 목표를 정하게 된 계기인 JPA 영속성 컨텍스트와 OSIV에 대한 내용입니다. ~~(회사 블로그 복붙)~~

저는 레일즈 개발만 주야장천 해오다 최근 Kotlin + Spring 프로젝트를 인계받게 됐고, 이 글은 전환 과정 중 JPA 영속성 콘텍스트를 제대로 이해하지 못해 발생한 문제를 분석한 글입니다.

발단

회사에서 Kotlin + Spring 으로 만들어져 있던 프로젝트를 인계받게 됐고, 첫 한 달은 큰 문제없이 유지보수 하며 개발할 수 있었습니다. 항상 사고는 초보 딱지를 뗀 다음에 온다더니.. 문제는 그 뒤에 발생했습니다.

기존 Spring Batch 에서 호출하도록 만들어져 있던 핵심 함수를 AWS SQS에서 호출되도록 변경했습니다. 당연히 테스트도 진행했고 단순히 트리거 포인트만 변경하는 작업이라 문제없이 동작할 것이라 기대했습니다.

하지만 위 변경사항을 적용하자 DB에 데이터가 업데이트 되지 않는 문제가 발생했습니다. 이로 인해 제가 소속된 팀원들과 2주 이상 밤을 새우다시피 하며 고생하게 됐습니다.

문제가 됐던 버전을 롤백하고 2주간 고생하며 수습한 뒤 곰곰히 생각해보니 다시 살펴봐도 분명 트리거 포인트만 변경했고 핵심 함수는 건들지 않았는데 함수의 실행 결과가 달라지는 이상한 상황이었고, 요리 살펴봐도.. 조리 살펴봐도.. 동일한 코드에 동일한 INPUT인데 OUTPUT 이 다른 상황이라 멘탈이 박살 났습니다.

여러 추측이 있었지만 명확한 원인파악이 되지 않아 서비스에서 사용 중이던 JPA부터 시작해 다시 처음부터 파보기 시작했습니다. 문제가 됐던 코드는 아래에서 자세히 다뤄보도록 하겠습니다.

다시 처음부터.. JPA

위 이미지를 아래서부터 살펴보면 제일 아래에 RDBMS 가 위치해 있고 그 위로 JDBC (Java Database Connectivity), Hibernate, JPA(Java Persistence API)가 위치해 있는데 각 역할은 아래와 같습니다.

JDBC (Java DataBase Connectivity) — DB 커넥션, SQL 실행 핸들링에 대한 표준 API, 때문에 각 DB 에 맞는 JDBC Dirver 를 설치해 사용해야 한다.
Hibernate — 내부적으로 JDBC 를 사용하는 ORM 프레임워크로 JPA (Java Persistence API) 를 구현한 구현체
JPA (Java Persistence API) — 애플리케이션에서 사용할 ORM 표준 API
SpringDataJPA — JPA를 조금 더 편하게 쓰기 위해 확장한 모듈

때문에 어플리케이션에서 JPA 를 사용한다면 주로 SpringDataJPA > JPA API > Hibernate > JDBC API > JDBC Driver > DATABASE의 순서를 거쳐 실행이 됩니다.

영속성 콘텍스트

JPA에서 빠질 수 없고 단어부터 어려운 영속성 콘텍스트! 과연 무엇일까요?

JPA는 ORM 표준으로 DB의 테이블을 Entity class와 매핑해 사용하고 DB에 저장된 데이터를 Entity class 의 객체로 매핑해 사용하는데 이를 Entity 라고 부릅니다. DB 에 저장된 데이터를 매핑한 Entity 인 만큼 역으로 Entity 의 생성/변경/삭제 또한 DB 에 반영돼 데이터가 생성/변경/삭제되기도 하는데 이 일을 중재하는 것이 EntityManager입니다.

제가 이해하기로 영속성 콘텍스트란 EntityManager에 의해서 관리되는 Entity의 라이프 사이클에 대한 내용입니다.

EntityManager는 내부적으로 Entity 들을 관리하고, Entity 들의 변경사항들을 DB에 동기화 하는 일을 합니다. 때문에 Entity 의 변경사항을 DB 에 반영하고 싶다면 EntityManager 를 통해서 저장을 해줘야하는데요. EntityManager .managed() 를 사용해 현재 관리되고 있는 상태(Managed)로 등록해주고 EntityManager .flush() 를 호출해주어야 DB 에 변경사항이 반영됩니다. 백날 Entity를 수정해도. flush()를 호출해주지 않는다면 DB 변경사항이 업데이트되지 않습니다.

val em = emf.createEntityManager()

val user = userRepository.findByName("Jambo")
user.name = "KJambo" # => 변경되지 않음 

em.persist(user)
em.flush() # => 변경

SpringDataJPA

사실 SpringDataJPA를 사용하다 보면 EntityManager를 직접 사용할 일은 적습니다. SpringDataJPA 가 내부적으로 EntityManager 를 간편하게 사용할 수 있도록 몇 가지 기능을 제공하고 있기 때문인데요.

SimpleJpaRepository.class

일반적으로 많이 사용하는. save() 함수는 저장이 필요한 entity를 파라미터로 넘겨 DB 데이터를 생성 또는 수정하는 함수입니다. 때문에 내부 구현체를 확인해보면 새로운 Entity 라면 em (EntityManager). persist()로 관리 상태(Managed)로 만들어주고 아니라면. merge()를 호출해 관리 상태로 만들어주고 있습니다.

눈썰미가 좋은 분들은 여기서 특이한 점을 발견하셨을 겁니다. 바로. flush()를 호출하는 코드는 보이지 않는다는 겁니다! EntityManager 가 DB에 동기화되는 시점은. flush()가 호출될 때인데 아무리 봐도. flush()가 호출되는 코드는 보이지 않습니다.

사실. flush()를 직접 호출해주지 않아도 디비에 관리상태의 Entity 들을 저장할 수 있는 방법이 있는데 바로 Transaction을 사용하는 경우입니다. Transaciton을 사용하면 Transaction 이 commit 될 때 알아서. flush() 호출해주고 있기 때문에 별도 코드 없이. save() 함수가 종료되면 @Transacitonal 어노테이션으로 해당 함수가 Transaction 블록 처리가 되어 함수가 종료되는 시점에. flush()가 호출되는 것이었습니다.

문제 재현해 보기

JPA 영속성 콘텍스트와 SpringDataJPA까지 동작 방식을 확인해 보았는데요. 이제 제가 겪었던 문제를 코드로 재현해 보도록 하겠습니다.

@Entity
class Bank(
  @Id
  @GeneratedValue(strategy = GenerationType.IDENTITY)
  val id: Long = 0L,

  @ManyToOne
  @JoinColumn(name="user_id")
  var user: User? = null,

  var amount: Int = 0,
) {
}

@Entity
class User(
  @Id
  @GeneratedValue(strategy = GenerationType.IDENTITY)
  val id: Long = 0L,

  val name: String? = null,
  var totalAmount: Int = 0,
) {
}

우선 두 개의 Entity class를 만들어줍니다. User entity class에서는 사용자의 이름 정보와 총 자산 정보를 저장하고 있고, Bank entity class 에서는 사용자에게 지급된 금액 정보를 저장하고 있습니다.

@Service
class BankService(
  private val userRepository: UserRepository,
  private val bankRepository: BankRepository
) {

  fun giveMeTheMoney(user: User) {
    val money = createMoney(user)

    money.amount = 1_000
    user.totalAmount += money.amount

    userRepository.save(user)
  }

  private fun createMoney(user: User): Bank {
    return bankRepository.save(
      Bank(
        user = user,
      )
    )
  }
}

이때 사용자에게 1,000 원을 지급하고 지급내역을 저장하는 BankService. giveMeTheMoney() 함수를 만들었습니다. 코드는 간단합니다. 그런데 의도한 대로 동작을 할까요? 실제로 테스트 코드에서 정상적으로 1,000 원을 지급한 내역이 만들어지고 사용자의 총자산이 증가하는지 확인해보도록 하겠습니다.

@SpringBootTest
class BankServiceTest @Autowired constructor(
  private val bankService: BankService,
  private val userRepository: UserRepository,
  private val bankRepository: BankRepository,
) {

  @AfterEach
  fun clean() {
    bankRepository.deleteAll()
    userRepository.deleteAll()
  }

  @Test
  fun `사용자에게 1,000원을 지급한다.`() {
    var user = userRepository.save(User(name = "Jambo"))

    bankService.giveMeTheMoney(user)

    user = userRepository.findByIdOrNull(user.id) ?: throw IllegalArgumentException("ID 없음")
    val bankAmount = bankRepository.findAll().sumOf { it.amount }

    assertThat(user.totalAmount).isEqualTo(1_000)
    assertThat(bankAmount).isEqualTo(1_000)
  }
}

테스트 코드 내용은 이렇습니다! Jambo user를 만들어 giveMeTheMoney() 함수를 호출합니다. 함수에서는 사용자에게 천 원을 지급하고, 지급된 내역을 저장하고 있기 때문에 사용자가 가진 총 자산 금액과 은행이 지급한 내역은 동일해야 합니다!

하지만 테스트를 돌려보면 테스트는 실패하고 bankAmount 에는 0원이 들어있습니다. 왜 저장되지 않은 걸까요? 사실 코드를 차근차근 살펴보면 이유를 알 수 있습니다.

  fun giveMeTheMoney(user: User) {
    val money = createMoney(user)

    money.amount = 1_000
    user.totalAmount += money.amount

    userRepository.save(user)
  }

  private fun createMoney(user: User): Bank {
    return bankRepository.save(
      Bank(
        user = user,
      )
    )
  }

EntityManager는. flush()를 호출해주거나 또는 Transaction commit 이 발생할 때 디비에 Entity의 변경사항을 저장해준다고 위에서 설명했습니다.. save() 구현체에서는 별도. flush()를 호출해주고 있지 않지만 @Transactional 어노테이션을 사용해 함수가 종료되면 자동으로 Transaction commit 이 발생하기 때문에 자동으로. flush()가 호출되고 있습니다. 여기서 또 중요한 부분이 있는데. flush()가 호출된 후. close()를 호출해 관리 상태 (Managed)로 남아있던 Entity 들을 관리 해제 (Detached) 상태로 변경한다는 것입니다!

때문에 위 코드를 순서대로 읽어보면 아래 순서로 Entity 관리 상태가 변경됩니다.

1. Bank(user = user, amount = 0) Entity 생성
2. Bank(user = user, amount = 0) Entity .persist()
3. Transaction commit 이 발생
4. Bank(user = user, amount = 0) Entity .flush()
5. Bank(user = user, amount = 0) Entity .close()
6. Bank(user = user, amount = 1000) 으로 Entity 수정
7. User(name = "Jambo", totalAmount = 1000) 으로 Entity 수정
8. User(name = "Jambo", totalAmount = 1000) Entity .merge()
9. Transaction commit 이 발생
10. User(name = "Jambo", totalAmount = 1000) Entity .flush()
11. User(name = "Jambo", totalAmount = 1000) Entity .close()

5번에서. close()를 호출해 Bank Entity를 관리 해제 상태로 변경했는데 6번에서 amount 값을 1000으로 수정했고 그 이후로. merge()를 통해 다시 관리 상태(Managed)로 만들어주지 않아 이후 코드에서 EntityManager. flush()가 호출되어도 Bank Entity의 변경사항은 저장되지 않았던 것이었습니다!

OSIV 또는 OEIV

네 그럼. giveMeTheMoney() 함수는 애초에 잘못 만들어진 함수이고 지급 내역이 정상적으로 저장될 일은 없는 함수인 것이겠죠? 하지만 REST API로 호출해보면 어떨까요?

@RestController
@RequestMapping("/test")
class TestController(
  private val bankService: BankService,
  private val userRepository: UserRepository,
  private val bankRepository: BankRepository
) {

  @PostMapping("/money")
  fun money() {
    var user = userRepository.save(User(name = "Jambo"))

    bankService.giveMeTheMoney(user)

    val bankAmount = bankRepository.findAll().sumOf { it.amount }

    println(bankAmount)
  }
}

테스트 코드와 동일하게. giveMeTheMoney()를 호출해주고 있습니다. 하지만 결과는 테스트 코드와 다른데요. 로그를 확인해보면 아래와 같습니다.

2023-01-04 10:27:33.311 DEBUG 4297 --- [nio-8080-exec-4] o.s.web.servlet.DispatcherServlet        : POST "/test/money", parameters={}
2023-01-04 10:27:33.311 DEBUG 4297 --- [nio-8080-exec-4] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2023-01-04 10:27:33.340 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(1607166658<open>)] for JPA transaction
2023-01-04 10:27:33.340 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2023-01-04 10:27:33.340 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.t.internal.TransactionImpl         : begin
2023-01-04 10:27:33.342 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@34a113e7]
2023-01-04 10:27:33.342 DEBUG 4297 --- [nio-8080-exec-4] org.hibernate.engine.spi.ActionQueue     : Executing identity-insert immediately
2023-01-04 10:27:33.342 DEBUG 4297 --- [nio-8080-exec-4] org.hibernate.SQL                        : insert into bank (amount, user_id) values (?, ?)
2023-01-04 10:27:33.344 DEBUG 4297 --- [nio-8080-exec-4] o.h.id.IdentifierGeneratorHelper         : Natively generated identity: 12
2023-01-04 10:27:33.344 DEBUG 4297 --- [nio-8080-exec-4] o.h.r.j.i.ResourceRegistryStandardImpl   : HHH000387: ResultSet's statement was not registered
2023-01-04 10:27:33.344 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2023-01-04 10:27:33.344 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(1607166658<open>)]
2023-01-04 10:27:33.345 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.t.internal.TransactionImpl         : committing
2023-01-04 10:27:33.345 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.i.AbstractFlushingEventListener    : Processing flush-time cascades
2023-01-04 10:27:33.345 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.i.AbstractFlushingEventListener    : Dirty checking collections
2023-01-04 10:27:33.345 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.i.AbstractFlushingEventListener    : Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
2023-01-04 10:27:33.345 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.i.AbstractFlushingEventListener    : Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2023-01-04 10:27:33.345 DEBUG 4297 --- [nio-8080-exec-4] o.hibernate.internal.util.EntityPrinter  : Listing entities:
2023-01-04 10:27:33.345 DEBUG 4297 --- [nio-8080-exec-4] o.hibernate.internal.util.EntityPrinter  : com.example.demo.domain.user.User{totalAmount=0, name=Jambo, id=12}
2023-01-04 10:27:33.345 DEBUG 4297 --- [nio-8080-exec-4] o.hibernate.internal.util.EntityPrinter  : com.example.demo.domain.bank.Bank{amount=0, id=12, user=com.example.demo.domain.user.User#12}
2023-01-04 10:27:33.350 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Not closing pre-bound JPA EntityManager after transaction
2023-01-04 10:27:33.350 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Found thread-bound EntityManager [SessionImpl(1607166658<open>)] for JPA transaction
2023-01-04 10:27:33.350 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2023-01-04 10:27:33.350 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.t.internal.TransactionImpl         : begin
2023-01-04 10:27:33.352 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@7985f77d]
2023-01-04 10:27:33.352 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2023-01-04 10:27:33.352 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(1607166658<open>)]
2023-01-04 10:27:33.352 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.t.internal.TransactionImpl         : committing
2023-01-04 10:27:33.352 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.i.AbstractFlushingEventListener    : Processing flush-time cascades
2023-01-04 10:27:33.352 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.i.AbstractFlushingEventListener    : Dirty checking collections
2023-01-04 10:27:33.352 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.i.AbstractFlushingEventListener    : Flushed: 0 insertions, 2 updates, 0 deletions to 2 objects
2023-01-04 10:27:33.352 DEBUG 4297 --- [nio-8080-exec-4] o.h.e.i.AbstractFlushingEventListener    : Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2023-01-04 10:27:33.352 DEBUG 4297 --- [nio-8080-exec-4] o.hibernate.internal.util.EntityPrinter  : Listing entities:
2023-01-04 10:27:33.353 DEBUG 4297 --- [nio-8080-exec-4] o.hibernate.internal.util.EntityPrinter  : com.example.demo.domain.user.User{totalAmount=1000, name=Jambo, id=12}
2023-01-04 10:27:33.353 DEBUG 4297 --- [nio-8080-exec-4] o.hibernate.internal.util.EntityPrinter  : com.example.demo.domain.bank.Bank{amount=1000, id=12, user=com.example.demo.domain.user.User#12}
2023-01-04 10:27:33.353 DEBUG 4297 --- [nio-8080-exec-4] org.hibernate.SQL                        : update user set name=?, total_amount=? where id=?
2023-01-04 10:27:33.355 DEBUG 4297 --- [nio-8080-exec-4] org.hibernate.SQL                        : update bank set amount=?, user_id=? where id=?
2023-01-04 10:27:33.363 DEBUG 4297 --- [nio-8080-exec-4] o.s.orm.jpa.JpaTransactionManager        : Not closing pre-bound JPA EntityManager after transaction
1000

전체 로그를 이해하는 건 아니지만 대략적으로 살펴보면
- Found thread-bound EntityManager EntityManager 찾았고
- Transaction begin 시작했고
- insert into bank (amount, user_id) values (?,?) Bank Entity insert 했고
- committing & flush 했는데..
- Not closing pre-bound JPA EntityManager after transaction close 는 되지 않는다?!

로그상으로는 EntityManager. close()가 호출되지 않아서 관리 중인 Entity들이 관리 해제 되지 않은 걸로 보입니다.

fun giveMeTheMoney(user: User) {
    val money = createMoney(user)

    money.amount = 1_000
    user.totalAmount += money.amount

    userRepository.save(user)
  }

  private fun createMoney(user: User): Bank {
    return bankRepository.save(
      Bank(
        user = user,
      )
    )
  }

원래라면. createMoney()에서 만들어진 Bank Entity는. save() 함수가 종료되면. close()가 호출돼 관리 해제가 돼 이후 userRepository.save(user) 실행될 때는 변경사항이 DB에 반영되지 않아야 하지만, REST API 로 호출하면 .close() 가 호출되지 않아 관리 상태로 남아있게 됐고 이후 userRepository.save(user) 에서 관리 상태로 남아있는 두 Entity 의 변경사항이 모두 .flush() 되는 일이 발생합니다. (엄밀히 말하면 하나의 EntityManager 가 .save() 이후에도 없어지지 않고 재사용 된 것도 OSIV 옵션 때문입니다.)

결국 테스트코드에서는 저장되지 않았던 money.amount = 1_000 코드가 DB 에 반영되며 은행에서 지급해준 총합은 천 원으로 사용자가 가진 금액 합계와 동일해졌습니다.

왜 이런 차이가 발생한 걸까요?

이유는 로그에서 찾아볼 수 있습니다. 저도 원인을 알 수 없어 로그를 찾아보다 테스트 코드를 실행했을 때는 발견할 수 없었던 로그를 발견했는데요. 바로 OpenEntityManagerInViewInterceptor입니다. 리퀘스트 요청 즉시 생성되는 로그에서 찾을 수 있는데요. 어떤 역할을 하는 녀석인지 찾아보면 이러합니다.

Spring web request interceptor that binds a JPA EntityManager to the thread for the entire processing of the request. Intended for the “Open EntityManager in View” pattern, i.e. to allow for lazy loading in web views despite the original transactions already being completed.

즉 OSIV 또는 OEIV 패턴을 사용하기 위한 스프링 웹 인터셉터로 트랜잭션이 종료되더라도 EntityManager의 관리 상태를 유지하는 기능이었던 것입니다!

출처: https://ykh6242.tistory.com/entry/JPA-OSIVOpen-Session-In-View%EC%99%80-%EC%84%B1%EB%8A%A5-%EC%B5%9C%EC%A0%81%ED%99%94

OSIV는 원래라면 유지되지 않는 영속성 콘텍스트를 View 랜더링 또는 컨트롤러 단에서도 유지시켜 View Layer 위한 데이터 오브젝트를 유지하지 않아도 되는 등의 편의를 제공하는 기능입니다.

위 기능이 Spring에서 기본적으로 켜져있다 보니 Rest Controller에서 Transaction 이 종료되더라도 Entity들이 관리 상태로 남아있게 됐고 스레드에 바인딩된 EntityManager. flush()가 될 때 관리 중인 모든 Entity의 변경사항이 함께 저장되는 것이었습니다.

spring.jpa.open-in-view=false

OSIV 옵션을 끄면 의도한 대로 (?) 저장이 되지 않는지 확인해보도록 하겠습니다.

2023-01-04 14:52:15.285 DEBUG 21683 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : POST "/test/money", parameters={}
...
2023-01-04 14:52:15.537 DEBUG 21683 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.findAll]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
2023-01-04 14:52:15.537 DEBUG 21683 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(1634329259<open>)] for JPA transaction
2023-01-04 14:52:15.538 DEBUG 21683 --- [nio-8080-exec-1] o.s.jdbc.datasource.DataSourceUtils      : Setting JDBC Connection [HikariProxyConnection@1135301420 wrapping com.mysql.cj.jdbc.ConnectionImpl@61911947] read-only
2023-01-04 14:52:15.541 DEBUG 21683 --- [nio-8080-exec-1] o.h.e.t.internal.TransactionImpl         : On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2023-01-04 14:52:15.541 DEBUG 21683 --- [nio-8080-exec-1] o.h.e.t.internal.TransactionImpl         : begin
2023-01-04 14:52:15.543 DEBUG 21683 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@1b4d681b]
2023-01-04 14:52:15.543 DEBUG 21683 --- [nio-8080-exec-1] o.h.q.c.internal.CriteriaQueryImpl       : Rendered criteria query -> select generatedAlias0 from Bank as generatedAlias0
2023-01-04 14:52:15.543 DEBUG 21683 --- [nio-8080-exec-1] org.hibernate.SQL                        : select bank0_.id as id1_0_, bank0_.amount as amount2_0_, bank0_.user_id as user_id3_0_ from bank bank0_
2023-01-04 14:52:15.546 DEBUG 21683 --- [nio-8080-exec-1] org.hibernate.loader.Loader              : Result set row: 0
2023-01-04 14:52:15.546 DEBUG 21683 --- [nio-8080-exec-1] org.hibernate.loader.Loader              : Result row: EntityKey[com.example.demo.domain.bank.Bank#13]
2023-01-04 14:52:15.547 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Resolving attributes for [com.example.demo.domain.bank.Bank#13]
2023-01-04 14:52:15.547 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Processing attribute `amount` : value = 0
2023-01-04 14:52:15.547 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Attribute (`amount`)  - enhanced for lazy-loading? - false
2023-01-04 14:52:15.547 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Processing attribute `user` : value = 13
2023-01-04 14:52:15.547 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Attribute (`user`)  - enhanced for lazy-loading? - false
2023-01-04 14:52:15.547 DEBUG 21683 --- [nio-8080-exec-1] org.hibernate.SQL                        : select user0_.id as id1_1_0_, user0_.name as name2_1_0_, user0_.total_amount as total_am3_1_0_ from user user0_ where user0_.id=?
2023-01-04 14:52:15.554 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Resolving attributes for [com.example.demo.domain.user.User#13]
2023-01-04 14:52:15.554 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Processing attribute `name` : value = Jambo
2023-01-04 14:52:15.554 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Attribute (`name`)  - enhanced for lazy-loading? - false
2023-01-04 14:52:15.554 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Processing attribute `totalAmount` : value = 1000
2023-01-04 14:52:15.554 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Attribute (`totalAmount`)  - enhanced for lazy-loading? - false
2023-01-04 14:52:15.554 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Done materializing entity [com.example.demo.domain.user.User#13]
2023-01-04 14:52:15.554 DEBUG 21683 --- [nio-8080-exec-1] .l.e.p.AbstractLoadPlanBasedEntityLoader : Done entity load : com.example.demo.domain.user.User#13
2023-01-04 14:52:15.555 DEBUG 21683 --- [nio-8080-exec-1] o.h.engine.internal.TwoPhaseLoad         : Done materializing entity [com.example.demo.domain.bank.Bank#13]
2023-01-04 14:52:15.555 DEBUG 21683 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2023-01-04 14:52:15.555 DEBUG 21683 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(1634329259<open>)]
2023-01-04 14:52:15.555 DEBUG 21683 --- [nio-8080-exec-1] o.h.e.t.internal.TransactionImpl         : committing
2023-01-04 14:52:15.559 DEBUG 21683 --- [nio-8080-exec-1] o.s.jdbc.datasource.DataSourceUtils      : Resetting read-only flag of JDBC Connection [HikariProxyConnection@1135301420 wrapping com.mysql.cj.jdbc.ConnectionImpl@61911947]
2023-01-04 14:52:15.561 DEBUG 21683 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1634329259<open>)] after transaction
0

OSIV 옵션을 끄자 Closing JPA EntityManager. close()가 호출되면서 관리 해제 상태로 넘어가 println의 결과도 0 원으로 찍히는 것을 확인할 수 있었습니다.

마지막으로

결국 문제는 OSIV 옵션으로 인해 스레드 바인딩 된 EntityManager의 영속성 콘텍스트가 종료되지 않아 정상적으로 동작하는 것처럼 보였지만! 사실은 경우에 따라서는 동작하지 않을 수도 있습니다! 짜잔!

문제 원인을 찾았습니다!! 끝!! 여러분도 조심하세요!

라고 끝나게 되었지만 사실문제를 파볼수록 결국 가장 큰 문제는 OSIV 옵션도 @Transactional 어노테이션이 붙어있지 않아서도 아닌 코드에서 데이터의 변경을 명시적으로 알 수 없었던 것이 가장 큰 문제이지 않았나 생각이 들었습니다.

코드를 명시적으로 이해하기 어려운 상태에서 기존에 잘 동작하던 코드이니 문제없겠지, 스프링의 기능이겠거니 생각해 자세히 파보지 않은 상태로 넘겼고 그 안일함에 대한 결과가 장애로 나타났다고 생각합니다.

앞으로는 이러한 문제를 피하기 위해 데이터에 변경사항들을 명확히 알 수 있도록. save() 함수를 사용해 코드를 작성하려고 합니다.

Spring + JPA를 시작하면서 많은 고수님들이 JPA 영속성 콘텍스트만 이해하면 된다고 여러 번 말씀을 주셨는데 큰 값을 치르고 이해하게 됐습니다. 부디 다른 분들은 저와 같은 실수를 하지 않길 바라며.. 🙏 긴 글 읽어주셔서 감사합니다.