Post

ElementCollection에서 발생한 버그

문제 상황

먼저 Article 엔티티 클래스는 다음과 같이 태그를 포함하고 있다.

1
2
3
4
@ElementCollection
@CollectionTable(name = "article_tags", joinColumns = @JoinColumn(name = "article_id"))  
@Column(name = "name")  
private List<String> tags;

@ElementCollection은 기본 fetch 전략이 LAZY이다.

해당 아티클을 조회하는 E2E 테스트를 수행하던 중 에러가 발생했다. 원인은 HTTP 응답이 다음과 같이 깨져 나오는 것이었다.

1
2
3
4
5
6
7
8
9
10
11
12
13
{
    "article": {
        "slug": "title-2913e1",
        "title": "title",
        "description": "desc",
        "body": "body",
        "tagList"
    }
}{
    "errors": {
        "internal": "server error."
    }
}

본래 정상 응답(위 article) 또는 에러 응답(아래) 둘중하나만 출력되어야 하지만, 둘 모두가 출력되는 이상한 상황이었다.

응답의 article 내부를 살펴보면 tagList가 비정상적인 형식을 갖고 있다. 이를 통해 두가지 사실을 유추했다.

  • JSON 매퍼가 동작하는 중에 문제가 발생했다.
  • 문제의 원인은 tagList와 연관이 있다.

한가지 특이한 사항으론, 디버깅 중에 특정 객체를 탐색하면 에러가 발생하지 않는 점이 있었다. (예를들어 아래의 코드에 브레이킹 포인트를 찍으면 에러가 발생하지 않았다.) 버그를 고치기 위해 디버깅을 하는데 디버깅을 하면 버그가 발생하지 않는다니… 당황스러웠다.

1
2
3
4
5
6
@Transactional(readOnly = true)
public ArticleResponse getArticle(Long loginId, Long articleId) {  
    final ArticleView articleView = articleQueryRepository.findById(loginId, articleId)  
        .orElseThrow(ArticleNotFoundException::new);  
    return ArticleResponse.of(articleView);  
}

ArticleView는 아티클을 조회하기 위한 모델로 Querydsl을 사용한다. 또, ArticleResponse.of() 내부에선 응답을 만들기 위해 여러 값을 설정한다. 이 과정에 태그 리스트를 설정하기 위해 this.tagList = articleView.getTagList()가 포함된다.

테스트 로그만으론 원인을 찾을 수 없어, 서버를 띄우고 테스트와 동일한 요청을 직접 보냈다. 마찬가지로 같은 문제가 발생하였고, 콘솔의 DEBUG 로그를 탐색하던 중 아래와 같은 메시지를 발견하였다.

1
2023-09-22T00:32:05.194+09:00 DEBUG 11400 --- [nio-8080-exec-3] .m.m.a.ExceptionHandlerExceptionResolver : Resolved [org.springframework.http.converter.HttpMessageNotWritableException: Could not write JSON: failed to lazily initialize a collection of role: real.world.domain.article.entity.Article.tags: could not initialize proxy - no Session]

중간에 잘 살펴보면 failed to lazily initialize라는 문구가 보인다. 현재 서버 설정 상 OSIV가 false이며 LAZY 전략을 사용하고 있으나, @Transactional가 붙어있는 메서드 안에서 ArticleResponse.of()를 통해 응답을 미리 만들었으므로 이해가 되지 않는 상황이었다.

원인

고민을 하던중 불현듯 this.tagList = articleView.getTagList() 코드가 눈에 들어왔다.

articleView에선 this.tagList = article.getTags()를 통해 값을 설정하고 있으니 결과적으론 articleResponse.tagList == article.getTags()인 셈이다. 여기서 tagsList 객체다. 자바는 원시 자료형이 아닌 모든 타입은 참조를 통해 전달된다.

위에서 살펴보았듯 tags@ElementCollection로 LAZY 전략이 적용되어 있다. 즉, 실제로 tags프록시 객체로 관리되며 실제 값을 사용할 때 쿼리가 나가게 된다.

참고로 tags 객체는 컬렉션이므로 PersistentBag로 처리된다. CGLIB을 이용하는 일반 엔티티의 프록시와 형태가 다를뿐 PersistentBag도 일종의 프록시다.

이러한 사실들을 종합해보면 @Transactional 내에서 ArticleResponse로 값을 전달해주지만, 이때 전달되는 tags는 리스트 내의 값이 아닌 프록시 객체에 대한 참조만 전달된다.

이 상태로 JSON 매퍼가 값을 쓰려고 리스트 내부의 값을 꺼내려는 순간 LazyInitializingException이 발생하는 것이다. tagList.get(n)을 실행하는 순간 쿼리가 나가야 하지만 트랜잭션이 닫혀있어 실제 값을 초기화할 수 없기 때문이다.

디버깅을 거친 뒤엔 버그가 발생하지 않던 이유도 바로 여기에 있다. 디버거는 내부의 값을 확인할 수 있어야 하므로 디버거가 찍는 순간 프록시가 실제 값을 얻기위해 DB에 쿼리를 보내게 된다.

매퍼가 동작하는 과정에 에러가 발생했으므로 응답 body도 저런 이상한 형태가 된다.

실제로 디버거를 통해 확인해보면,

위와 같이 articleResponse.tagListPersistentBag의 참조가 주입되어 있다.

해결 방법

원인을 찾았으니 해결방법은 간단하다. 여러 방법이 있으나 @ElementCollection(fetch = FetchType.EAGER)와 같이 fetch 타입을 변경해주었다. 여러 방법 중 해당 해결책을 택한 이유는 다음과 같다.

일단 태그에 대해 생각해봤는데 태그의 생명 주기는 아티클과 동일하다. 생성, 변경, 삭제가 모두 함께 발생하기 때문이다. 또, 모든 아티클관련 요청은 태그를 포함하고 연관된다. 이런 경우엔 굳이 지연 로딩 전략을 사용할 필요가 없어 EAGER로 설정해도 무방하다고 생각했다.

디버깅 환경에선 발생하지 않는 신기한 버그였다. 디버깅이 불가능한 상황이라 평소에 자바의 특성이나 JPA, 프록시 객체의 성질에 대해 잘 이해하고 있지 못했다면 해결하기 어려웠을 것이다.

역시 도구를 잘 활용하기 위해선 내부 원리도 잘 공부해야 한다.

This post is licensed under CC BY 4.0 by the author.