어떤 부분에서 예외가 발생하는지 로그를 통해 확인하는 것이 점점 중요해지고 있다.
기존에는 개발자가 문제가 되는 부분을 어렵게 찾아 로그를 직접 만들어 남겼다면, 이제는 로그를 미리 남겨 문제가 되는 부분을 쉽게 찾을 수 있다.
📌 주어진 요구사항
- 모든 PUBLIC 메소드의 호출과 응답 정보를 로그로 출력
- 애플리케이션의 흐름을 변경하면 안됨 → 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨.
- 메소드 호출에 걸린 시간 필요
- 정상 흐름과 예외 흐름 구분하기 → 예외 발생시 예외 정보가 남아야 함.
- 메소드 호출의 깊이 표현 필요 (
| |
)- HTTP 요청을 구분
- HTTP 요청 단위로특정 ID
를 남겨 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분 가능해야 함.
- 트랜잭션 ID (DB 트랜잭션 X), 여기서는 하나의 HTTP 요청이 시작해 끝날 때가지를 하나의 트랜잭션이라고 함.(트랜잭션이라는 단어는 문맥에 따라 여러가지 의미로 쓰일 수 있다.)
⚠️ 모니터링 툴을 도입하면 많은 부분을 해결할 수 있지만 지금은 학습이 목적이기 때문에 그렇게 하지 않을 것.
테스트 코드를 작성하기 전까지는 이해가 안 되는 것이 당연하다.
먼저 로그 추적기를 위한 기반 데이터를 가진 TraceId
, TraceStatus
클래스 만들기
TraceId.java
public class TraceId {
private String id;
private int level;
public TraceId() {
this.id = createId();
this.level = 0;
}
private TraceId(String id, int level) {
this.id = id;
this.level = level;
}
private String createId() {
return UUID.randomUUID().toString().substring(0, 8);
// 원래 randomUUID()로 뽑으면 엄청 긺.
// 그래서 toString()을 통해 문자열로 뽑고,
// substring(0, 8)로 앞 8자리만 자르는 과정.
}
public TraceId createNextId() {
return new TraceId(id, level + 1); // id는 똑같고 level만 하나씩 증가하는 로직
}
public TraceId createPreviousId() {
return new TraceId(id, level - 1);
}
public boolean isFirstLevel() { // 첫번째 레벨인지 조금 더 편리하게 판별하기 위한 메소드
return level == 0;
}
public String getId() {
return id;
}
public int getLevel() {
return level;
}
}
TraceId Class
로그 추적기는 트랜잭션 ID와 깊이를 표현하는 방법이 필요하다.
우선 여기서 트랜잭션 ID, 깊이를 표현하는 level을 묶어
TraceId
라는 개념을 생성했다.
TraceId
는 단순히id
(트랜잭션 ID),level
정보를 가짐.➡️ 이런식으로 표현될 것
UUID
TraceId
를 처음 생성하면createId()
를 사용해 UUID를 만들어낸다.그런데 UUID는 너무 길어서 보기 힘드므로 앞 8자리만 사용하기 위해
.substring(0, 8)
를 이용했다.
이렇게 생성된 값을 트랜잭션 ID로 사용한다.
createNextId()
createNextId()
는 다음TraceId
를 만든다.위의 표현 예시를 보면 깊이가 증가해도 트랜잭션 ID는 같다.
따라서
createNextId()
를 사용해 현재TraceId
를 기반으로 다음 아이디를 만들면id
는 기존과 동일,level
은 하나 증가하게 된다.
createPreviousId()
createNextId()
와 반대 역할을 수행한다.
id
는 기존과 동일,level
은 하나 감소하게 된다.
isFirstLevel()
: 첫번째 레벨 여부를 편리하게 확인할 수 있는 메소드
TraceStatus.java
public class TraceStatus {
private TraceId traceId;
private Long startTimeMs;
private String message;
public TraceStatus(TraceId traceId, Long startTimeMs, String message) {
this.traceId = traceId;
this.startTimeMs = startTimeMs;
this.message = message;
}
public TraceId getTraceId() {
return traceId;
}
public Long getStartTimeMs() {
return startTimeMs;
}
public String getMessage() {
return message;
}
}
TraceStatus 클래스
: 로그 상태 정보를 나타냄.
로그를 시작하면 끝도 있어야 한다.
TraceStatus
는 로그를 시작할 때의 상태 정보를 가진다. 이 상태 정보는 로그를 종료할 때 사용된다.
traceId
: 내부에트랜잭션 ID
와level
을 가짐.startTimeMs
: 로그 시작 시간. 로그 종료시 이 시작 시간을 기준으로 시작-종료까지 전체 수행 시간을 구할 수 있음.message
: 시작시 사용한 메시지. 이후 로그 종료시에도 이 메시지를 사용해 출력함.
HelloTraceV1.java
: TraceId
, TraceStatus
를 사용해 실제 로그를 생성하고 처리하기
@Slf4j
@Component
public class HelloTraceV1 {
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<X-";
public TraceStatus begin(String message) {
TraceId traceId = new TraceId();
Long startTimeMs = System.currentTimeMillis();
// 로그 출력
log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
return new TraceStatus(traceId, startTimeMs, message);
}
public void end(TraceStatus status) {
complete(status, null);
}
public void exception(TraceStatus status, Exception e) {
complete(status, e);
}
private void complete(TraceStatus status, Exception e) {
Long stopTimeMs = System.currentTimeMillis();
long resultTimeMs = stopTimeMs - status.getStartTimeMs();
TraceId traceId = status.getTraceId();
if (e == null) {
log.info("[{}] {}{} time={}ms", traceId.getId(),
addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(),
resultTimeMs);
} else {
log.info("[{}] {}{} time={}ms ex={}", traceId.getId(),
addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs,
e.toString());
}
}
/**
* level=0:
* level=1: |-->
* level=2: | |-->
* level=2와 예외 발생: | |<X-
* level=1와 예외 발생: |<X-
*/
private static String addSpace(String prefix, int level) {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < level; i++) {
sb.append( (i == level - 1) ? "|" + prefix : "| ");
}
return sb.toString();
}
}
위 메소드를 사용해 실제 로그를 시작, 종료할 수 있다. 또한, 로그를 출력하고 실행 시간도 측정 가능하다.
@Component
: 싱글톤으로 사용하기 위해 스프링 빈으로 등록. 컴포넌트 스캔 대상이 됨.
공개 메소드
: 로그 추적기에서 사용되는 공개 메소드 세 가지
➡️begin()
,end()
,exception()
✔️
TraceStatus begin(String message)
: 로그를 시작한다.
로그 메시지를 파라미터로 받아 시작 로그를 출력한다. 또한 응답 결과로 현재 로그 상태인 TraceStatus를 반환한다.✔️
void end(TraceStatus status)
: 로그를 정상 종료한다. (정상 흐름에서 호출)
파라미터로 시작 로그의 상태(TraceStatus)를 전달 받는다.
이 값을 활용해 실행 시간을 계산하고, 종료시에도 시작할 때와 동일한 로그 메시지를 출력한다.✔️
void exception(TraceStatus status, Exception e)
: 로그를 예외 상황으로 종료한다. (예외 발생시 호출)
TraceStatus
,Exception
정보를 함께 전달 받아 실행시간, 예외 정보를 포함한 결과 로그를 출력한다.
비공개 메소드
complete(TraceStatus status, Exception e)
:end()
,exception()
의 요청 흐름을 한 곳에서 편리하게 처리.
실행 시간을 측정하고 로그를 남김.
String addSpace(String prefix, int level)
: 아래와 같은 결과를 출력함.
⚠️ 참고로 HelloTraceV1
는 아직 모든 요구사항을 만족하지 못한다. 이후 기능이 하나씩 추가될 것.
HelloTraceV1Test.java
: 테스트 작성하기
public class HelloTraceV1Test {
@Test
void begin_end() {
HelloTraceV1 trace = new HelloTraceV1();
TraceStatus status = trace.begin("hello");
trace.end(status);
}
@Test
void begin_exception() {
HelloTraceV1 trace = new HelloTraceV1();
TraceStatus status = trace.begin("hello");
trace.exception(status, new IllegalStateException());
}
}
⚠️ 이 테스트가 완전한 테스트 코드가 아니다.
일반적으로 테스트라면 자동으로 검증하는 과정이 필요한데 이 테스트는 검증 과정이 없고 결과를 콘솔로 직접 확인해야만 한다.
이렇게 응답 값이 없는 경우를 자동으로 검증하려면 여러가지 테스트 기법이 필요하다.
여기까지의 로그 추적기가 어떻게 동작하는지 완전히 이해하고 넘어가야 함