로그 추적기, Flyway, RestAssured, Jacoco 도입

이번 프로젝트를 시작하기 전 백엔드 팀원들과 회의를 하면서 로그 추적기, Flyway, RestAssured를 도입하기로 결정하고 시작했었다.

프로젝트를 마무리한 시점에 각 도구를 왜 사용하는지, 실제로 사용해보면서 어떤 장점을 가질 수 있는지 정리해보고자 한다.

로그 추적기

이전 프로젝트를 진행했을 때 필요한 로그를 직접 하나하나 작성했었다.

  
log.info("어떤 메서드.. param={}", userId);

로그를 직접 작성했을 때 물론 큰 문제는 없다. 조금 귀찮고 가끔 매개변수 정보를 제대로 넣지 않는 문제 정도가 있었다.

그리고 여러 팀원들이 함께하는 작업이다보니 어떤 팀원의 코드에는 로그가 상세하게 작성되어있고, 어떤 팀원의 코드에는 로그가 조금씩 누락된 부분들이 보였다.

코드리뷰로 이런 부분을 모두 잡기에도 시간이 한정적이었기 때문에 이번 프로젝트에서는 이런 부분들을 보완하고 싶었다.

그래서 AOP를 활용해 로그 추적기를 도입하고 프로젝트를 시작해보고자 했고, 도입하게 되었다.

구현

  
@Aspect
@Component
@Slf4j
public class TraceAspect {

    private final TraceLogger traceLogger;

    public TraceAspect(TraceLogger traceLogger) {
        this.traceLogger = traceLogger;
    }

    private static final ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>();

    @Pointcut("execution(* com.dangdangsalon.domain..controller..*(..)) || " +
            "execution(* com.dangdangsalon.domain..service..*(..)) || " +
            "execution(* com.dangdangsalon.domain..repository..*(..))")
    private void applicationPackagePointcut() {}

    @Around("applicationPackagePointcut()")
    public Object logExecution(ProceedingJoinPoint joinPoint) throws Throwable {
        TraceId traceId = traceIdHolder.get();
        TraceStatus status = null;

        try {
            String methodName = joinPoint.getSignature().toShortString();
            Object[] args = joinPoint.getArgs();
            String argsString = Arrays.toString(args);

            traceId = (traceId == null) ? new TraceId() : traceId.createNextId();
            traceIdHolder.set(traceId);

            status = traceLogger.begin(traceId, methodName + " with args: " + argsString);

            Object result = joinPoint.proceed();

            traceLogger.end(status);
            return result;

        } catch (Exception e) {
            if (status != null) {
                traceLogger.exception(status, e);
            }

            throw e;
        } finally {
            TraceId currentTraceId = traceIdHolder.get();
            if (currentTraceId != null && currentTraceId.isFirstLevel()) {
                traceIdHolder.remove();
            } else {
                traceIdHolder.set(currentTraceId.createPreviousId());
            }
        }
    }
}

AOP를 활용해 메서드 실행의 시작, 종료, 예외 상황을 로깅하는 역할을 담당한다.
@Aspect
- 이 클래스가 AOP의 핵심 역할을 수행함을 알린다.
ThreadLocal
- 메서드 실행의 고유 식별자인 TraceId를 쓰레드별로 독립적으로 관리한다.
- 동일한 요청 내에서 메서드 호출 계층 구조를 유지할 수 있도록 한다.
@Pointcut
- controller, service, repository 하위에 속한 모든 메서드를 대상으로 동작한다.

이 외 TraceId, TraceLogger, TraceStatus는 로그 형식에 관한 클래스들이다. 원하는 로그 형식으로 작성해주면 된다.

이렇게 했을 때 아래와 같은 결과를 얻을 수 있다.

로그인했을 때 나타나는 로그이다.

더 깊은 구조일 때 어떤 메서드가 실행되는지, 각 메서드가 실행될 때 어떤 매개변수가 사용되고 실행 시간은 어느정도인지 바로 확인할 수 있어서 문제를 파악하기 용이했다.

특히 예외가 발생했을 때 어떤 매개변수가 잘못들어갔는지, 어떤 메서드에서 잘못 들어갔는지 계층별로 한 눈에 파악할 수 있어서 편리했다.

장점

반복 코드 제거
- 따로 작성해주지 않아도 모든 메서드에 일관된 로그를 남길 수 있다. 필요한 로그가 따로 있다면 그 때 따로 작성할 수도 있다.
- 코드가 간결해지고, 팀원끼리 로그 구조가 다르지 않다.
트랜잭션 흐름 추적
- 계층 정보와 TraceId가 모두 포함된 로그이기 때문에 API 호출에 있어 전체 흐름을 파악하기 용이하다.
예외 상황 로깅
- 예외가 발생했을 때 로그를 통해 예외가 발생한 메서드와 호출 계층을 쉽게 알 수 있다.

아쉬운 점

대부분 다 좋았는데, 이 방식으로 구현했을 때 불편한 부분이 있다.

예외가 나타났을 때 예외가 여러 번 기록된다.

이유는 AOP의 @Around는 메서드 호출 전후와 예외 상황을 감싸는 구조를 가진다.

그런데 예외 발생 시 AOP 로직에서 한 번, 이후 호출 스택에서 또 예외가 기록된다.

AOP에서 예외를 감싸 처리한 후 throw e로 예외를 다시 던져주고 있는데 이 던져진 예외가 호출 스택의 상위 다른 로직에서도 처리되고 로그 기록이 남게 되는 것이다.

그렇다고 예외를 던져주지 않으면 AOP에서 예외가 발생한 시점에 실행 흐름이 중단되어 예외 로직이 정상적으로 동작하지 않아 문제가 생긴다.

그렇다고 AOP에서 예외를 처리해버린다면 그 또한 구조가 이상하다.

이 부분을 해결하고 사용했다면 더 좋았을 것이라는 아쉬움이 있다.

개선점

현재 거의 모든 메서드 호출을 AOP로 감싸 로그를 작성했는데 트래픽이 높은 경우 성능 저하의 원인이 될 수 있다고 한다.

따라서 꼭 디버깅이 필요한 부분에만 AOP 적용 범위를 설정하거나 빈번하게 호출되는 메서드의 경우에는 위와 같은 상세한 로그가 아닌, 간단하게 요약되어있는 로그를 남기는 방식으로 처리해볼 수 있을 것 같다.

Flyway

학습과 경험의 목적이 가장 큰 프로젝트인 만큼 여러 도구들을 도입해보고 싶었다.

Flyway는 데이터베이스 마이그레이션 / 버전관리 도구이다. 데이터베이스 스키마 변경이나 데이터 초기화를 스크립트로 저장해두면 실행 시 자동화 된다.

물론 JPA를 활용했을 때 그런 부분이 충족되지만 그 기록이 남지 않는다.

따라서 JPA는 create-drop이나 update 설정 대신 validation 설정으로 바꾸고 스키마 관리는 Flyway를 이용하게 되었다.

사용 방법

마이그레이션 파일 작성
- 데이터베이스 변경 내용을 담은 sql 파일을 작성한다.
- V1__Create_User_table.sql 과 같은 형식으로 파일명을 지정해야 한다.
- V2, V3과 같이 버전을 업데이트 해나갈 수 있다.
- Flyway는 이 파일들을 실행해 데이터베이스 버전을 업데이트한다.
- src/main/resources/db/migration/ 디렉토리에 파일을 두면 된다.
Metadata Table
- Flyway는 데이터베이스에 자체적으로 관리 테이블을 생성한다. (flyway_schema_history)
- 이 테이블에는 실행된 마이그레이션 파일의 정보를 저장하는데, 마이그레이션 중간에 문제가 생겼을 때 이 부분들을 초기화해주어야 한다.

장점

버전 관리
- 테이블의 변경 기록이 모두 남아있기 때문에 이 부분을 왜 변경했었는지 알 수 있었다.
- JPA의 update를 활용했을 때는 내가 왜 이렇게 바꿨었는지, 아니면 팀원이 왜 이렇게 바꿨는지에 대한 부분을 서로 소통하고 기억해내야 했었는데 이런 부분들을 같이 파일을 보고 바로 파악 후 필요에 따라 정정할 수 있었다.
배포 후 마이그레이션 용이
- 어떤 테이블을 이미 생성했고, 그 테이블 구조에 맞추어 데이터도 많이 추가된 상태일 때 어떤 필드를 추가하거나 제거해야 하는 상황을 가정해보자.
- 직접 MySQL 서버에서 추가해줘야 하는 경우가 있다.
- 물론 JPA를 활용한 DDL 자동 생성도 가능하겠지만, 정밀하게 제어할 수 없어 어떤 경우에는 문제가 생길 수 있다.
- 하지만 Flyway를 활용하면 SQL 파일을 직접 작성하기 때문에 명시적으로 관리하고 안전하게 업데이트가 가능해진다.
더미데이터 관리 가능
- 단순히 테이블 구조의 변경 뿐 아니라 더미데이터의 삽입도 파일로 따로 관리할 수 있다.
- 물론 디렉토리 구조 및 일부 설정이 필요하다.

여기에 더해 유료버전은 롤백까지 지원해주어 안정적으로 DB의 버전 관리를 할 수 있다고 한다.

불편했던 점

팀원들이 동시에 마이그레이션 파일을 생성하는 경우가 있었다.
- 버전명이 같아 합칠 때 문제가 생긴 경우도 있었다.
- 작성 전 충분히 소통 후 진행하더라도 V2를 작성한 팀원이 있어 V3으로 작업을 했는데 V3으로 작업한 팀원이 작업을 일찍 끝냈을 경우 V2가 누락되어 있어 바로 병합해볼 수 없는 문제가 생기기도 했다.
- DB 설계를 처음부터 신중하게 하고, 팀원들과 지속적인 소통으로 보완할 수 있다.
모두 Flyway 사용이 처음이다보니 개발 단계에서 단순하게 어떤 테이블의 필드 하나를 변경할 때의 버전관리가 애매했다.
- 처음 테이블을 생성했던 파일에서 해당 필드를 수정해주어야 할지, 아니면 버전을 하나 생성해서 필드를 변경해야 할지 고민이 됐다.
- 우리는 단순한 변경이라 버전이 너무 많이 생기는 것을 방지하고자 기존 테이블 생성 파일에서 변경했었다.
- 하지만 이렇게 진행했을 때 테이블을 초기화해야 하는 번거로움이 생겼다.
- 물론 배포환경에 개발을 진행을 시작하고서는 무조건 버전을 새롭게 만들고 진행해서 이 부분의 불편함은 장점으로 바뀌기도 했다.

장점과 함께 불편한 점도 있었는데 이런 부분들을 보완하려면 규칙을 엄격하게 정할 필요가 있겠다는 생각을 하게 됐다.

RestAssured

RestAssured는 Java 기반 REST API 테스트 라이브러리이다.

물론 기존에 Controller, Service, Repository 테스트를 작성해 각 계층에서 발생하는 문제를 확인할 수 있었지만 RestAssured를 사용하면 확실한 End-To-End 테스트를 작성할 수 있다.

예시

  
@SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT)
@ActiveProfiles("test")
@AutoConfigureMockMvc
public class ChatApiTest {

    @LocalServerPort
    private int port;

    @Autowired
    private MockMvc mockMvc;

    @MockBean
    private ChatRoomService chatRoomService;

    @MockBean
    private ChatMessageService chatMessageService;

    @MockBean
    private JwtUtil jwtUtil;

    @BeforeEach
    void setup() {
        RestAssured.port = port;
        RestAssuredMockMvc.mockMvc(mockMvc);

        given(jwtUtil.isExpired(anyString())).willReturn(false);
        given(jwtUtil.getUserId(anyString())).willReturn(1L);
        given(jwtUtil.getUsername(anyString())).willReturn("testUser");
        given(jwtUtil.getRole(anyString())).willReturn("ROLE_USER");
    }

    @Test
    @DisplayName("채팅방 생성 요청 성공 테스트")
    void createChatRoomTest() {
        CreateChatRoomRequestDto requestDto = new CreateChatRoomRequestDto(1L);

        RestAssuredMockMvc
                .given()
                .contentType(ContentType.JSON)
                .body(requestDto)
                .cookie("Authorization", "mock.jwt.token")
                .when()
                .post("/api/chatrooms")
                .then()
                .statusCode(HttpStatus.OK.value());
    }
	//...
}

컨트롤러 테스트와 비교해 간결한 메서드 체인을 활용하여 HTTP 요청을 구성하고 응답 검증이 가능하다.

장점

사실 큰 장점을 느끼지 못했다. 하지만 딱 하나가 있는데 직렬화/역직렬화 문제를 잡아냈다는 점이다.

Controller 테스트와 구조가 비슷하고 역할도 비슷해보인다. 하지만 RestAssured는 확실한 End-To-End 테스트를 할 수 있다.

Controller 테스트는 DispatcherServlet을 활용한 요청-응답 흐름을 검증하는데 초점이 맞춰져 있다.

하지만 실제 HTTP 요청을 시뮬레이션하지 않기 때문에 직렬화/역직렬화 문제를 잡아내는데에는 한계가 있다.

RestAssured는 실제 HTTP 요청과 응답을 기반으로 End-To-End 테스트를 수행하기 때문에 클라이언트와 서버 간의 데이터 변환 과정에서 발생할 수 있는 문제를 잡아낼 수 있다.

실제로 채팅에 관한 테스트를 작성할 때 DTO 구조가 바뀌면서 Java LocalDateTime 타입의 직렬화 문제가 생겼고, 그 직렬화 문제를 해결하고자 JacksonConfig 클래스를 만들었다.

이 클래스를 만들면서 다른 직렬화 부분에서 예상치 못한 문제가 생겼었는데 인지하지 못하고 있다가 테스트 코드를 전체로 돌려보면서 알게 되었고 이는 RestAssured 라이브러리를 활용한 테스트 코드에서만 잡아낼 수 있었다.

정리

이렇게 Controller, Repository, Service, RestAssured 테스트 코드를 작성하다보니 테스트 코드 메서드 개수가 500개 가까이 됐었다.

학습의 목적도 있기 때문에 좋은 경험이었다고 생각이 든다. 하지만 Controller 테스트 코드와 RestAssured 테스트 코드를 둘 다 작성해야 하느냐에 대한 고민이 들었다.

물론 다르다는 점도 알고, 실제로 RestAssured 테스트 코드에서만 잡아낸 문제도 있었다. 하지만 중복된 영역이 많아 보인다. 테스트 코드를 작성하는 것도 일종의 비용이고 효율성이 떨어진다는 느낌을 지울 수 없었다.

그래서 두 테스트 방식 중 하나를 선택하거나 역할을 확실히 구분해야 의미가 있겠다는 생각이 들었다.

만약 둘 다 작성해야 한다면 이번 프로젝트처럼 모든 부분에 전부 작성하는 것이 아닌, 간단한 흐름 검증은 Controller 테스트만 작성하고, 클라이언트와 서버 간 데이터 변환 검증이나 실제 환경과 비슷한 테스트가 필요한 경우 Controller 테스트를 생략하고 RestAssured를 사용하는 방식으로 구현하는게 효율적일 것 같다.

Jacoco

Jacoco는 테스트 코드 커버리지를 체크하고 제한을 둘 수 있는 도구이다.

우리는 라인 커버리지 70%, 브랜치 커버리지 70% 정도를 목표로 삼고 했었다. 멘토링을 받았을 때 이 이상의 수치로 잡았을 때 테스트만을 위한 테스트가 될 수 있다고 조언을 받았기 때문이다.

꼭 높게 잡을 필요는 없다고 하셨지만 학습 과정이기 때문에 한 번쯤 높게 잡아보는 것도 좋다고 하셔서 70%를 목표로 삼았다.

결과적으로 라인 커버리지는 넉넉하게 달성할 수 있었다. 하지만 문제는 브랜치 커버리지다.

개발 중 프론트 서버와 합치는 과정에서 사소한 버그들이 많이 발견되었는데 프로젝트 기간이 빡빡했기 때문에 이 과정에서 버그를 고칠 때 단순 분기처리가 많아졌다.

단순 분기처리가 많아지다보니 해당 분기처리에 대한 테스트가 꼼꼼히 진행될 수 없었고 브랜치 커버리지가 50% 아래로 떨어지게 된 것이다.

프로젝트를 마무리하고 보여줘야 했기 때문에 Jacoco 커버리지를 조정할 수 밖에 없었고 이 부분이 조금 아쉽긴 했다.

하지만 Jacoco를 도입해보면서 테스트 코드의 중요성을 느낄 수 있었다. 코드의 테스트 범위를 객관적으로 파악하고 코드 품질을 개선하는 부분에 어느정도 강제성을 둘 수 있다는 점이 좋았다.

특히 브랜치 커버리지가 낮았던 경험을 통해 단순 분기 처리와 같은 부분도 테스트가 충분히 이루어져야 한다는 점을 깨달을 수 있었다. 이렇게 누락된 부분은 실제 운영 환경에서 예상치 못한 버그를 낼 수 있을 것 같다.

이번에 Jacoco를 도입해보면서 테스트 커버리지는 수치를 무작정 높이기보다 프로젝트의 요구사항과 일정에 맞추어 효율적으로 전략을 짜야겠다는 생각이 들었다.

로그 추적기, Flyway, RestAssured, Jacoco 도입