JPA 영속성 컨텍스트와 OSIV

안녕하세요, 한국신용데이터에서 뱅킹 프로덕트 개발을 하고 있는 백엔드 개발자 잠보입니다.

저는 개발 커리어를 루비 온 레일즈로 시작했고, 한국신용데이터에 함께하고 나서도 쭉 레일즈로 만들어진 캐시노트 서버 개발을 해왔습니다.

하지만 최근 서비스된 한국신용데이터의 마켓 서비스와 뱅킹 서비스는 Kotlin + Spring 으로 만들어져 있었고 개발자 채용에 어려움이 있어 레일즈에서 Kotlin + Spring 전환을 결정 했습니다.

이 글은 전환 과정중에 JPA 를 정확히 이해하지 못해 생겼던 문제를 정리한 글입니다.

kotlin + spring 강의

한국신용데이터에서는 레일즈 개발자들의 원활한 스프링 전환을 돕기 위해 전문 강사를 초빙해 2주간 짧고 굵은 kotlin + spring 강의를 진행했는데요.

너무 좋은 강의로 뽕이 차올라 스프링으로 운영되고 있던 금융 서비스를 인계받아 개발을 시작했고.. 재앙이 시작됐습니다..

사건의 발단

저는 뱅킹팀에서 운영 중인 빠른정산 서비스(현금 흐름 유동화 서비스)를 인수인계 받아 개발을 진행했고 첫 한 달은 큰 문제 없이 유지보수를 할 수 있었습니다.

항상 사고는 초보 딱지를 뗀 다음에 온다더니.. 문제는 그 뒤에 발생했습니다. 자신감에 차오른 저는 정해진 시간에 일괄적으로 정산금을 지급해주는 배치를 AWS SQS 를 사용해 사용자별로 순차적으로 지급되도록 변경했습니다.

물론 정산의 핵심 기능을 변경하지는 않았습니다. 핵심 함수를 호출하는 트리거 포인트만 변경해서 큰 문제가 발생하지 않는다고 생각했고 테스트 결과도 문제가 없어보였습니다. (지금 생각해보면 당연히 테스트도 완벽하지 않았습니다.)

하지만 위 변경사항을 적용하자 DB에 데이터가 업데이트 되지 않는 문제가 발생했습니다. 이로 인해 뱅킹팀(제가 소속된)의 거의 모두가 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 를 간편하게 사용할 수 있도록 몇가지 기능을 제공하고 있기 때문인데요.

일반적으로 많이 사용하는 .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 의 관리 상태를 유지하는 기능이였던 것입니다!

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 영속성 컨텍스트만 이해하면 된다고 여러번 말씀을 주셨는데 큰 값을 치루고 이해하게 됐습니다. 부디 다른분들은 저와 같은 실수를 하지 않길 바라며 .. 🙏 긴 글 읽어주셔서 감사합니다.