ddl-auto를 설정하면서 발생한 이슈 (1)
문제
우리 회사에서는 운영 환경에서 ddl-auto를 validate로 설정하도록 권장하고 있다.
그런데 우리 팀에서 이 부분이 적용되어 있지 않아 운영 배포시 warning 알람이 오는 것을 발견하게 되었다.
ddl-auto 설정 추가 작업을 진행하던 중 특정 프로젝트에서만 해당 설정이 동작하지 않는 이슈가 발생했다.
(그냥 .yml에 ddl-auto: validate 한줄만 추가하면 되는 줄 알고 시작했는데… 🥲)
분석
로그 분석
단순히 application을 실행시켜 테스트 해보았을때 알 수 있었던 점은 다음 2가지이다.
- yml 작성 형식에 맞게 작성했음에도 불구하고 특정 프로젝트에서만 동작하지 않는다.
- index에 포함되는 컬럼의 경우 application 실행에 실패하지만, index에 포함되지 않는 경우 무시된다.
먼저 ddl-auto 설정이 동작하는 프로젝트와 문제가 되는 프로젝트의 로그를 비교해보았다.
(디버깅 잘하는 사람들은 로그를 엄청 열심히 보길래 한번 따라해봤다.)
정상 케이스(ddl-auto가 잘 적용되는 케이스)
autoconfigure를 통한 EntityManagerFactory 빈 생성에 실패했고, SchemaManagementException이 발생했다.
AbstractSchemaValidator.validateTable() 가 호출될때 예외가 발생한다.
💡 정상 케이스는 AbstractSchemaValidator 에서 스키마를 검증한다.
문제 케이스(ddl-auto가 적용되지 않는 케이스)
뭔지는 몰라도 일단 autoconfigure가 아닌 직접 구현된 설정을 통한 EntityManagerFactory 빈 생성에 실패해고, AnnotationException이 발생했다.
InflightMetadataCollectorImpl.buildUniqueKeyFromColumnNames() 가 호출될때 예외가 발생했다.
💡 문제 케이스는 spring boot에서 autoconfigure를 통해 제공하는 EntityManagerFactory를 사용하지 않고 있다.
// TODO: 어떤 경우에 직접 EntityManagerFactory를 Bean 등록해 사용하는건지 알아보기
코드 분석
인텔리제이의 디버그 기능을 사용하기 위해 breakpoint를 걸어보았다.
1. AbstractSchemaValidator.validateTable()
로그를 분석하면서 이 부분에서 테이블 정보에 대한 검증이 이루어진다는 것을 알게되었다.
메서드를 살펴보면,
- 읽어온 table 정보에 validate하고자 하는 column이 존제하는지 확인하고 없는 경우
- 읽어온 column 정보와 실제 column의 타입이 일치하지 않는 경우
SchemaManagementException을 던지고 있다.
테이블 정보가 제대로 들어오는지 확인해보기 위해 breakpoint를 걸어보았는데, 걸리지 않고 넘어갔다.
validateTable()는 같은 클래스의 doValidation() 메서드를 통해 호출되고 있었고, 이 부분에 다시 breakpoint를 걸어보았다.
이번에도 걸리지 않고 넘어가고 있었다. 즉, 애초에 validate 메서드를 타지 않는다는 사실을 알게 되었다.
2. SchemaManagementToolCoordinator.performDatabaseAction()
AbstractSchemaValidator.doValidate()가 호출되는 부분을 따라가보니 SchemaManagementToolCoordinator.performDatabaseAction() 에서 ddl-auto 설정인 action에 따라 실행되고 있었다.
action 값을 확인하기 위해 진입점인 SchemaManagementToolCoordinator.performDatabaseAction()에 breakpoint를 걸어보았다.
확인해본 결과 action은 NONE으로 설정되어 있었고, 때문에 SchemaManagementToolCoordinator.performDatabaseAction()는 호출조차 되고 있지 않았다.
3. JpaProperties
위 코드는 ddl-auto가 설정되지 않는 프로젝트에서 EntityManagerFactory 빈을 생성하는 부분이다.
나는 당연히 파라미터의 JpaProperties에서 JPA 관련 모든 설정을 가져오고 있을 것으로 예상했다.
JpaProperties 구현체를 살펴보니, @ConfigurationProperties(prefix = "spring.jpa")로 jpa 관련 설정에 접근하고는 있었지만, ddl-auto 관련 설정은 가져오지 않고 있었다.
이때 섣부른 예측으로 빠르게 캐치할 수 있었던 부분을 놓친 것 같아 아차싶었다. 🥲
(다시 보니 여기서 ddl-auto 설정이 설정 파일의 spring.jpa.hibernate 하위에 속한다는 것을 감안해 @ConfigurationProperties(prefix = "spring.jpa.hibernate")를 검색해 볼 생각을 했을 수도 있을 것 같다.)
4. HibernateProperties.getAdditionalProperties()
구글링을 통해 EntityManagerFactory를 직접 bean 등록해서 사용하고 있는 다른 프로젝트에서는 ddl-auto를 어떻게 적용시키고 있는지 알아보았다.
대부분 bean 생성시에 properties에 직접 AvailableSettings.HBM2DDL_AUTO라는 이름으로 ddl-auto 설정을 넣어주고 있었다.
그래서 자동으로 EntityManagerFactory bean이 생성될때 해당 설정을 세팅해주는 곳을 찾아보기 위해 AvailableSettings.HBM2DDL_AUTO가 사용되는 곳을 따라가보았더니, HibernateProperties.getAdditionalProperties()가 나왔다.
참고로 ddl-auto 값은
JpaProperties에서 가져온 값HibernateProperties에서 가져온 값DataSource를 통해 가져온 기본 값
순서대로 값의 유무를 확인하면서 값이 존재하는 경우 해당 값으로 설정되고, 값이 존재하지 않는 경우 다음 값으로 넘어가는 방식으로 동작하고 있었다.
5. HibernateJpaConfiguration.getVendorProperties()
HibernateProperties.getAdditionalProperties()가 호출되는 HibernateProperties.determineHibernateProperties() 메서드를 사용하고 있는 곳은 HibernateJpaConfiguration.getVendorProperties()였다.
여기서 133번 라인이 앞서 말한 DataSource를 통해 ddl-auto의 기본값을 가져오는 부분이고, 135번 라인은 JpaProperties의 세팅되어 있는 properties를 가져오는 부분이다.
원인
HibernateJpaConfiguration.getVendorProperties()가 호출되는 곳을 따라가보니, JpaBaseConfiguration.entityManagerFactory()가 나왔고, 이 메서드는 autoConfigure로 EntityManagerFactory가 bean으로 등록되는 곳이었다.
여기서 131번 라인에 주목해야 하는데, LocalContainerEntityManagerFactoryBean은 ddl-auto 설정이 되지 않는 프로젝트에서 EntityManagerFactory를 직접 bean으로 등록하는 메서드의 리턴값이다.
@ConditionalOnMissingBean은 뒤에 적혀있는 bean이 존재하지 않는 경우에만 해당 메서드가 실행되도록 하는 어노테이션이다.
따라서 우리 프로젝트에서는 해당 bean이 이미 존재하고 있어 ddl-auto를 포함한 HibernateProperties의 모든 값이 적용되지 않고 있었던 것이다.
해결
ddl-auto 설정이 세팅되어 있는 HibernateProperties를 파라미터로 받아 JpaProperties의 properties에 추가해주었다.
.yml의 설정을 직접 가져와 세팅하는 방법도 고려해 보았지만, 자동으로 @ConfigurationProperties를 통해 세팅되어 있는 값을 사용하지 않을 이유가 없다고 판단했다.
느낀점
로그를 열심히 보려고 노력은 했지만 글을 정리하면서 다시 로그를 보니 당시에 놓쳤던 부분들이 꽤 많이 보였다.
로그를 보는게 중요하다는 사실은 알았지만 로그를 통해 어떤 정보를 얻을 수 있고, 어디서부터 살펴보는게 도움이 되는지에 대한 감이 없었다.
또 코드 분석을 처음 할때는 꽤나 삽질을 했다. 디버깅을 잘하는 사람들은 디버그를 잘 활용하던데 그 점을 놓쳤다.
그래서 처음에 로그를 통해 알게된 AbstractSchemaValidator.validateTable()부터 시작해서
hibernate에서ddl-auto설정을 읽어오는 부분- 메타 정보를 이용해 스키마를 검증하는 부분
이렇게 두 부분에 대한 구현 흐름을 코드로 따라가며 살펴보았다.
구현체에 대해 자세히 알고 있다는게 큰 장점이 될 수 있는지 아직 삐약이 개발자인 나는 잘 모르지만 그래도 흐름이 익숙해지고 나니 디버깅 하기도 편했다.
이번 트러블슈팅을 하면서 글에서도 조금씩 적혀있듯 “디버깅을 잘하는 사람은 어떻게 하더라?” 라는 생각을 가지고 많이 따라해봤다.
아직 미숙하지만 이번 트러블 슈팅을 통해 내가 터득한 방식은 다음과 같다.
로그 잘 활용하기
- 로그를 통해 어떤 부분에서 문제가 발생했는지 살펴보기
- 어떤 흐름의 어떤 상황에서 문제가 발생했을지 유추해보기
디버그 잘 활용하기
- 눈에 보이는 코드 흐름을 믿지 말고 정확히 내가 생각한 지점에서 기대한 동작을 하는지 확인해보기
- 인텔리제이 디버그 기능 및 단축키 익혀 시간 단축하기
(가르침 출처: 손선생님)
다음에는 이번에 터득한 디버깅 꿀팁을 이용해 문제 해결 시간을 단축시킬 수 있을 것만 같다. :)
+) 이 외에도 디버깅을 잘할 수 있는 방법을 알고 계시다면 댓글로 잔뜩 적어보도록~!