SpringBoot 로그 레벨 동적으로 변경하기 (runtime logging level change)

2월에 진행된 백기선님의 우아한테크세미나 스프링부트편 말미에 나온 내용을 요약하고,

따라해보며 개인적으로 알게된 추가내용을 덧붙인 포스팅입니다 :)

급하신 분은 맨 아래 요약으로! (테스트해볼 수 있는 샘플 프로젝트 파일과 포스트맨 json도 있어요)

---

개요

런타임에 동적으로 로그 레벨을 변경할 수 있는 방법을 알게 됐다.

백기선님께서 꽤 오래 전에 이미 구현되어 있는 기능이라고 말씀하셨지만,
채팅창을 보면 나만 몰랐던 건 아닌 듯 하다 ㅎㅎ

의존성에 actuator만 추가하고 약간의 설정만 가미해두면 되기 때문에 

운영중인 서비스의 로그를 tail 걸어서 잠시 상세하게 확인하고 싶을때 로그레벨을 변경하는 식으로 사용가능할 듯 하다.

그럼 꼬우

 

 

---

1. 프로젝트 준비

1.1 의존성

SpringBoot 2.5.1, Java 1.8, gradle, jar를 선택했다.
의존성으로는 lombok, actuator, web 세 가지를 추가했다.

compileOnly 'org.projectlombok:lombok'
annotationProcessor 'org.projectlombok:lombok'
implementation 'org.springframework.boot:spring-boot-starter-actuator'
implementation 'org.springframework.boot:spring-boot-starter-web'

 

 

1.2 컨트롤러

기본 패키지 하위에 messages라는 패키지를 만들고, 그 안에 RichController 라는 클래스를 생성했다.
기본 경로에 접근 시, lombok의존성을 통해 사용가능하게 된 Slf4j를 이용해 레벨에 따른 로깅을 하도록 했다.

package com.example.dynamiclogginglevelchange.messages;

import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@Slf4j
@RestController
public class RichController {

    @GetMapping("/")
    public Object home() {
        log.trace("트레이스 하위");
        log.info("인포 하위");
        return "hello";
    }

}

 

 

1.3 localhost:8080/ 접속 확인

기동완료 후 접속해보면 기본 로그레벨이 INFO여서 INFO 레벨로 로깅하는 내용만 확인되고 있음을 알 수 있다.

2021-06-12 22:12:49.623  INFO 6388 --- [-175.197.43.137] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms
2021-06-12 22:12:57.131  INFO 6388 --- [nio-8080-exec-1] c.e.d.messages.RichController            : 인포 수신
2021-06-12 22:12:59.737  INFO 6388 --- [nio-8080-exec-2] c.e.d.messages.RichController            : 인포 수신
2021-06-12 22:12:59.956  INFO 6388 --- [nio-8080-exec-4] c.e.d.messages.RichController            : 인포 수신
2021-06-12 22:13:00.193  INFO 6388 --- [nio-8080-exec-3] c.e.d.messages.RichController            : 인포 수신

 

---

2. 동적 로깅 레벨 변경

2.1 로그 레벨

TRACE  <  DEBUG  <  INFO  <  WARN  <  ERROR < OFF

로그 레벨은 위와 같은 구조로 이뤄져 있다.
가령 INFO로 레벨을 설정할 경우, TRACE, DEBUG에 해당하는 정보는 로그되지 않는 것이다.
TRACE로 하면 최대한의 정보가, ERROR로 하면 최소한의 정보가 노출될 것이다.
따라서 적절한 로그 레벨의 설정이 필요하고, logging-back 설정 등을 이용해
로그를 아카이브하고, 분리하고, 용량을 설정하는 등의 상세 설정을 하기도 한다.

그런데 이런 로그 레벨을 동적으로 바꿀 수 있다면, 이는 굉장이 유용한 기능이 아닐 수 없는데,
이를 이제 알았다니!! 그럼 바로 고우.

 

2.2 actuator 설정

localhost:8080/actuator 에 접속해보면 다음과 같은 정보가 나온다.
(JSON으로 리턴된 데이터인데, JSONViewer 라는 크롬 확장프로그램을 이용해 보기 좋게 형태만 변경된 모습이다.)

내용은 접속 가능한 링크들의 목록을 나타낸다. 아무런 설정을 하지 않았을 경우, health에만 접속 가능하다.

health에 접속시 앱이 정상적으로 실행되고 있는지 여부를 나타내는 status값이 JSON으로 반환된다.

// 20210612221811
// http://localhost:8080/actuator/

{
  "_links": {
    "self": {
      "href": "http://localhost:8080/actuator",
      "templated": false
    },
    "health": {
      "href": "http://localhost:8080/actuator/health",
      "templated": false
    },
    "health-path": {
      "href": "http://localhost:8080/actuator/health/{*path}",
      "templated": true
    }
  }
}

 

이 외에도 여러 기능들을 actuator에서 제공하지만, 보안등의 이유로 기본설정은 health만 open한다.
로그 레벨을 actuator를 통해 관리할 수 있게 open하기 위해서 application.properties 파일에 다음 내용을 설정해준다.

그냥 *을 입력해서 모든 것을 개방한뒤 어떤 게 있는지 하나씩 보는 것도 재밌을 것이다.
오늘은 로깅 레벨만을 보면 되니까 properties에 입력한 뒤 localhost:8080/actuator에 다시 접속해보자.

management.endpoints.web.exposure.include=health, loggers

 

health에 이어 loggers가 추가되었다.
또한 loggers 이하 경로에 pathVariable에 따라 다른 경로들도 접속 가능하다는 의미인 loggers-name도 보인다.

// 20210612222419
// http://localhost:8080/actuator

{
  "_links": {
    "self": {
      "href": "http://localhost:8080/actuator",
      "templated": false
    },
    "health": {
      "href": "http://localhost:8080/actuator/health",
      "templated": false
    },
    "health-path": {
      "href": "http://localhost:8080/actuator/health/{*path}",
      "templated": true
    },
    "loggers": {
      "href": "http://localhost:8080/actuator/loggers",
      "templated": false
    },
    "loggers-name": {
      "href": "http://localhost:8080/actuator/loggers/{name}",
      "templated": true
    }
  }
}

 

2.3 현재 설정된 로깅 레벨 확인하기

localhost:8080/actuator/loggers 에 접속하면 아주 방대한 정보가 나온다.

그 중에 여기서 다뤄볼 내용은 네 가지 정도다.

첫번째는 levels 이다.
loggers의 응답값 중 가장 앞에 오는 문자열 배열인데, 어떤 레벨 설정 옵션이 있는지 나타낸다. OFF는 처음 알았다.

 "levels": [
    "OFF",
    "ERROR",
    "WARN",
    "INFO",
    "DEBUG",
    "TRACE"
  ],

 

두번째는 ROOT 다.
이름에서 예상할 수 있듯이, 로깅 레벨을 전역으로 설정할 때 사용하는 곳으로 예상된다.
configuredLevel은 설정한 레벨, effectiveLevel은 현재 적용되고 있는 레벨로 생각된다.
기본적으로 전역으로 INFO 레벨로 설정함을 알 수 있다.

  "loggers": {
    "ROOT": {
      "configuredLevel": "INFO",
      "effectiveLevel": "INFO"
    },
  }

 

세번째는 org.springframework.web 이다
API 개발을 진행하며 좀 더 상세한 디버깅이 필요할 때 프로퍼티에 아래와 같이 직접 입력해서 설정한 적이 있다.

logging.level.org.springframework.web=DEBUG

 

이 설정을 loggers에서도 확인할 수 있다. ROOT에서 조금 내려가면 있다.
로그레벨을 특정한 적이 없기 때문에 configuredLevel은 null,
ROOT 설정에 의해 INFO가 주입되어 effectiveLevel은 INFO로 확인되는 모습이다.

  "loggers": {
    "_org.springframework.web": {
      "configuredLevel": null,
      "effectiveLevel": "INFO"
    },
  }

 

네번째는 내가 만든 클래스다.
각 패키지별로, 클래스별로도 로그레벨을 확인할 수 있다. 

  "loggers": {
    "com.example.dynamiclogginglevelchange.messages.RichController": {
      "configuredLevel": null,
      "effectiveLevel": "INFO"
    },
  }

 

이제 컨트롤러에 작성한 info.trace 내용이 로깅되지 않는 이유를 찾은 것이다.

 

마지막으로 하나가 추가됐다;

최하단에 그룹이 선언되어 있다. 기본으로 묶어두고 이들을 한번에 설정할 수 있게 해두는 것 같다.
내가 기존에 사용하던 logging.level.org.springframework.web=DEBUG가 저렇게 그룹으로 적용되는 원리였던듯 하다.
밑으로는 sql관련 설정도 보이는 것을 확인할 수 있다.

"groups": {
    "web": {
      "configuredLevel": null,
      "members": [
        "org.springframework.core.codec",
        "org.springframework.http",
        "org.springframework.web",
        "org.springframework.boot.actuate.endpoint.web",
        "org.springframework.boot.web.servlet.ServletContextInitializerBeans"
      ]
    },
    "sql": {
      "configuredLevel": null,
      "members": [
        "org.springframework.jdbc.core",
        "org.hibernate.SQL",
        "org.jooq.tools.LoggerListener"
      ]
    }

 

2.4 POST 요청을 보내 런타임에 로깅 레벨 변경하기

로깅 레벨 변경은 POST요청을 보내야 해서 포스트맨을 사용했다.
앞으로는 현재 로깅 레벨 설정도 포스트맨을 통해 확인해보자.

 

아래는 내가 작성한 컨트롤러 클래스의 로그 레벨을 확인하는 GET요청이다. 초기 설정인 INFO 레벨이 확인된다./
그로 인해 트레이스 수신은 확인되지 않는 모습이다.

 

이번엔 같은 주소로 POST요청을 보내되, JSON으로 아래와 같은 body를 전송해보자
응답은 204 No Content가 반환된다. 그리고 다시 포스트맨으로 설정을 확인해보자.
form-data 혹은 urlencoded 방식은 지원되지 않는다.

{ 
  "configuredLevel" : "TRACE" 
}

 

변경을 요청한대로 TRACE로 변경된 모습이다. 레벨 설정을 요청했기에 configuredLevel도 값이 생긴 모습이다.
그럼 이제 localhost:8080/에 다시 접속해보면 트레이스 레벨의 로그도 확인되는 모습이다.

 

 

2.5 로그 읽어보기

2021-06-12 22:49:53.316  INFO 9004 --- [nio-8080-exec-9] c.e.d.messages.RichController            : 인포 수신

스프링부트에서 로그 형식이 위와 같은데 어떤 내용인지 좀 궁금해져서 찾아봤다.
첫번째는 당연히 날짜와 시간이고, (2021-06-12 22:49:53.316)

다음은 로그 레벨이다. (INFO)

세번째는 PID다. (9004)

netstat 명령어로 8080포트를 사용하고 있는 PID를 확인한 모습. 로그와 일치한다.

 

네번째는 내장 톰캣의 스레드풀에서 생성하는 스레드의 이름이다. (nio-8080-exec-9)
여기저기를 찾고 디버깅을 걸어도 확인되지 않아서 포기했었는데, 
디버깅이 걸리지 않는 이유가, 스레드를 풀에다 미리 다 생성해둔 상태이기 때문에
이미 기동한 다음에는 스레드의 이름을 주입하는 부분이 break걸리지 않기 때문이었다.
앱을 재기동하자 브레이크포인트가 작동해서 확인할 수 있었다.

위치는 External Libraries에서 org.apache.tomcat.embed:tomcat-embed-core:버전 이하이다.
org.apache.tomcat.util.threads 패키지에 있는 TaskThreadFactory의 newThread 메소드에서 이름을 생성한다.

또한 여기에 브레이크 포인트를 거니까, 기동시에 톰캣에서 몇개의 스레드를 생성하는지도 확인할 수 있었다.
Catalina-utility 라는 이름으로 2개를 만들고, 그 외에는 웹 요청에 응답하기 위한 스레드 10개를 생성함을 확인했다.

그 다음은 com.example.dynamiclogginglevelchange.message.RichController 인데,(c.e.d.messages.RichController)
기본 패키지까지의 경로는 앞자만을 이용해서 축약해주는 모양이다.

마지막으로 콜론 뒤에 나오는 내용은  로그 내용이다. (            : 인포 수신)

---

3. 디버깅을 위한 몇가지 추가 설정

 

3.1 요청 수신 시 파라미터 확인하기 - GET

먼저 org.springframework.web 의 로그 레벨을 DEBUG로 변경한다.
그리고 이번엔 localhost:8080/에다가 ?name=rich 라고 쿼리스트링을 추가해서 보내보자.

 

이제는 훨씬 상세한 로그가 나온다.
GET 으로 "/?name=rich" 주소를 요청했고, RichController의 home 메소드에 매핑되었으며,
text/html로 "hello"라고 wirte하고 200 OK 로 종료한다는 내용까지 나온다.

이 가운데 parameters={masked} 가 거슬렸다.
이 테스트에서는 쿼리스트링으로 파라미터가 왔기 때문에 보이긴 하지만,
POST로 전송했을 경우 확인되지 않을 것이기 때문이다.

2021-06-12 23:02:30.430 DEBUG 9004 --- [nio-8080-exec-7] o.s.web.servlet.DispatcherServlet        : GET "/?name=rich", parameters={masked}
2021-06-12 23:02:30.430 DEBUG 9004 --- [nio-8080-exec-7] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.dynamiclogginglevelchange.messages.RichController#home()
2021-06-12 23:02:30.430 TRACE 9004 --- [nio-8080-exec-7] c.e.d.messages.RichController            : 트레이스 하위
2021-06-12 23:02:30.430  INFO 9004 --- [nio-8080-exec-7] c.e.d.messages.RichController            : 인포 수신
2021-06-12 23:02:30.431 DEBUG 9004 --- [nio-8080-exec-7] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/html', given [text/html, application/xhtml+xml, image/avif, image/webp, image/apng, application/xml;q=0.9, application/signed-exchange;v=b3;q=0.9, */*;q=0.8] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
2021-06-12 23:02:30.431 DEBUG 9004 --- [nio-8080-exec-7] m.m.a.RequestResponseBodyMethodProcessor : Writing ["hello"]
2021-06-12 23:02:30.431 DEBUG 9004 --- [nio-8080-exec-7] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

 

이 경우 아래 설정을 properties에 추가하면 masked가 해제된다

parameters={name:[rich], age:[20]} 이 잘 확인되는 모습이다.

spring.mvc.log-request-details=true

2021-06-12 23:35:49.719 DEBUG 2540 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : GET "/?name=rich&age=20", parameters={name:[rich], age:[20]}
2021-06-12 23:35:49.720 DEBUG 2540 --- [nio-8080-exec-3] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.dynamiclogginglevelchange.messages.RichController#home()
2021-06-12 23:35:49.720  INFO 2540 --- [nio-8080-exec-3] c.e.d.messages.RichController            : 인포 수신
2021-06-12 23:35:49.721 DEBUG 2540 --- [nio-8080-exec-3] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/html', given [text/html, application/xhtml+xml, image/avif, image/webp, image/apng, application/xml;q=0.9, application/signed-exchange;v=b3;q=0.9, */*;q=0.8] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
2021-06-12 23:35:49.721 DEBUG 2540 --- [nio-8080-exec-3] m.m.a.RequestResponseBodyMethodProcessor : Writing ["hello"]
2021-06-12 23:35:49.722 DEBUG 2540 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

 

 

그러나 이번에 넣은 설정은 actuator를 통해 런타임에 수정할 수 있는 방법을 찾지 못했다.

GET 요청은 DispatcherServlet에서 요청받은 URL이 노출되기 때문에
쿼리스트링으로 파라미터를 모두 확인할 수 있어서 상관없다고 할 수도 있는데, 그렇다면 POST요청은 어떨까?

parameters를 노출시키는 설정을 주입하지 않고도, 동적으로 수정하지 않아도 파라미터를 확인할 수 있을까?

 

3.2 요청 수신 시 파라미터 확인하기 - POST

답은 YES다.

다만 파라미터의 종류가 많아질 경우 생략되기 때문에, 로그레벨을 TRACE로 설정해야 한다.
그리고 details 설정은 다시 false처리한다. (혹은 삭제해도 default가 false라서 무관하다)

spring.mvc.log-request-details=false
logging.level.org.springframework.web=TRACE

 

컨트롤러에 코드를 추가한다.

    @PostMapping("/parameters")
    public Object secondHome(@RequestBody Map<String, Object> map) {
        log.info("map size : {}", map.size());
        return "ok";
    }

 

포스트맨으로 요청을 보낸다.

 

아래는 로그 결과다.

GET과는 달리 데이터를 Body에 담아 보내서 그런지 parameters는 비어있고 headers가 masked 되어 있다.
포스트맨으로 보내서 Content-Type = 'application/json'이 자동으로 추가되어 전송되었을 것이다.

세번째줄을 보면 RequestResponseBodyMethodProcessor 라는 클래스에서 데이터를
application/json;charset-UTF-8로 읽어들이고 있는 것을 알 수 있다. 

그 다음엔 HandlerMethod 클래스가 읽어들인 데이터를 사용하는 것으로 생각되는데,
아마도 읽어들인 JSON데이터를 @RequestBody 애너테이션 선언된 객체에 주입해주는 것으로 생각된다.

2021-06-12 23:40:55.040 TRACE 12596 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : POST "/parameters", parameters={}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2021-06-12 23:40:55.045 TRACE 12596 --- [nio-8080-exec-2] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.dynamiclogginglevelchange.messages.RichController#secondHome(Map)
2021-06-12 23:40:55.074 TRACE 12596 --- [nio-8080-exec-2] m.m.a.RequestResponseBodyMethodProcessor : Read "application/json;charset=UTF-8" to [{name=rich, age=20, skillset=[java, javascript], assets=[{name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}]}]
2021-06-12 23:40:55.083 TRACE 12596 --- [nio-8080-exec-2] o.s.web.method.HandlerMethod             : Arguments: [{name=rich, age=20, skillset=[java, javascript], assets=[{name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}, {name=samsung, quantity=100}, {name=kakao, quantity=100}]}]
2021-06-12 23:40:55.083  INFO 12596 --- [nio-8080-exec-2] c.e.d.messages.RichController            : map size : 4
2021-06-12 23:40:55.771 DEBUG 12596 --- [nio-8080-exec-2] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/plain', given [*/*] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
2021-06-12 23:40:55.771 TRACE 12596 --- [nio-8080-exec-2] m.m.a.RequestResponseBodyMethodProcessor : Writing ["ok"]
2021-06-12 23:40:55.782 TRACE 12596 --- [nio-8080-exec-2] s.w.s.m.m.a.RequestMappingHandlerAdapter : Applying default cacheSeconds=-1
2021-06-12 23:40:55.782 TRACE 12596 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : No view rendering, null ModelAndView returned.
2021-06-12 23:40:55.783 DEBUG 12596 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Completed 200 OK, headers={masked}

 

 

3.3 결론

GET 방식은 요청받은 URL의 쿼리스트링으로 확인이 가능하고,
POST 방식은 로그 레벨을 TRACE로 설정하면, 데이터를 매핑하는 과정에서 값이 로깅되므로,
동적으로 설정할 수 없는 spring.mvc.log-request-details 설정을 만질 필요가 없다.

필요에 따라 동적으로 로그 레벨만 TRACE로 잠시 낮추면 될 것이다.

 

---

요약

의존성 추가

implementation 'org.springframework.boot:spring-boot-starter-actuator'

 

application.properties에 actuator 설정 추가

management.endpoints.web.exposure.include=health, loggers

 

레벨별 로그 처리

log.trace("trace evel log : {}", msg);
log.info("info evel log : {}", msg);

 

부분별 로깅 레벨 확인

GET : http://localhost:8080/actuator/loggers/com.example.dynamiclogginglevelchange.messages.RichController

// 20210612235243
// http://localhost:8080/actuator/loggers/com.example.dynamiclogginglevelchange.messages.RichController

{
  "configuredLevel": null,
  "effectiveLevel": "INFO"
}

 

동적 로깅 레벨 변경

POST : http://localhost:8080/actuator/loggers/com.example.dynamiclogginglevelchange.messages.RichController

// POST + JSON
{ 
    "configuredLevel" : "DEBUG"
}

 

샘플 프로젝트 및 포스트맨 json

dynamicLoggingLevelChange.zip

0.56MB

DynamicLoggingLevelChange.postman_collection.json

0.01MB