[Spring] 로깅

개발을 하다 보면 로그를 출력해야 하는 경우들이 있다. 따라서 로그에 대해 간단히 짚고 넘어가자.

 

운영 시스템에서는 System.out.println() 같은 시스템 콘솔을 사용해서 필요한 정보를 출력하지 않고, 별도의 로깅 라이브러리를 사용해서 로그를 출력한다. 여기서는 최소한의 사용 방법만 알아본다.

 

<로그 라이브러리>

스프링 부트를 사용하면 스프링 부트 로깅 라이브러리(spring-boot-starter-logging)가 함께 포함된다.

스프링 부트 로깅 라이브러리는 기본으로 SLF4J, Logback 라이브러리를 사용한다.

로깅 라이브러리는 Logback, Log4J 등 수 많은 라이브러리가 있는데, 그것을 통합해서 인터페이스로 제공하는 것이 바로 SLF4J 라이브러리다. 스프링 부트는 그 구현체로 Logback을 사용하는 것이다.

 

간단한 예제로 로그를 사용해보자.

<LogTestController.java>

@RestController
public class LogTestController {

    private final Logger log = LoggerFactory.getLogger((getClass()));

    @RequestMapping("/log-test")
    public String logTest(){
        String name = "Spring";

        System.out.println("name = " + name);

        log.trace("trace log={}", name);
        log.debug("debug log={}", name);
        log.info("info log={}", name);
        log.warn("warn log={}", name);
        log.error("error log={}", name);

        return "ok";
    }
}

+) 매핑 정보 : @RestController 

@Controller는 반환 값이 String이면 뷰 이름으로 인식되어 뷰를 찾고 뷰가 렌더링된다.

@RestController는 반환 String 값을 HTTP 메시지 바디에 바로 입력한다.

 

return "ok"

 

로그는 Logger 인터페이스를 사용한다. 이 때 Slf4j 라이브러리에 해당하는 Logger를 선언해야 한다.

import org.slf4j.Logger;

 

이제 name을 설정하고 시스템 콘솔과 로그 둘 다 출력해보자.

<결과>

name = Spring
2021-05-10 18:35:10.229  INFO 27096 --- [nio-8080-exec-3] hello.springmvc.basic.LogTestController  : info log=Spring
2021-05-10 18:35:10.231  WARN 27096 --- [nio-8080-exec-3] hello.springmvc.basic.LogTestController  : warn log=Spring
2021-05-10 18:35:10.232 ERROR 27096 --- [nio-8080-exec-3] hello.springmvc.basic.LogTestController  : error log=Spring

System.out.println()으로 콘솔에 출력한 부부은 문자열이 그대로 출력되었다.

Logger를 통해 출력한 로그는 일정 포맷을 갖는 것을 확인할 수 있다.

(시간, 로그 레벨, 프로세스 ID, 쓰레드 명, 클래스명, 로그 메시지)

 

그런데 결과를 보면 코드에서 제시한 trace, debug 로그들은 찍히지 않은 것을 볼 수 있다. 이는 로그 레벨과 관련이 있다.

 

<로그 레벨 설정>

로그 레벨은 다음과 같다.

trace > debug > info > warn > error

전체 로그 레벨은 기본적으로 info로 설정되어 있기 때문에 info부터 그 상위 레벨인 error까지 출력되는 것이다.

 

기본 설정을 변경해보자.

<application.properties>

#전체 로그 레벨 설정(기본 info)
logging.level.root=info

#hello.springmvc 패키지와 그 하위 로그 레벨 설정
logging.level.hello.springmvc=debug

우선 전체 로그 레벨은 root로 설정할 수 있고 패키지 별 로그 설정 역시 가능하다. springmvc 패키지의 로그 레벨을 debug로 설정해보자.

 

<결과>

name = Spring
2021-05-10 18:41:02.018 DEBUG 31140 --- [nio-8080-exec-1] hello.springmvc.basic.LogTestController  : debug log=Spring
2021-05-10 18:41:02.021  INFO 31140 --- [nio-8080-exec-1] hello.springmvc.basic.LogTestController  : info log=Spring
2021-05-10 18:41:02.022  WARN 31140 --- [nio-8080-exec-1] hello.springmvc.basic.LogTestController  : warn log=Spring
2021-05-10 18:41:02.022 ERROR 31140 --- [nio-8080-exec-1] hello.springmvc.basic.LogTestController  : error log=Spring

debug부터 error까지 출력되는 것을 확인할 수 있다.

 

+) 이처럼 개발자가 유연하게 로그 레벨을 설정할 수 있다. 일반적으로 개발 서버는 debug부터 운영 서버는 info부터 출력하도록 설정한다.

 

<@Slf4j>

@Slf4j
@RestController
public class LogTestController {

//    private final Logger log = LoggerFactory.getLogger((getClass()));

    @RequestMapping("/log-test")
    public String logTest(){
        String name = "Spring";

        System.out.println("name = " + name);

        log.info("info log={}", name);
}

롬복 라이브러리에서는 @Slf4j 애노테이션을 제공한다. 이는 위와 같이 Logger를 통해 로그 선언을 할 필요 없이 바로 로그 기능을 사용할 수 있게끔 해준다.

 

<올바른 로그 사용법>

log.info("info log={}",name)과 log.info("info log="+name)은 같은 결과를 출력한다. 그렇다면 후자의 방식으로 사용해도 되지 않을까? 결론은 후자의 방식은 사용하지 않는다는 것이다.

 

로그 출력 레벨을 debug로 설정하면 trace 레벨은 출력되지 않는다. 그러나 자바 특성상 log.trace안의 문자열을 먼저 확인하는데 "trace log="+name 문자열에서 name에 파라미터 매핑을 하고 '+' 연산을 수행하도록 설정되어 있다. 결과적으로 사용하지도 않는 trace 로그는 문자 더하기 연산으로 인해 CPU를 잡아먹는다.

그러나 "trace log={}",name의 경우 단순히 파라미터만 name에 넘긴 채로 끝나기 때문에 의미없는 연산이 발생하지 않는다.

-> 그래서 로그를 출력할 때는 "trace log={}",name 방식을 사용해야 한다.

 

<로그 사용시 장점>

- 쓰레드 정보, 클래스 이름 같은 부가 정보를 함께 볼 수 있고, 출력 형식 또한 조정 가능하다.

- 서버 종류에 따라서(개발, 운영 등) 로그 레벨을 조절할 수 있다.

- 콘솔에만 출력하는 것이 아니라, 파일이나 네트워크 등 별도의 위치에 남길 수 있다. 특히 파일에 남길 때는 용량에 따라 로그를 분할하는 것도 가능하다.

- 일반적으로 성능이 System.out보다 좋다.

-> 실무에서는 꼭 로그를 사용하자.