필요성
지금 제가 진행하는 프로젝트 중 출시를 앞두고 있는게 있습니다. 그렇기 때문에 인프라를 구축하고, 기능만 개발할게 아니라 실질적으로 운영에 필요한 기능들을 준비해보고자 했습니다.
이번에는 그 첫 번째 과정으로 로그를 수집하고, 분석해서, 알림까지 주는 파이프라인을 구축해보았습니다.
프로젝트 구성
"코지메이트"라는 프로젝트 아래와 같은 아키텍처로 구성되어있습니다.
실제로 배포하고 운영까지 해보고자 하는 의지를 가지고 진행하는 프로젝트이지만 언제나 대학생에게 서버비용은 부담스러운 지출이 아닐수가 없습니다.
그래서 이 아키텍처는 모두 프리티어를 사용하여 구성되어있고, 개발을 시작한 7월부터 지금까지 총 비용이 0.07달러로 거의 비용이 발생하지 않고 운영되고 있습니다.
따라서 이번 로그 수집 과정에서도 추가적으로 발생하는 비용 없이 로그를 수집하고, 전송하는 것을 목표로 진행했습니다.
로그 수집
로그가 저장되는 위치
아키텍처를 보시면 아시겠지만 해당 프로젝트는 Spring Boot를 사용하며, Docker에 Container로 실행되고 있기 때문에 기본적인 로그가 자동으로 쌓이고 이를 파일로 확인할 수 있습니다. 아래처럼 말이죠.
root 계정으로 /var/lib/docker/containers에 현재 Docker에서 돌아가고 있는 컨테이너 디렉터리가 존재하게 되고, 해당 디렉터리 내에 .log 파일이 존재합니다. 이 파일에 실행되는 컨테이너의 로그가 쌓이게 됩니다.
뭐 따로 컨테이너 내에서 로그 저장 위치를 지정하고, 해당 로그가 존재하는 디렉터리를 ec2의 특정 디렉터리와 마운트하는게 더 안정적이고 간편하지만, 아직은 해당 설정이 안 되어있고 우선 기능 자체를 구성하고 발전시키고자 하였기 때문에 해당 파일을 바로 가져와서 사용하는 방식으로 구성했습니다.
Spring에서 저장할 로그를 커스텀하자
스프링에서는 기본적으로 로그 형식을 제공해주고, 이 로그 형식도 상당히 깔끔합니다.
그래서 그냥 이걸 그대로 쓸까 했는데, 조금 마음에 안드는 부분도 있었습니다.
- 시간대에
+09:00이 붙어있는게 마음에 들지 않음 77702라는 PID도 굳이 필요없어보임- 호출되는 클래스 이름이 너무 길게 표현되는 것 같음
그래서 이런 불만들 해결하고자, 저는 따로 커스텀을 진행했습니다. 구글링을 통해 찾아보면 Slf4j의 커스텀이라면서 XML 파일 만들고 이것저것 하는 내용들이 많았는데 저는 application.yml에 다음 데이터를 추가하는 것으로 충분했습니다.
logging:
pattern:
console: "%yellow(%d{yyyy-MM-ddTHH:mm:ss.SSS}) [%20.20thread] %highlight(%-5level) %cyan(%-30.30C{0}) - %msg%n"+09:00을 없앴습니다.- PID 출력도 없애버리고, 대신 스레드를 넣었습니다. 스레드는 그래도 실행할 때마다 바뀔테니, 그나마 유의미한 데이터라고 생각했기 때문이죠.
- 로그 레벨을 출력합니다. 이건 필수.
- 호출되는 클래스 이름도 확 줄여서 최대 30자가 되도록 만들었습니다. 종종 30자를 넘어가는 이름들도 있어서 어느정도 알아보기 위해서는 이정도는 할당해야된다고 판단했습니다.
- 로그 메시지를 출력합니다. 여기에 제가 원하는 로그 데이터를 출력할 예정입니다.
이렇게 변경하면 다음처럼 출력됩니다.
좀 더 깔끔해졌죠? (저는 그렇게 생각합니다)
어떤 데이터를 로깅할 것인가?
이제 로그 출력 형식도 정했으니 msg에 넣을 내용에 대해서 고민해봐야합니다. 저는 크게 Request, Response, Function으로 구분해서 로그를 출력하고자 했습니다.
이에 대한 여러 레퍼런스를 찾아보려고 기웃겨렸는데, 어떤 데이터를 수집하는지에 대해서 기술해놓은 레퍼런스는 찾기 어려웠습니다. 그래서 대부분 제 생각과 의견에서 필요하다고 생각되는 데이터이며 계속 개발하면서 추가적으로 필요하다고 생각되는 부분은 점차 추가될 예정입니다.
Request
사용자의 Request로부터 로그를 출력합니다. URL, Param, IP같은 것들 말이죠. Body도 로깅하려고 했지만, 일단은 좀 깔끔하게 출력되는걸 원해서, Body는 제외했습니다. 하지만 추후에 추가할 요소 1순위로 백로그에는 추가해놨기 때문에 곧 추가할 계획입니다.
그래서 현재 제가 수집하고자 하는 Request 데이터 형식은 다음과 같습니다.
[ REQUEST] rid {} | ip {} | method {} | uri {} | param {}- rid: Request Id입니다. 사용자가 호출할 때마다 무작위로 uuid를 생성하여 부여합니다. 이후에 Function과 Response에서도 해당 RequestID를 함께 출력합니다.
- ip: 요청한 사용자의 ip입니다.
- method: GET, POST 등의 방식을 출력합니다.
- uri: 사용자가 요청한 endpoint를 출력합니다.
- param: 사용자가 요청할 때 함께 보낸 param을 출력합니다. pathVariable은 uri에 포함되어 출력됩니다.
Response
사용자가 요청을 하고 모든게 처리한 뒤 응답 시기에 로그를 출력합니다. 이 부분에서 가장 중요한 부분은 응답 속도라고 생각을 했으며, 응답 속도에서 통계를 내고 분석할만한 데이터를 함께 로그로 출력하고자 했습니다.
마찬가지로 Body도 로그로 넣어야되는데, 이후에 추가할 계획입니다.
[RESPONSE] {rid} | {method} | {uri} | {status} | {responseTime}ms | {ip} | {user-agent}- rid: Request Id입니다. 에러가 발생했을 때 해당 rid로 요청의 진행 과정을 파악할 수 있습니다.
- method: 로그를 분석할 때 사용하고자 Request와 중복됩니다.
- uri, ip: 마찬가지
- status: 어떤 응답 코드(200, 400, 500)을 반환하는지 출력합니다. 이후에 에러 빈도를 통계낼 때 사용하고자 넣었습니다.
- responseTime: 응답시간입니다. Request가 들어왔을 때 시작시간을 저장하고, Response를 반환할 때 종료시간과의 차이를 구해서 계산합니다. 측정된 응답 시간을 기준으로 발전시켜야할 API를 판단하고자 했습니다.
- user-agent: IOS, Android, Web을 구분하기 위해서 추가해두었습니다.
Function
요청을 처리할 때 방문하는 모든 함수에 대해서 로그를 쌓고자 했습니다. 이 과정을 처리해두면 나중에 운영상황에서 에러가 발생했을 때 좀 더 명확한 판단이 가능할 것이라 생각했습니다.
[FUNCTION] rid {} | func {} | time {}ms- rid: Request Id입니다. 에러를 분석할 때 특정 호출에 대한 로그인지를 분석하고자 넣었습니다.
- func: 실행한 함수 이름입니다. 어떤 순서로 함수를 실행했는지 분석할 수 있을 것이라 생각했습니다.
- time: 현재 해당 함수를 실행할 때 진행된 시간입니다. 어떤 함수에서 시간이 많이 들었는지도 분석할 수 있습니다.
어떻게 로그를 수집할 것인가?
이제 수집할 로그의 형태를 결정했으니 코드로 작성할 시간입니다. Request와 Response는 HandlerInterceptor를 사용하여 구현하였고, Function은 AOP를 사용하여 구현하였습니다.
아래에 MDC를 활용하여 데이터를 저장하고 전달하는데요. 해당 기술에 대해서 인사이트를 얻은 곳은 우아한기술블로그 / 로그 및 SQL 진입점 정보 추가 여정입니다. MDC에 대한 추가적인 개념에 대해서는 따로 설명을 생략하겠습니다.
HandlerInterceptor
HandlerInterceptor는 Spring 요청을 처리할 때 추가적인 작업을 위해 사용되는 인터페이스입니다. Spring의 DispatcherServlet 내부에서 동작하기 때문에 시작 지점, 끝 지점에서 요청을 가로채서 추가적인 작업을 할 수 있습니다.
preHandle: Controller에서 요청을 처리하기 전에 가로챕니다. 해당 부분에서 REQUEST 로깅을 진행했습니다.
afterCompletion: 요청을 끝내기 전에 가로챕니다. 해당 부분에서 RESPONSE 로깅을 진행했고, MDC clear 과정을 거쳐줬습니다.
코드는 아래와 같습니다.
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response,
Object handler) throws Exception {
MDC.put("startTime", String.valueOf(System.currentTimeMillis()));
MDC.put("requestId", java.util.UUID.randomUUID().toString());
log.info("[ REQUEST] rid {} | ip {} | method {} | uri {} | param {}",
MDC.get("requestId"),
request.getRemoteAddr(),
request.getMethod(),
request.getRequestURI(),
request.getQueryString());
return true;
}
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response,
Object handler, Exception ex) throws Exception {
if (MDC.get("startTime") != null && MDC.get("requestId") != null) {
long startTime = Long.parseLong(MDC.get("startTime"));
long endTime = System.currentTimeMillis();
log.info(
"[RESPONSE] {} | {} | {} | {} | {}ms | {} | {}",
MDC.get("requestId"),
request.getMethod(),
request.getRequestURI(),
response.getStatus(),
endTime - startTime,
request.getRemoteAddr(),
request.getHeader("User-Agent")
);
// RequestId | Method | URI | Status | Time | IP | User-Agent
}
MDC.clear();
}이렇게 구성하고 실행하게 되면, 다음과 같은 로그가 찍히는 것을 볼 수 있습니다.
- [ REQUEST] rid 03bc53a5-87f3-4105-bd94-ed3499d8b375 | ip 0:0:0:0:0:0:0:1 | method GET | uri / | param null
- [RESPONSE] 03bc53a5-87f3-4105-bd94-ed3499d8b375 | GET | / | 200 | 121ms | 0:0:0:0:0:0:0:1 | Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36REQUEST와 RESPONSE의 로그 구성 자체는 비슷하면서 다른데요. 기본적인 통계는 RESPONSE로 대부분 처리할 계획이라서, pipe 문자(|)로 쉽게 잘릴 수 있도록 구성하였고, REQUEST는 RESPONSE로 문제를 확인하였을 때 추척하면서 사용하고자 하는게 목표여서 어떤 값이 들어있는지 매칭이 쉽도록 이름까지 함께 써주었습니다.
AOP
AOP는 Aspect Oriented Programming의 약자인데요. 자세한 설명을 하고자 한다면 정말 너무너무 복잡하고, 중요한 개념이라 여기서 설명하기엔 애매해보입니다. 따라서 AOP의 개념에 대해서 알고자 하시는 분들은 이 링크를 참고해주시면 될 것 같아요.
간단하게 AOP를 설명하자면, 어떤 로직이 있을 때 비즈니스 로직과, 부가 기능이 포함된 로직을 구분하여 따로 관리하겠다는 개념인데요.
예를 들어서 DB에 데이터를 넣는 작업과, 트랜잭션을 볼 수 있습니다. DB에 데이터를 넣는 작업은 비즈니스 로직에 포함되어있는 반면 트랜잭션 처리는 부가 기능이라고 볼 수 있는데요.
이 두 기능이 한 코드에 들어있게 되면 관리도 힘들 뿐더러, 트랜잭션은 대부분의 DB 접근 비즈니스 로직과 함께 사용되기 때문에 너무나도 많은 코드의 중복이 발생하게 됩니다. 따라서 이를 따로 구분해서 관리하고자 하는 필요성이 생겼고, 이런 기능을 제공하는게 AOP라고 볼 수 있겠습니다.
(명확하고 구체적으로 설명한 것은 아니니 그냥 그렇구나~ 하고 넘어가주시면 됩니다.)
아무튼 스프링 AOP를 사용하여 저는 함수가 시작하기 전에 로깅을 하도록 처리를 하였고, 그 코드는 아래와 같습니다.
@Aspect
@Component
@Slf4j
public class AopLogger {
@Pointcut("execution(* {경로}..*.*(..))")
public void classAdvice() {
}
@Before("classAdvice()")
public void beforeClassCall(JoinPoint joinPoint) {
if(MDC.get("startTime") != null){
long startTime = Long.parseLong(MDC.get("startTime"));
long endTime = System.currentTimeMillis();
String functionName = joinPoint.getSignature().getName();
log.info("[FUNCTION] rid {} | func {} | time {}ms",
MDC.get("requestId"), functionName, endTime - startTime
); // RequestId | FunctionName | Time
}
}
}
자세한 사항을 설명하기엔 한도끝도 없으니 생략하도록 하고, MDC를 이용하여, rid와 startTime을 받아와서 로그를 출력해줍니다.
- [FUNCTION] rid 03bc53a5-87f3-4105-bd94-ed3499d8b375 | func {func} | time 77ms위처럼 로그의 msg부분을 출력하게 됩니다.
수집한 결과
이렇게 수집된 로그는 이렇게 생겼습니다.
이쁘죠? 전 정말 만족스러웠습니다. 깔끔하고, 있을 것 다있고..
SQL은 어떻게 했는가?
여기서 간단하게 하나 더 설명하고 가자면 SQL문을 출력하는 부분도 로그 형식에 맞춰서 깔끔하게 들어와있는데요.
spring:
jpa:
show-sql: true
properties:
hibernate:
format_sql: false
show_sql: false
highlight_sql: true
use_sql_comments: true
logging:
pattern:
console: "%yellow(%d{yyyy-MM-ddTHH:mm:ss.SSS}) [%20.20thread] %highlight(%-5level) %cyan(%-30.30C{0}) - %msg%n"
level:
org:
hibernate:
SQL: debug다음처럼 SQL 출력에 대한 세팅을 하고, 로깅 레벨을 SQL을 debug로 설정하면 깔끔하게 로그 형식으로 한줄로 나오게 됩니다! 간단하죠? (심지어 하이라이트도 설정됨 ㄷㄷ)
로그 수집 마무리
원래 분석과 알림부분까지 정리를 끝내려고 했는데, 내용이 너무 길어져서 한번 끊고 다시 작성하는게 나을 것 같아보여서 여기까지 한번 정리하고 가겠습니다.
다음 주 내로 해당 부분을 마무리하는게 목표입니다!
