팀 로깅 전략 세우기

이돈이면 official·2023년 7월 28일
백엔드
9
post-thumbnail

작성자: 우아한테크코스 5기 여우

로깅 전략을 왜 세워야 할까

로컬 환경과 달리 운영서버에서 실행 중인 애플리케이션은
디버깅 기능을 통한 문제 분석이 사실상 불가능하죠.

서버 안에서 어떤 일이 일어나고 있는지는
서버의 특정 파일에 실시간으로 기록되는 '로그' 를 통해서만 간접적으로 관찰할 수 있어요.

원활한 모니터링을 위해서는 최대한 자세하고 적절한 '로그 메시지' 를 통해
문제를 빠르게 분석한 후 해결할 수 있어야 하는데,

때문에 어떤 로그를 어떤 레벨로 어디에 기록하고,
얼마동안 그 기록을 보관할지를 결정하는
'로그 전략'이 매우 중요합니다.

전략을 세우는 기준을 찾아보자

근디 어케하란 말이고 🥹
써본 거라곤 System.out.println() 뿐인데

다행히 실제 대규모 서비스를 운영중인 다양한 기업에서 자신들의 로깅 전략을 블로그로 공유하고 있는데,
이 중 넷마블의 옵저버빌리티 포스팅으로부터 중요한 로깅 인사이트를 얻을 수 있었어요.

넷마블의 로깅 팁

  1. ERROR와 WARN 로그에는 꼭 스택 트레이스와 콘텍스트 정보를 넣는 것이 좋다.
  2. INFO 레벨 로그에는 작업의 중간 진행상황을 기록하기 보다, 하나의 작업 단위가 완료되면 해당 작업을 요약한 내용을 기록하는 것이 좋다.
  3. 편리하게 그룹화할 수 있도록 고유한 에러 코드를 필드에 추가하는 것이 좋다.
  4. 통합 테스트 단계에서부터 로깅 내용을 신경써서 관찰하거나, 아예 로깅 내용을 테스트코드에 포함하는 것이 좋다. 이 과정에서 내용이 부실한 로그나 레벨이 맞지 않는 로그를 색출할 수 있기 때문이다.
  5. 로그 발생 원인은 가능한 친절하게 작성하는 것이 좋다.
  6. 민감한 정보는 필터링하거나 수집되지 않게 주의를 기울이는 것이 좋다.

조아요 👀 이 팁을 마음속에 새기면서 전략을 세워 봅시다!

로깅 레벨을 정해보자

다양한 로깅 라이브러리들을 추상화한 Slf4j에서 제공하는 로깅 레벨은 크게 5가지가 있어요.

  • Error
  • Warn
  • Info
  • Debug
  • Trace

로그의 성격에 따라 로깅 레벨을 지정해 줌으로써
수많은 로그를 레벨에 따라 필터링하여 열람할 수 있고,

서버를 구동하는 환경에 따라 로그 레벨을 다르게 하여
어떤 레벨의 로그를 기록하고 기록하지 않을지 설정할 수 있어요.

예를 들어 Info 레벨까지 로깅하겠다, 라고 설정한다면
Error, Warn, Info 레벨까지만 로깅을 수행하고
Debug, Trace 레벨의 로깅은 수행하지 않는 식!

그렇기 때문에 어떤 로그를 어떤 레벨에 남길지 결정하는 것이 아주 중요해요.

이돈이면 팀에서는 다양한 자료 취합과 논의를 통해
로깅 레벨을 아래와 같이 결정했습니다.

ERROR

'개발팀이 의도하지 않은 오류로 인해 요청과 응답이 정상적으로 이루어지지 않은 경우' 해당 레벨의 로그를 남겨요.

(예시)

  • NPE가 적절히 처리되지 못하고 컨트롤러를 넘어 ExceptionHandler까지 넘어온 경우
  • IAE 등의 기본 JDK 예외가 적절히 처리되지 못하고 컨트롤러를 넘어 ExceptionHandler까지 넘어온 경우
    (이돈이면 팀에서는 기본 JDK 대신 적절한 커스텀 예외만 던지기로 합의했어요)
  • 사용자의 잘못으로 일어나지 않은 StackOverFlowException, IOException 등의 예외
  • 그 외 응답 코드로 internal server error에 해당하는 500 코드를 응답하는 모든 예외 상황

WARN

'당장 오류 상황이 아니거나 처리 가능한 오류상황이지만, 향후 시스템 에러로 이어질 수 있는 경우' 해당 레벨의 로그를 남겨요.

(예시)

  • 한 페이지당 20개의 게시글을 조회하는데, 사용자가 스크롤을 계속 내려 게시글을 1000개 이상 조회하는 경우
    -> 메모리에 게시글 엔티티가 너무 많이 쌓이면 메모리 부족 현상이 일어날 수 있으므로 경고 상황

INFO

'일반적인 사용자 요청과 응답의 요약, 또는 개발자가 의도한 오류 상황이 발생한 경우' 해당 레벨의 로그를 남겨요.

(예시)

  • 성공적인 API 요청과 응답이 오가는 경우
  • 400, 401 등 사용자의 잘못된 요청으로 인한 의도된 오류를 발생시키는 경우

DEBUG, TRACE

INFO에서 다루는 API의 세부 정보(HTTP 코드, SQL 쿼리 등)이 필요한 경우에 주로 해당 레벨의 로그를 남기는데,
이 레벨의 로그는 보통 운영 환경에서는 사용하지 않고 개발용 로컬 환경에서 자주 사용한대요.

하지만 로컬 환경에서만 기록하는 로그라면, IntelliJ의 디버깅 기능으로 충분히 정보를 얻을 수 있는데
굳이 DEBUG 로그를 관리할 필요가 없어 보이니,
DEBUG 레벨의 로깅은 하지 않기로 했습니다.

어떤 로그를 남길 지 정해보자

실제 회사에서 사용하는 로그를 본 적이 거의 없어서
어떤 내용을 로그로 남겨야 하지?를 정하는 데에 어려움을 겪었어요.
이 또한 다양한 기술 블로그를 비교하고 함께 논의하면서 얼레벌레 정해보았습니다.

공통

  • 요청 시간(timestamp)
  • 로깅용 멤버 식별자
  • 요청 URL

ERROR

  • 에러 메시지
  • stackTrace

WARN

  • 경고 메시지(가능한 상세히)

INFO

  • 응답 코드
  • ReponseBody
  • (에러 응답인 경우) 에러 코드

이제 이 내용을 표현할 구체적인 로그 포맷을 정하면 돼요!

로그의 데이터 모양을 정해보자

스프링 부트 프로젝트에서 기본으로 보여주는 로그는
보통 요렇게 문자열이 줄줄이 나열된 형태로 기록되는데,

이런 줄이 수십 만개 쌓여있으면 일단 눈이 아프고
어떤 단락이 어떤 내용인지, 어떤 요청이 오가면서 기록된 로그인지 파악하기가 힘들었어요.

그래서 로그의 형태를 조금 더 가독성있는 json 형태로 구성한다면
key-value 데이터를 사람이 읽으면서 내용을 파악하기에도 쉽고,
컴퓨터도 알아들을 수 있는 구조이므로 나중에 필터링 등의 작업에 활용하기도 좋겠다고 생각했어요!

이 내용을 바탕으로 대략적인 로그 표본을 만들어 보았습니다.

ERROR

{
	"uri": "/image/confirm",
	"request-identifier": "3a76c903614e4e",
	"timestamp": 202307 26215824.983532 (초 아래 소수점 6자리까지),
	"message" : "file path not found",
	"stacktrace": "java.io.FileNotFoundException: C:/Users/tamagochi/abc.txt (Is a directory) 
		at java.io.FileOutputStream.open0(Native Method) 
		at java.io.FileOutputStream.open(FileOutputStream.java:270) 
		at java.io.FileOutputStream.(FileOutputStream.java:213) 
		at JavaHungry.main(JavaHungry.java:10)
		..."
}

WARN

{
	"uri": "/image/confirm",
	"request-identifier": "3a76c903614e4e",
	"timestamp": 20230726 215824.983532 (초 아래 소수점 6자리까지),
	"message" : "over 1,000 post loaded on memory. Concerns about exceeding memory capacity."
	(1,000개를 초과한 post가 메모리에 올라감. 메모리 허용량 초과 우려됨)
}

INFO(성공 케이스)

{
	"uri": "/image/confirm",
	"request-identifier": "3a76c903614e4e",
	"timestamp": 20230726 215824.983532 (초 아래 소수점 6자리까지),
	"statuscode" : 201,
	"message": {성공시 RepsonseBody}
}

INFO(실패 케이스)

{
	"uri": "/image/confirm",
	"request-identifier": "3a76c903614e4e",
	"timestamp": 20230726 215824.983532 (초 아래 소수점 6자리까지),
	"statuscode": 400,
	"message": {실패시 RepsonseBody}
}

구현하자

조아요

로깅 설정파일 만들기

logback 설정은 xml을 사용해야 하는데 xml 사용법을 몰라서,
logback 공식문서와 다양한 기술 블로그를 열심히 찾아보며 밤낮으로 공부하고 실험해야 했어요.

로그를 json 형태로 표현하기 위해서는
스프링 부트에서 기본으로 제공하는 라이브러리 외에
logback-jackson
logback-json-classic
logstash-logback-encoder 라는 별도의 라이브러리가 필요해요.
그래서 build.gradle에 해당 라이브러리 의존성을 추가해 주었습니다.

implementation 'ch.qos.logback.contrib:logback-jackson:0.1.5'  
implementation 'ch.qos.logback.contrib:logback-json-classic:0.1.5'  
implementation 'net.logstash.logback:logstash-logback-encoder:6.1'

그리고 위에서 결정한
로깅 레벨에 따른 로그의 형태, 로그를 저장할 장소와 로그가 얼마나 쌓이면 어디에 어떻게 백업할지 등의 전략을
xml파일을 이용해 설정해 주었어요.

  • logback.xml - 애플리케이션의 로깅 전략을 총괄하는 xml
<?xml version="1.0" encoding="UTF-8"?>  
  
<configuration>  
<include resource="console-error-appender.xml" />  
<include resource="console-warn-appender.xml" />  
<include resource="console-info-appender.xml" />  
  
<root level="info">  
<appender-ref ref="INFO"/>  
<appender-ref ref="ERROR"/>  
<appender-ref ref="WARN"/>  
</root>  
</configuration>
  • info-appender.xml - INFO 레벨의 로깅 전략을 설정하는 xml
<appender name="INFO" class="ch.qos.logback.core.ConsoleAppender">  
<filter class="ch.qos.logback.classic.filter.LevelFilter">  
<level>INFO</level>  
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch> 
</filter>
<encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">  
<providers>  
<mdc/>  
<pattern>  
<pattern>  
{  
"timestamp": "%date{yyyyMMdd HHmmss.SSSSSS}",  
"message": "%message"  
}  
</pattern>  
</pattern>  
</providers>  
<jsonGeneratorDecorator class="net.logstash.logback.decorate.CompositeJsonGeneratorDecorator">  
<decorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/>  
</jsonGeneratorDecorator>  
<timestampPattern>yyyyMMddHHmmss.SSSSSS</timestampPattern>  
</encoder>  
</appender>
  • 실제로 출력된 로그
  • (성공 요청)
	{
	  "statuscode" : "200",
	  "uri" : "/log/info/success",
	  "request-identifier" : "dc5b32be-20c7-4a48-ba63-2c5dfc7d9cff",
	  "timestamp" : "20230728 155714.716000",
	  "message" : "body {\"like\":\"rollable\"} "
	}
  • (실패 요청)
	{
	  "statuscode" : "400",
	  "uri" : "/log/info/fail",
	  "request-identifier" : "1d415a81-175f-475c-b834-748d8b9c5ef4",
	  "timestamp" : "20230728 160017.301000",
	  "message" : "body {\"errorCode\":4006,\"errorMessage\":\"추천 한 게시글의 비추천을 취소할 수 없습니다.\"} "
	}
  • warn-appender.xml - WARN 레벨의 로깅 전략을 설정하는 xml
<appender name="WARN" class="ch.qos.logback.core.ConsoleAppender">  
<filter class="ch.qos.logback.classic.filter.LevelFilter">  
<level>WARN</level>  
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">  
<providers>  
<mdc/>  
<pattern>  
<pattern>  
{  
"timestamp": "%date{yyyyMMdd HHmmss.SSSSSS}",  
"message": "%yellow(%message)"  
}  
</pattern>  
</pattern>  
</providers>  
<jsonGeneratorDecorator class="net.logstash.logback.decorate.CompositeJsonGeneratorDecorator">  
<decorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/>  
</jsonGeneratorDecorator>  
<timestampPattern>yyyyMMddHHmmss.SSSSSS</timestampPattern>  
</encoder>  
</appender>
  • 실제로 출력된 로그
{
  "uri" : "/log/warn",
  "request-identifier" : "1da8c277-70c9-43b7-9464-9dadb40b5654",
  "timestamp" : "20230728 160212.635000",
  "message" : "EntityManager에 캐싱중인 Post Entity의 개수가 3,000개를 초과했습니다. 메모리 부족이 일어날 수 있습니다."
}
  • error-appender.xml - ERROR 레벨의 로깅 전략을 설정하는 xml
<included>  
<appender name="ERROR" class="ch.qos.logback.core.ConsoleAppender">  
<filter class="ch.qos.logback.classic.filter.LevelFilter">  
<level>ERROR</level>  
<onMatch>ACCEPT</onMatch> <!-- 해당 레벨만 기록한다. -->  
<onMismatch>DENY</onMismatch> <!-- 다른 수준의 레벨은 기록하지 않는다.(상위 레벨도 기록 안함), 상위 수준의 레벨에 대한 기록을 원하면 ACCEPT 로 하면 기록된다. -->  
</filter> <!-- 레벨별 필터링이 필요없을 경우 filter class 관련된 부분을 삭제하면 됨-->  
<encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">  
<providers>  
<mdc/>  
<pattern>  
<pattern>  
{  
"timestamp": "%date{yyyyMMdd HHmmss.SSSSSS}",  
"message": "%message",  
"stacktrace": "%rEx"  
}  
</pattern>  
</pattern>  
</providers>  
<jsonGeneratorDecorator class="net.logstash.logback.decorate.CompositeJsonGeneratorDecorator">  
<decorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/>  
</jsonGeneratorDecorator>  
<timestampPattern>yyyyMMddHHmmss.SSSSSS</timestampPattern>  
</encoder>  
</appender>  
</included>
  • 실제로 출력된 로그
{
  "uri" : "/log/error",
  "request-identifier" : "33b26bb1-edf4-4292-b751-1141112d1f19",
  "timestamp" : "20230728 160251.757000",
  "message" : "알지 못하는 예외 발생",
  "stacktrace" : "org.springframework.web.bind.MissingServletRequestParameterException: Required request parameter 'a' for method parameter type int is not present\n\tat org.springframework.web.method.annotation.RequestParamMethodArgumentResolver.handleMissingValueInternal(RequestParamMethodArgumentResolver.java:218)\n\tat org.springframework.web.method.annotation.RequestParamMethodArgumentResolver.handleMissingValue(RequestParamMethodArgumentResolver.java:193)\n\tat org.springframework.web.method.annotation.AbstractNamedValueMethodArgumentResolver.resolveArgument(AbstractNamedValueMethodArgumentResolver.java:114)\n\tat"
}

stacktrace 메시지 등에 개행이 되지 않고 일렬로 쭉 써지는 게 조금 별로지만,
기획했던 형태의 로그가 잘 나오는 걸 보고 만족했습니다.

로깅 레벨 별로 저장 파일 분리하기

위 설정대로 실행하면 모든 로그가 콘솔에만 표시돼요.
운영 서버라고 가정하면 nohup.out 파일이 로그로 꽉 차는거죠 👀

별도의 로그 파일에
ERROR, WARN, INFO같은 로깅 레벨 별로 로그를 나누어 저장하게 만들기 위해 xml 파일을 개선했어요.

<included>
    <appender name="ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>./logs/error.log</file>
        <!-- Appender를 변경하고, 로그를 저장할 파일 이름을 명시 -->

        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>

        <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
            <providers>
                <mdc/>
                <pattern>
                    <pattern>
                        {
                        "timestamp": "%date{yyyyMMdd HHmmss.SSSSSS}",
                        "message": "%message",
                        "stacktrace": "%rEx"
                        }
                    </pattern>
                </pattern>
            </providers>
            <jsonGeneratorDecorator class="net.logstash.logback.decorate.CompositeJsonGeneratorDecorator">
                <decorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/>
            </jsonGeneratorDecorator>
            <timestampPattern>yyyyMMddHHmmss.SSSSSS</timestampPattern>
        </encoder>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>error-history.log.%d{yyyy-MM-dd}.gz</fileNamePattern>
            <maxHistory>30</maxHistory>
            <totalSizeCap>5GB</totalSizeCap>
        </rollingPolicy>
        <!-- 어떤 조건일 때 기존 로그파일을 압축해 분리할 지 조건을 명시 -->
    </appender>
</included>

그랬더니 로그 레벨별로 별도의 파일들에 로그가 쫘자작 기록되기 시작했습니다.

나이스!

운영 서버 환경에서만 로깅 전략 적용하기

근데 다들 익히 아시듯
로컬에서 개발할 때에는 application.properties에 이것저것 설정을 해두면
sql 쿼리나 http 통신 내용 등 엄청 자세한 내용의 로그를 알아서 써주기 때문에
우리가 만든 심플하고 획일화된 로깅 전략을 개발 환경에서 적용하는 게 오히려 방해가 될 수 있습니다.

로컬 환경에서는 평소에 쓰던 로그를 계속 쓰고,
운영 서버, 즉 'prod' 환경에서만 이 로깅 전략이 적용되게 하고 싶었어요.

그래서 그렇게 했습니다!

<?xml version="1.0" encoding="UTF-8"?>

<configuration>
    <include resource="console-error-appender.xml" />
    <include resource="console-warn-appender.xml" />
    <include resource="console-info-appender.xml" />

    <root>
        <springProfile name="prod"> <!-- appender를 적용할 spring profile을 설정 -->
            <appender-ref ref="INFO"/>
            <appender-ref ref="ERROR"/>
            <appender-ref ref="WARN"/>
        </springProfile>
    </root>
</configuration>

요렇게 했더니
스프링 부트의 profile을 prod로 설정할 때에만 로깅 전략이 적용되었습니다.

  • profile을 prod로 했을 때

(로깅 전략이 적용된 모습. 파일에 로깅하게 설정해 두었으니 콘솔에는 아무것도 안 나옴!)

  • profile을 dev로 했을 때

(평소와 같은 로그가 출력되는 모습)

(예정) 피드백 받기 / 보완하기 / 모니터링 툴 적용하기

아직 로깅을 구현한 PR이 머지되지 않아 운영 서버에서 모니터링해보지 못했지만
실제 환경에서 사용하기에는 딱봐도 뭔가 부족할 것 같아 보여요.

머지 이후에 ssh 콘솔에서 계속 모니터링 해보고,
어떤 정보가 포함되면 좋을 지 팀원들과 논의해보고
코치님들께도 보여드리면서 실무에서 사용하는 로그와 어떤 차이가 있는지 비교해볼 예정입니다.

그리고 로그 기록을 좀 더 편하게 볼 수 있는 모니터링 툴로 어떤 게 있는지 비교해보고
우리팀에 최적인 툴을 찾아 적용해볼 예정입니다.

신나요
로깅과 관련된 다양한 경험을 더 해본 후 해당 문단을 보충하겠습니다 🙂

profile
이돈이면 official
이돈이면 기술 블로그입니다 🫶🏻
이전 포스트

N+1 + Pageable 트러블슈팅 여행기

다음 포스트

4가지 성능테스트 도구로 쿼리 성능 개선 테스트하기

3개의 댓글

comment-user-thumbnail
LeeGeonHo
2023년 7월 31일

It's awesome

답글 달기
comment-user-thumbnail
munjin0201
2023년 8월 5일

로깅 관련해서 학습중이었는데 너무 정리 잘 해주셔서 많이 배워가요! 고마워요 여우~ (히이로입니당 ㅎㅎ)

답글 달기
comment-user-thumbnail
dooboocookie
2024년 7월 12일

역시 여우쨩

답글 달기