운영 로그를 읽기 좋게 관리하는 방법

운영을 시작하고 나서 가장 먼저 느낀 건, 로그가 많다고 해서 문제가 잘 보이는 건 아니라는 점이었습니다.
오히려 로그가 너무 많고 형식이 제각각이면 필요한 순간에 더 읽기 어려웠습니다.

처음엔 "일단 많이 찍어두면 언젠가 도움이 되겠지"라는 생각으로 로그를 남겼습니다. 그런데 장애가 한 번 나고 나니 그 방식이 얼마나 불편한지 바로 알게 됐습니다.

• 같은 요청인데 어떤 로그는 한국어, 어떤 로그는 영어였습니다
• 어떤 로그는 사용자 id가 있고 어떤 로그는 없었습니다
• 어떤 로그는 한 줄로 끝났고 어떤 로그는 의미 없는 디버그 문장이 다섯 줄씩 이어졌습니다

결국 중요한 건 로그의 양이 아니라, 다시 읽을 수 있는 형태로 남아 있느냐였습니다.

로그를 남길 때 먼저 정한 원칙

운영 로그를 정리하면서 아래 기준을 먼저 세웠습니다.

1. 한 줄만 봐도 무슨 일이 일어났는지 알 수 있어야 한다
2. 같은 종류의 이벤트는 같은 형식으로 남겨야 한다
3. 검색 키워드가 되는 값은 항상 같은 이름으로 넣는다
4. 디버깅에 필요 없는 정보는 과감하게 줄인다

이 원칙을 세우고 나니, 로그를 "기록"이 아니라 "검색 가능한 운영 데이터"처럼 다루게 됐습니다.

가장 먼저 바꾼 것: 문장형 로그 줄이기

예전에 자주 보던 로그는 이런 식이었습니다.

주문 생성 시작
주문 생성 완료
유저 주문 요청 들어옴
주문 처리 중 오류 발생

이런 문장은 작성할 때는 편하지만, 나중에 읽을 때는 생각보다 도움이 적었습니다.
누가, 어떤 주문을, 어떤 결과로 처리했는지가 빠져 있기 때문입니다.

그래서 이벤트 중심으로 한 줄을 다시 만들었습니다.

event=order-created orderId=28194 userId=1042 amount=39000 status=SUCCESS
event=order-create-failed userId=1042 errorCode=ORDER-409 status=FAIL

이렇게 바꾸고 나니 검색이 쉬워졌습니다.
orderId, userId, event, errorCode만으로도 원하는 로그를 빠르게 모을 수 있었습니다.

로그 키 이름을 통일했다

이건 작아 보여도 효과가 컸습니다.

예를 들어 어떤 로그는 memberId, 어떤 로그는 userId, 어떤 로그는 accountId를 쓰고 있으면 운영 중에 같은 사용자의 흐름을 한 번에 모으기 어렵습니다.

그래서 자주 검색할 키는 아예 팀 안에서 통일했습니다.

• traceId
• userId
• orderId
• event
• status
• errorCode
• durationMs

이름이 통일되면 Kibana나 CloudWatch에서 필터를 걸기도 쉽고, 장애 대응할 때 "어떤 단어로 검색해야 하지?"라는 고민이 줄어듭니다.

요청 단위로 묶어서 볼 수 있게 했다

운영 로그에서 가장 답답했던 순간은, 하나의 요청이 여러 서비스와 리포지토리를 지나가는데 서로 연결이 안 되던 경우였습니다.

그래서 요청 단위 추적을 위해 traceId를 꼭 남기도록 했습니다.

String traceId = UUID.randomUUID().toString();
MDC.put("traceId", traceId);

필터나 인터셉터에서 traceId를 잡고, 이후 로그 패턴에 이 값을 포함시켰습니다.

<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level traceId=%X{traceId} %logger - %msg%n</pattern>

이렇게 해두면 하나의 요청이 지나간 로그를 묶어 보기 쉬워집니다.
특히 "왜 이 요청만 느렸나" 같은 문제를 볼 때 정말 도움이 됐습니다.

실제로는 이 부분만 따로 정리할 이야기가 꽤 많았습니다.
필터로 넣을지 인터셉터로 넣을지, MDC.clear()는 어디서 해야 하는지, 응답 헤더로도 같이 넘길지 같은 문제는 Spring에서 traceId를 Filter와 Interceptor로 남기는 방법 글에 따로 적어두었습니다.

성공 로그와 실패 로그를 같은 자리에서 보이게 했다

예전에는 성공 로그는 서비스 한쪽, 실패 로그는 핸들러 한쪽에 흩어져 있었습니다.
그러다 보니 같은 기능인데 성공 케이스와 실패 케이스가 전혀 다른 형식으로 남았습니다.

지금은 가능하면 같은 이벤트 이름을 기준으로 성공/실패를 맞춥니다.

log.info("event=payment-confirmed paymentId={} userId={} status=SUCCESS durationMs={}",
    paymentId, userId, durationMs);
 
log.warn("event=payment-confirmed paymentId={} userId={} status=FAIL errorCode={} durationMs={}",
    paymentId, userId, errorCode, durationMs);

이렇게 하면 같은 키워드로 검색했을 때 성공과 실패를 함께 볼 수 있습니다.
운영에서는 이 차이가 생각보다 큽니다.

로그 레벨도 의미 있게 나눴다

처음에는 info와 error만 대충 나누고 있었습니다. 그런데 운영을 해보니 warn이 생각보다 중요했습니다.

지금은 대체로 이렇게 씁니다.

• info: 정상적인 흐름, 중요한 상태 변경
• warn: 예상 가능한 비즈니스 실패, 재시도 가능한 실패
• error: 시스템 장애, 예기치 못한 예외

예를 들면 재고 부족은 warn에 가깝고, DB 연결 실패는 error에 가깝습니다.
이 기준이 없으면 알람도 시끄러워지고, 진짜 장애와 정상적인 실패를 구분하기 어려워집니다.

너무 자세한 객체 로그는 지양했다

운영 중에는 요청 객체 전체를 그대로 찍고 싶어질 때가 많습니다. 디버깅이 편해 보이기 때문입니다.

하지만 그렇게 남기다 보면 금방 문제가 생깁니다.

• 개인정보가 섞일 수 있다
• 토큰이나 민감한 값이 노출될 수 있다
• 로그 한 줄이 너무 길어져 읽기 어렵다

그래서 지금은 객체 전체를 찍기보다, 정말 필요한 필드만 명시적으로 꺼내서 남깁니다.

log.info("event=order-created orderId={} userId={} itemCount={} amount={}",
    orderId, userId, itemCount, amount);

이 방식은 조금 번거롭지만, 운영 로그는 결국 사람이 읽어야 하므로 이 편이 훨씬 낫다고 느꼈습니다.

느린 요청은 따로 보이게 했다

정상 처리 로그만으로는 성능 문제를 보기 어려울 때가 많았습니다.
그래서 일정 시간 이상 걸린 요청은 따로 남기기로 했습니다.

long start = System.currentTimeMillis();
 
try {
    return chain.doFilter(request, response);
} finally {
    long durationMs = System.currentTimeMillis() - start;
 
    if (durationMs >= 1000) {
        log.warn("event=slow-request method={} uri={} status={} durationMs={}",
            request.getMethod(), request.getRequestURI(), response.getStatus(), durationMs);
    }
}

이 로그는 장애가 아니더라도 운영에서 꽤 유용했습니다.
특정 API가 언제부터 느려졌는지, 배포 이후에 달라진 점이 있는지 확인하기 쉬웠기 때문입니다.

실제로 남기지 않기로 한 로그도 있다

로그를 정리하면서 "무엇을 남길까"보다 "무엇을 남기지 않을까"를 결정하는 게 더 중요했습니다.

지금은 아래 로그는 최대한 줄입니다.

• 의미 없는 시작/종료 로그
• 한 요청에서 너무 잘게 쪼개진 중간 상태 로그
• 이미 다른 이벤트 로그에서 충분히 알 수 있는 중복 로그
• 민감 정보가 섞일 가능성이 있는 원본 요청 전체

처음엔 불안했지만, 오히려 이런 로그를 줄이고 나서 필요한 로그가 더 또렷하게 보였습니다.

운영에서 도움이 됐던 형식

개인적으로는 로그 메시지를 자연어 문장으로 길게 쓰기보다, 아래처럼 짧게 구조화하는 방식을 더 선호하게 됐습니다.

event=login-succeeded userId=42 provider=google status=SUCCESS
event=login-failed provider=google status=FAIL errorCode=AUTH-401
event=slow-request method=GET uri=/api/orders durationMs=1328 status=200

문장처럼 예쁘진 않아도, 운영에서는 이 편이 훨씬 읽기 좋았습니다.
특히 장애가 난 상황에서는 예쁜 로그보다 빨리 찾을 수 있는 로그가 중요했습니다.

결국 로그는 읽기 쉬워야 했다

운영 로그를 관리하면서 가장 크게 바뀐 생각은 이거였습니다.

로그는 남기는 사람 기준이 아니라, 나중에 문제를 찾는 사람 기준으로 써야 한다는 점입니다.

평소에는 대충 보이던 로그도 장애 상황에서는 전부 다르게 읽힙니다.
그때 빠르게 검색되고, 한 줄만 봐도 상황이 보이고, 같은 요청 흐름을 따라갈 수 있어야 비로소 운영 로그 역할을 한다고 느꼈습니다.

마무리

운영 로그를 잘 남긴다는 건 거창한 기술보다 습관에 더 가까웠습니다.
필드 이름을 통일하고, 이벤트를 짧게 정리하고, 필요한 값만 명시적으로 남기는 것만으로도 로그 품질은 꽤 달라졌습니다.

지금도 기능을 추가할 때마다 "이 이벤트는 나중에 어떻게 검색할까?"를 먼저 생각합니다.
그 질문을 먼저 던질수록 로그는 더 읽기 쉬워졌고, 운영 대응도 훨씬 덜 지치게 됐습니다.