배경
서비스 개발, 운영을 하다보면 로그가 없어서는 안된다.
내가 필요하다고 느낀 로그의 목적은 3가지였다.
- 사용자 패턴 파악
- 에러 추적
- 성능 측정
근데 여태까지는 yml 파일을 통해 logging 설정을 하여 쿼리 관련된 로그만 남고 있었다.
이러다 보니 에러도 추적하기 어렵고 심지어 기능을 개발하며 로그를 볼 때도 로그보기가 헷갈렸다.
그래서 logback과 AOP를 활용하여 로그를 제대로 남겨야겠다고 생각했다.
Spring AOP
Spring AOP는 스프링에서 제공하는 기능인데 공통 기능을 분리하고 모듈화할 수 있다.
대표적인 예시로 트랜잭션 관리가 있다. 또한 로깅에도 활용된다.
AOP에 대한 글은 아니기에 개념은 생략한다. 아래 글을 통해 개념과 구성 요소를 파악할 수 있다.
[Spring]AOP 완전 정복하기(개념과 구성 요소)
AOP 구현
우선 로깅에 AOP를 적용할 것이고 API 요청에 대한 로그를 처리할 것이다.
그렇기에 Pointcut을 다음과 같이 정의했다.
@Pointcut("within(com.pokit..*) && within(@org.springframework.web.bind.annotation.RestController *)")RestController 어노테이션이 붙은 클래스에 Advice가 적용될 수 있게 했다.
이제 어떤 Advice가 동작되게 할 것인 지 Advice를 구현해야한다.
크게 나누면 요청 로그와 응답 로그로 구분지었다. 각각 메소드 실행 전, 후이므로 Around Advice를 적용했다.
@Around("controllerPointcut()")
fun logApi(joinPoint: ProceedingJoinPoint): Any? {
val methodSignature = joinPoint.signature as MethodSignature
val args = joinPoint.args
val userId = getUserId(args)
val httpMethod = request.method
val requestUri = request.requestURI
val operationSummary = getOperationSummary(methodSignature.method)
val queryString = request.queryString
val requestBody = getRequestBody(args)
log.info(
"\n----Request Log----\n" +
"API: {}\n" +
"Method: {}\n" +
"API Path: {}\n" +
"User Id : {}\n" +
"Query String: {}\n" +
"Request Body: \n{}\n" +
"---------------",
operationSummary, httpMethod, requestUri, userId, queryString, requestBody
)
var response: Any?
val executionTime = measureTimeMillis {
response = joinPoint.proceed()
}
val responseBody = getResponseBody(response)
log.info(
"\n----Response Log----\n" +
"API: {}\n" +
"Response Body: \n{}\n" +
"Execution Time: ${executionTime}ms" +
"---------------",
operationSummary, responseBody
)
return response
}요청, 응답에서 남긴 정보는 다음과 같다.
요청 로그
- API : 어떤 API인 지 → 스웨거의 summary를 가져온다.
- Method : API Method
- API Path : API 요청 경로
- User Id : 요청한 User의 ID, JWT가 필요없어 빈 채로 들어온 요청이면 Null이 찍힌다.
- Query String : 요청 파라미터
- Request Body : 없으면 요청 바디가 없다고 남긴다.
응답 로그
- API : 어떤 API인 지 → 스웨거의 summary를 가져온다.
- Response Body : 응답 바디를 남김
- Execution Time : API를 처리하는데 걸린 시간을 남긴다.
굳이 필요없는 정보는 더 추가하지 않고 정말 필요한 정보만 딱 남기도록 하였다.
특히 이제 성능 개선 작업에 들어 갈 예정인데 실행 시간 로그가 남도록 했더니 어떤 API가 성능 개선이 필요한 지 눈에 보이기 시작했다. 그런 API들 위주로 성능 개선을 진행하게 될 것 같다.
Advice구현에서 사용되는 함수들은 다음과 같다.
private fun getRequestBody(args: Array<Any>): String {
for (arg in args) {
if (arg !is HttpServletRequest && arg !is HttpServletResponse && isDto(arg)
) {
try {
return objectMapper.writerWithDefaultPrettyPrinter().writeValueAsString(arg)
} catch (e: JsonProcessingException) {
log.error("Failed to serialize request body: {}", e.message)
return "Failed to serialize request body"
}
}
}
return "No Request Body"
}
private fun getResponseBody(response: Any?): String {
return try {
objectMapper.writerWithDefaultPrettyPrinter()
.writeValueAsString(response) // Pretty Print
} catch (e: Exception) {
log.error("Failed to serialize response body: {}", e.message)
"Failed to serialize response body"
}
}
private fun getOperationSummary(method: Method): String {
val operation = method.getAnnotation(Operation::class.java)
return operation?.summary ?: "Summary 없음"
}
private fun isDto(obj: Any?): Boolean {
if (obj == null) {
return false
}
val packageName = obj::class.qualifiedName ?: return false
return packageName.startsWith("com.pokit") && packageName.contains(".dto")
}getRequestBody와 getResponseBody에 writerWithDefaultPrettyPrinter()는 필수는 아니지만 필수라고 생각한다. JSON을 pretty print할 수 있게 해주는데 저걸 안하면 로그 보기가 힘들다..(로그 남기는 의미가 없을 정도)
그리고 getRequestBody에서 isDto()함수를 조건에 넣은 이유는 API 요청 시 클라이언트측에서 실제로 요청한 body를 남기기 위함이다. 처음 구현할 땐 저 조건이 없었는데 그러면 API CRUD에 필요한 요청바디가 남는 것이 아닌 사용자 정보 바디가 남았다. 아마 이게 args 배열에서 제일 먼저 나오는 body인 것 같다.
Logback
logback이 왜 필요하냐면 로그 설정을 더 세심하게 관리할 수 있어서이다.
yml로 로그를 설정하기엔 불편하고 사실 어떻게 하는 지 깊게 알지 못했다.
기존에는 로그를 저장하지 않았다. 그래서 서버가 재배포 되면 배포 이전에 발생했던 에러를 추적하는게 불가능하다는 큰 문제가 있었다.
그래서 logback을 통해 로그를 저장하도록 했다. 이후에 Promtail을 통해 Loki로 로그를 전송하는 작업도 해야하기에 겸사겸사 진행했다.
Logback 내용이 좀 길어서 일부 중요한 내용만 가져와보았다.
<appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>/var/log/pokit/info/info.%d{yyyy-MM-dd}.log</fileNamePattern>
<maxHistory>30</maxHistory>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</pattern
<charset>UTF-8</charset>
</encoder>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>INFO</level>
</filter>
</appender>fileNamePattern을 보면 날짜 형식이다. 로그 저장이 일별로 이루어지며 같은 날의 로그는 한 파일에 저장되도록 했다. 저장 기간은 30일로 설정했는데 명확한 기준을 세우고 한 것은 아니고 30일보다 이전의 로그를 볼 일은 없지 않을까..란 생각에 했다ㅎ
<logger name="com.pokit.common.logging.LoggingAspect" level="INFO" additivity="false">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="INFO_FILE"/>
</logger>이 내용이 꼭 있어야 한다. LoggingAspect로 AOP를 구현했으므로 이 내용도 로그에 남도록 설정을 해줘야 한다.
처음에 이 내용 없이 했다가 로그 왜 안 뜨지..했다. 시간 날렸지만 이제 알았으니 됐다ㅋ
최종 결과
이런식으로 로그가 남는다. 예시 이미지만 봐도 데이터가 1000개 정도밖에 없는데 이 API 처리하는데 1초 넘게 걸렸다. 얼른 개선해야겠다… 끝!
소스코드는 다음 레포에 있습니다!
