스프링부트 AOP를 이용해 로깅 처리하기

 

 

 

이전글 스프링부트에 로그 남기기의 개선 사항이다.

 

이렇게 로그를 남기려고 하니, 몇 가지 문제가 있었다.

 

1. 로그가 두 번 남는 문제

2. message에 똑같은 로그가 한번 더 출력되는 문제

3. 모든 API 마다 set을 해줘야함

4. 윗 글엔 작성하지 않았지만, 요청 객체를 남기는 방식의 문제

 

이번 글에서는 1, 2, 3번 내용만 다룰 거고, 4번은 다음 글에서 다루려고 한다.

 

로그가 두번 남는 이슈

이 문제는 slf4j와 logback 설정을 잘못 이해해서였다. 

 

기존 logback-spring.xml을 열어보면 아래와 같이 설정되어 있었다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="SERVICE_LOG" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
            <fieldNames>
                <thread>[ignore]</thread>
                <version>[ignore]</version>
                <message>[ignore]</message>
                <levelValue>[ignore]</levelValue>
            </fieldNames>
        </encoder>
    </appender>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
            <fieldNames>
                <thread>[ignore]</thread>
                <version>[ignore]</version>
                <levelValue>[ignore]</levelValue>
            </fieldNames>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
    </root>
    
    <root level="INFO">
        <appender-ref ref="SERVICE_LOG"/>
    </root>
</configuration>

 별도의 새로 구현한 로그매니저를 통해 관리하는 로그들을 관리 하기 위해, serviceLogger를 만들어서 사용했었다.

 

그런데 위와 같이 설정하니 serviceLogger도 출력이 되고, 기본 로거인 sl4fj도 로거를 출력해 로그가 두 번씩 찍혔었다.

 

SERVICE_LOG를 제거하고 기본 로거를 사용하니 한번만 출력되도록 수정할 수 있었다.

 

메시지가 두번씩 찍히던 이슈

logstash encoder를 잘 못 사용해서 발생한 이슈이다.

 

이 전 글에서는 entries를 사용해서 Map의 정보를 남겨줬었다.

final static Logger serviceLogger = LoggerFactory.getLogger("serviceLog");

Map<String,Object> logMessageMap = new HashMap<>();
logMessageMap.put("id", userId);
logMessageMap.put("url", uri);
logMessageMap.put("message", message);
logMessageMap.put("code", code);

serviceLogger.info("{}", entries(logMessageMap));

위와 같이 로그를 작성하면, 

{
  "@timestamp": "2023-07-09T23:56:13.424Z",
  "message": "{code=200, method=GET, parameter=RequestMissionHistoryDto(pageNum=1, pageSize=10), id=0faf0a4d-12f6-4166-9ca5-b44b10ce27fa, url=/v1/mission/history}",
  "logger_name": "serviceLog",
  "level": "INFO",
  "code": 200,
  "method": "GET",
  "parameter": {
    "pageNum": 1,
    "pageSize": 10
  },
  "id": "0faf0a4d-12f6-4166-9ca5-b44b10ce27fa",
  "url": "/v1/mission/history"
}

message 안에 또 하나의 객체가 남는 현상이 있었다.

 

위 이슈는 logstash encoder의 appendEntries를 통해 수정할 수 있었다.

Map<String,Object> logMessageMap = new HashMap<>();
logMessageMap.put("id", userId);
logMessageMap.put("url", uri);
logMessageMap.put("message", message);
logMessageMap.put("code", code);

log.info(appendEntries(logMessageMap), "LOG");

appendEntries는 메시지에 넣는 방식이 아니라,

 

message와 같은 라인에 이어붙이는 방식이라 message엔 "LOG"만 남기고 필요한 정보들을 로그에 남길 수 있었다.

 

모든 API 마다 set을 해줘야 함

기존 방식은 조금 더티했다.

 

LogMessageManager라는 클래스에서 로그 생성을 관리하도록 구현했는데,

 

이렇게 구현할 경우 모든 컨트롤러 안에 LogMessageManager를 DI 해주고,

 

API마다 setLogMessage를 작성해줘야하는 불편함이 있었다.

@RestController
@RequiredArgsConstructor
public class TestController {

    private final LogMessageManager logMessageManager;

    private final TService tService;

    @GetMapping("...")
    public ResponseEntity<Object> getMessage(...) {
        ResponseEntity responseEntity = tService.getMethod(requestMissionPointsDto);
        logMessageManager.setLogMessage(responseEntity); // 이 부분을 매번 붙여줘야 했음
        return responseEntity;
    }
}

위 코드처럼 로그를 남기기 위해 모든 API에 로그 매서드를 붙여줬어야 했다.

 

이 문제를 해결? 하기 위해 AOP를 사용했다.

 

AOP로 로그처리하기

스프링부트에서 AOP를 사용하기 위해 먼저 Configuration을 설정해줘야 한다.

@Configuration
@EnableAspectJAutoProxy
public class AspectConfig {
}

간단하게 @EnableAspectJAutoProxy를 붙인 Aspect Configuration을 작성해준다.

 

반복적으로 Controller마다 붙이기 귀찮기 때문에 Controller에서 return 했을 때를 캐치해서 로그를 남기도록 구현했다.

@AfterReturning(pointcut = "execution(* com.polarishare..*Controller.*(..))", returning = "result")
public void loggingAspect(Object result) {
    if (result instanceof ResultVo) {
        ResultVo<?> resultVo = (ResultVo<?>) result;
        logMessageManager.setLogMessage(resultVo);
    }

    if(result instanceof Map) {
        Map<String, Object> resultVo = (Map<String, Object>) result;
        logMessageManager.setLogMessage(resultVo);
    }

    if(result instanceof ResponseEntity) {
        ResponseEntity<?> resultVo = (ResponseEntity<?>) result;
        logMessageManager.setLogMessage(resultVo);
    }
}

컨트롤러에서 리턴되는 값을 캐치해서 쓰기 위해, AfterReturning 어노테이션을 사용했다.

 

또한 레거시 코드들의 응답 방식이 Map과 ResponseEntity를 그대로 쓰는 것들이 있어서

 

setLogMessage를 오버로딩해서 처리할 수 있도록 구현했다.

 

더 좋은 방식이 있을지는 모르겠지만, 우선은 위 방식이 잘 동작하고 있다.

 

요청 객체를 남기는 방식의 문제

이 문제는 조금 다른 이슈다.

 

GET방식과 POST방식, 그리고 MultipartForm data를 받을 때 RequestBody와 쿼리 스트링을 처리하는 방식이 달라서 로그를 처리하는데 문제가 있었다.

 

예전에 로그를 처리했을 때는 MultipartForm data는 별도의 로그를 남기지 않았었는데,

 

위 내용에 대한 요청 사항이 있어서 손이 많이 갔다.

 

이 문제는 추후 다룰 예정이다.

 

마치며

일단 이걸로 로그에 대한 내용은 일단락 지은 것 같다.

 

다음은 테스트와 문서화쪽을 처리하지 않을까 싶다.