[트러블 슈팅 - 테스트 코드] 테스트 데이터 삽입 시 발생하는 auto_increment 컬럼값 충돌 문제 해결

🌱 들어가기 전

이번 포스팅에서는 테스트 코드를 작성하며 마주친 auto_increment 컬럼값 충돌 문제를 분석하고 해결하는 과정을 살펴보자.

 

포스팅 내용에 대한 자세한 코드는 Github에 올려두었습니다.

https://github.com/benjaminuj/test-code-with-architecture/tree/main

GitHub - benjaminuj/test-code-with-architecture: 아키텍처에 진화를 주는 테스트 코드에 대해 공부 및 실습

---

🌱 문제

💭 요약

미리 필요한 테스트 데이터를 쿼리로 세팅한 후 테스트 함수에서 객체가 DB에 잘 저장되는지 확인하는 테스트 과정에서, auto increment로 설정된 기본키 컬럼값 충돌 문제가 발생했다.

 

💭 문제 상황

<UserServiceTest>

(문제가 발생한 코드만 작성합니다. 전체 코드는 위의 Github를 참고해주세요.)

@SpringBootTest
@TestPropertySource("classpath:test-application.properties")
@Sql(value = "/sql/user-service-test-data.sql")
@Transactional
public class UserServiceTest {
    @Autowired
    private UserService userService;
    
    @MockBean
    private JavaMailSender mailSender;

    // ...
    
    @Test
    void userCreateDto를_이용하여_유저를_생성할_수_있다() {
        //given
        UserCreateDto userCreateDto = UserCreateDto.builder()
                .email("meme@kakao.com")
                .address("Gyeongi")
                .nickname("meme-k")
                .build();
        BDDMockito.doNothing().when(mailSender).send(any(SimpleMailMessage.class));

        //when
        UserEntity result = userService.create(userCreateDto);

        //then
        assertThat(result.getId()).isNotNull();
        assertThat(result.getStatus()).isEqualTo(UserStatus.PENDING);
    }
    
    // ...
}

 

<UserService>

(문제가 발생한 코드만 작성합니다. 전체 코드는 위의 Github를 참고해주세요.)

@Service
@RequiredArgsConstructor
public class UserService {

    // ...
    
    @Transactional
    public UserEntity create(UserCreateDto userCreateDto) {
        UserEntity userEntity = new UserEntity();
        userEntity.setEmail(userCreateDto.getEmail());
        userEntity.setNickname(userCreateDto.getNickname());
        userEntity.setAddress(userCreateDto.getAddress());
        userEntity.setStatus(UserStatus.PENDING);
        userEntity.setCertificationCode(UUID.randomUUID().toString());
        userEntity = userRepository.save(userEntity);
        String certificationUrl = generateCertificationUrl(userEntity);
        sendCertificationEmail(userCreateDto.getEmail(), certificationUrl);
        return userEntity;
    }
    
    // ...
}

 

<user-service-test-data.sql>

UserServiceTest에 @Sql로 설정한 sql파일

insert into `users` (`id`, `email`, `nickname`, `address`, `certification_code`, `status`, `last_login_at`)
values (1, 'meme@naver.com', 'meme', 'Seoul', 'aaaaaaaa-aaaa-aaaa-aaaa-aaaaaaaaaaaa', 'ACTIVE', 0);

insert into `users` (`id`, `email`, `nickname`, `address`, `certification_code`, `status`, `last_login_at`)
values (2, 'mymy@naver.com', 'mymy', 'Seoul', 'aaaaaaaa-aaaa-aaaa-aaaa-aaaaaaaaaaab', 'PENDING', 0);

 

해당 테스트를 돌리면, 모두 성공할거라는 예상과 달리 아래의 결과가 나온다.

UserServiceTest 실행 결과

 

🌱  문제 원인 분석 

UserServiceTest 실행시, 실패한 메소드의 예외 로그

 

로그를 보니, id(기본키)값이 1인 데이터가 중복 저장되려고하면서 테스트에 실패한 것으로 파악된다.

 

UserServiceTest 실행시, 실패한 메소드의 예외 로그

예외 발생 위치는 create() 내부다.

💭 의문점

처음에 예외 로그를 보고는, 작성해둔 sql 파일의 첫 번째 쿼리인 'values (1, 'meme@naver.com', 'meme', 'Seoul', 'aaaaaaaa-aaaa-aaaa-aaaa-aaaaaaaaaaaa', 'ACTIVE', 0);'를 insert하려는 쿼리 실행에 실패한 것으로 해석했다.

 

그리고 의문이 들었다.

@Sql로 설정한 sql 파일의 쿼리 실행 실패가, 왜 함수 시작 전이 아닌 함수 구현부 중간의 create() 내부에서 발생한걸까?

 

💭 문제 분석

앞 의문점에 대해 가능한 두 가지 시나리오를 생각했다.

 

1. sql 파일에 작성한 쿼리가 함수 시작 전에 한 번만 실행된게 아니라, 두 번 이상 실행된다.

정상적으로는 기본 @Sql로 설정한 sql파일은 모든 함수 시작 전에만 실행된다.

그런데 만약, 문제가 발생한 함수에서는 내부 어떤 과정으로 인해 꼬여서 sql파일이 두 번 실행된거라면, sql파일이 두  번째로 실행되는 과정에서는 이미 해당 데이터가 DB에 있기때문에 기본키 충돌이 발생 할 것이다.

 

문제가 발생한 테스트 코드는 복잡성이 낮기 때문에, 이 경우의 수처럼 상황이 꼬일 확률은 낮다고 생각했다. 

그렇지만, 확실히하기 위해 로그를 찍어 직접 확인해봤다.

 

우선 해당 내용과 관련하여 Spring 공식 문서를 찾아보았다.

Spring 공식 문서 - @Sql을 사용한 sql 실행

참고) https://docs.spring.io/spring-framework/reference/testing/testcontext-framework/executing-sql.html

@Sql은 SqlScriptsTestExecutionListener를 통해 제공된다고 한다.

 

 

테스트를 실행할 때 로그를 찍어서, @Sql 을 동작시키는 리스너인 SqlScriptsTestExecutionListener가 언제 찍히는지 확인해보았다. 문제가 발생한 테스트 함수에서는 SqlScriptsTestExecutionListener가 한 번만 찍히는 것을 확인했다. 

그 뜻은, @Sql로 설정한 sql 파일의 모든 쿼리들은 역시 단 한번 실행되며, 그 시점은 함수 시작 전이다. 따라서 이 경우의 수는 아닌 것 같다.

 

2. 테스트 함수 내에서 생성한 UserEntity객체를 DB에 save()하는 과정에서 발생한 예외이다. 즉, sql 파일의 쿼리 실행 실패와는 관련 없다.

로그 분석

이 경우의 수를 생각하기 위해서는 먼저 해결해야 할 의문점이 있다.

 

- 로그는 왜 sql 파일의 첫 번째 쿼리인 'values (1, 'meme@naver.com', 'meme', 'Seoul', 'aaaaaaaa-aaaa-aaaa-aaaa-aaaaaaaaaaaa', 'ACTIVE', 0);'와 관련하여서 찍혔을까?

현재 문제 상황의 로그

 

이 내용을 파다 보니 위의 로그 이미지에서 줄 친 부분은, 저 데이터를 넣으려는 쿼리를 날릴 때 발생한 문제라는 의미가 아니고, 충돌난 데이터(key값이 1번인 데이터)를 가져와서 보여준 것임을 알게되었다.

 

+ 참고) 실제로 해당 문제 상황에서 사용된 sql파일과 동일한 파일의 쿼리 실행 실패시 찍히는 로그는 아래와 같다.

sql파일에 작성된 쿼리 실행에 실패한 로그

sql파일의 쿼리를 실행시키다가 난 에러는 sql파일에 작성된 쿼리가 그대로 로그로 찍히는 것을 알 수 있다.

 

이번 문제 상황에서 찍힌 로그와 비교해보자. 

아래의 현재 문제 상황에서 찍힌 로그의 insert문을 보면, values에 값이 설정되지 않았다. 특히 id값이 default로 들어가고 있다. 이는 id값을 1로 직접 설정한 sql 파일의 쿼리와 달리, 내부적으로 쿼리가 생성되어 DB로 날아가는 것임을 알 수 있다. 즉, 테스트 함수에서 생성한 객체를 save()할 때 날아간 쿼리일 것이다.

현재 문제 상황의 로그

 

예외 발생 시점 파악

어디까지 정상적으로 실행되고, 언제 예외가 발생하는건지 직접 로그도 찍어보자.

 

<UserServiceTest>

로그를 찍어보기 위해, 해당 함수에 아래처럼 출력문을 추가했다.

    @Test
    void userCreateDto를_이용하여_유저를_생성할_수_있다() {
    	// log
        System.out.println("start******************************");
        List<UserEntity> data = userRepository.findAll();
        System.out.println("userCreateDto를_이용하여_유저를_생성할_수_있다 -> start data size : "  + data.size());

        //given
        UserCreateDto userCreateDto = UserCreateDto.builder()
                .email("meme@kakao.com")
                .address("Gyeongi")
                .nickname("meme-k")
                .build();
        BDDMockito.doNothing().when(mailSender).send(any(SimpleMailMessage.class));
        System.out.println("dto set!!******************************");

        //when
        UserEntity result = userService.create(userCreateDto);

        System.out.println("created!!******************************");

        //then
        assertThat(result.getId()).isNotNull();
        assertThat(result.getStatus()).isEqualTo(UserStatus.PENDING);
    }

 

<UserService>

    @Transactional
    public UserEntity create(UserCreateDto userCreateDto) {
        UserEntity userEntity = new UserEntity();
        System.out.println("create in**************");
        userEntity.setEmail(userCreateDto.getEmail());
        userEntity.setNickname(userCreateDto.getNickname());
        userEntity.setAddress(userCreateDto.getAddress());
        userEntity.setStatus(UserStatus.PENDING);
        userEntity.setCertificationCode(UUID.randomUUID().toString());
        System.out.println("before save()************");
        userEntity = userRepository.save(userEntity);
        System.out.println("end save()*************");
        String certificationUrl = generateCertificationUrl(userEntity);
        sendCertificationEmail(userCreateDto.getEmail(), certificationUrl);
        return userEntity;
    }

 

테스트 결과 로그는 아래와 같다.

UserServiceTest 테스트 결과, 'userCreateDto를_이용하여_유저를_생성할_수_있다()' 의 로그

 

'before save()************'까지는 정상적으로 찍히고 이후에 예외로그가 찍힌다.

즉, create() 함수 내부의 `userRepository.save(userEntity);` 를 하는 과정에 예외가 발생한 것임을 알 수 있다. 

 

사실, 영속성 컨텍스트에서 객체를 관리하기 위해서는 무조건 PK 값이 있어야하기 때문에 원래는 트랜잭션이 끝나는 COMMIT 시점 전에 모든 쿼리가 flush된다. 그러니까 이 말대로라면, save()이후 로그가 다 출력되고 함수가 끝날 때 예외가 발생해야한다.

 

그런데 왜 save()에서 예외가 발생했을까? 기본키 생성전략 때문이다.

 

<UserEntity>

@Entity
@Table(name = "users")
public class UserEntity {

    @Id
    @GeneratedValue(strategy = GenerationType.IDENTITY)
    private Long id;
    
    // ...
}

UserEntity는 기본키 생성 전략을 IDENTITY로 하고있기 때문에, save()를 호출하는 시점에 flush가 이루어진다. 따라서 이 때 예외가 발생한 것이다.

 

공식문서 조사

- 문제 시나리오: @Sql에 작성한 id값이 1과 2인 두 개의 insert문이 정상적으로 실행되어 데이터가 들어가 있는 상태인데, 해당 함수에서 객체를 save()할 때 id값이 1로 들어가려해서 기본키 충돌이 발생한다.

 

위 시나리오대로라면, auto increment로 설정된 id값을 직접 지정한 쿼리를 insert한 것은 auto increment 값에 반영되지 않았다는 말이다.

 

프로덕션 코드에서는 MySQL을 사용하기 때문에, 이와 관련해 MySQL 공식문서를 찾아본다.

MySQL 공식문서

참고) https://dev.mysql.com/doc/refman/8.4/en/innodb-auto-increment-handling.html

 

MySQL에서는 auto increment 컬럼에 특정 값을 직접 지정한 경우, 그 값이 counter값 보다 크면 counter이 업데이트 된다고 한다.

이 말대로라면, auto increment로 관리하는 id 컬럼의 값을 1과 2로 직접 지정해서 insert했을 때에 counter값이 업데이트되어야 한다. 그리고 이후 객체를 save()하면 자동적으로 id값이 3을 배정받아야 한다.

 

하지만 이렇게되지 않고 문제가 발생했다. 왜일까? 

H2 공식문서에서는 관련 내용을 찾을 수 없었지만 H2에 관한 여러 이슈들을 공유하는 글을 많이 보았다. 결론적으로는 H2 데이터베이스에서 MySQL 모드를 사용할 때 특정 동작이 MySQL과 동일하게 작동하지 않을 수도 있다는 것이다. 

 

실험

이 시나리오가 맞는지 실험을 해보자.

 

@Sql에 작성한 수동 쿼리의 id값을 1이 아닌 다른 값으로 바꿔보자. H2에서는 auto increment 컬럼에 특정 값을 지정하여 수동 쿼리를 날릴 시 counter가 업데이트 되지 않아서 함수 내 객체 save()는 id값 1부터 지정하려고 할 것이다. 따라서 직접 지정한 id 값이 1이 아니고, 이 시나리오가 맞다면 테스트가 성공할 것이다.

수동 쿼리 id값 수정

id값 수정한 후 실행 결과

 

이렇게 테스트 성공한 것을 보니, 확실히 H2에서 수동 쿼리는 auto increment에 반영 되지 못한 것을 알 수 있다.

 

💭 문제 원인

H2에서 auto increment 컬럼에 특정 값을 지정하여 insert 쿼리를 날리면, auto_increment 컬럼 값이 정상적으로 갱신되지 않는다.

 

🌱 문제 해결

💭 해결 방법 모색

여러 방법이 있다.

 

1. 문제 함수에서는 클래스 레벨에서 적용된 데이터 삽입이 필요없기 때문에, 함수 실행 전에 모든 데이터를 삭제한다.

 

<UserServiceTest>

    @Test
    @Sql(value = "/sql/delete-all-data.sql", executionPhase = ExecutionPhase.BEFORE_TEST_METHOD) // 문제 해결!
    void userCreateDto를_이용하여_유저를_생성할_수_있다() {
        // ...
    }

 

<delete-all-data.sql>

delete from `users` where 1;

 

 

2. 직접 auto increment 컬럼 값을 업데이트한다.

 

<user-service-test-data.sql>

insert into `users` (`id`, `email`, `nickname`, `address`, `certification_code`, `status`, `last_login_at`)
values (1, 'meme@naver.com', 'meme', 'Seoul', 'aaaaaaaa-aaaa-aaaa-aaaa-aaaaaaaaaaaa', 'ACTIVE', 0);

insert into `users` (`id`, `email`, `nickname`, `address`, `certification_code`, `status`, `last_login_at`)
values (2, 'mymy@naver.com', 'mymy', 'Seoul', 'aaaaaaaa-aaaa-aaaa-aaaa-aaaaaaaaaaab', 'PENDING', 0);

ALTER TABLE users ALTER COLUMN id RESTART WITH 3; -- 문제해결!

 

💭 해결

두 방법 모두 문제 함수의 특성에서 벗어나지 않는 해결 방법이다. 

 

그렇지만, 모든 테스트 함수를 고려했을 때 auto increment 값이 업데이트 되지 않은 것은 추후 다른 문제를 불러올 수 있다.

따라서 더 근본적인 해결을 위해, 직접 auto increment 컬럼 값을 업데이트 하는 방식을 선택했다.

 

문제 해결 후 실행 결과