[3] 로그 추적기 - 요구사항 분석
어떤 부분에서 예외가 발생하는지 로그를 통해 확인하는 것이 점점 중요해지고 있다.
기존에는 개발자가 문제가 되는 부분을 어렵게 찾아 로그를 직접 만들어 남겼다면, 이제는 로그를 미리 남겨 문제가 되는 부분을 쉽게 찾을 수 있다.
📌 주어진 요구사항
- 모든 PUBLIC 메소드의 호출과 응답 정보를 로그로 출력
- 애플리케이션의 흐름을 변경하면 안됨 → 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨.
- 메소드 호출에 걸린 시간 필요
- 정상 흐름과 예외 흐름 구분하기 → 예외 발생시 예외 정보가 남아야 함.
- 메소드 호출의 깊이 표현 필요 (
| |)- HTTP 요청을 구분
- HTTP 요청 단위로특정 ID를 남겨 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분 가능해야 함.
- 트랜잭션 ID (DB 트랜잭션 X), 여기서는 하나의 HTTP 요청이 시작해 끝날 때가지를 하나의 트랜잭션이라고 함.(트랜잭션이라는 단어는 문맥에 따라 여러가지 의미로 쓰일 수 있다.)
⚠️ 모니터링 툴을 도입하면 많은 부분을 해결할 수 있지만 지금은 학습이 목적이기 때문에 그렇게 하지 않을 것.
[4] 로그 추적기 V1 - 프로토타입 개발
테스트 코드를 작성하기 전까지는 이해가 안 되는 것이 당연하다.
먼저 로그 추적기를 위한 기반 데이터를 가진 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());
}
}⬇️ 테스트 결과
⚠️ 이 테스트가 완전한 테스트 코드가 아니다.
일반적으로 테스트라면 자동으로 검증하는 과정이 필요한데 이 테스트는 검증 과정이 없고 결과를 콘솔로 직접 확인해야만 한다.
이렇게 응답 값이 없는 경우를 자동으로 검증하려면 여러가지 테스트 기법이 필요하다.
여기까지의 로그 추적기가 어떻게 동작하는지 완전히 이해하고 넘어가야 함
