서버 에러를 빠르게 발견하고 해결하는 방법: 로그 분석의 핵심

프로젝트를 로컬에서 단위,통합 테스트를 하고 배포를 하면 끝인줄 알았던 나는 개발서버에서 간단한 에러가 터져도 확인하기가 번거로웠다.

 

aws 인스턴스에서 서버를 돌렸던 나는 에러를 확인하기 위해 다음과 같은 행위를 했다.(다시는 이러지 않겠다는 마음으로 써본다)

 

1. vim nohup.out 실행 : 참고로 nohup은 터미널이나 세션이 종료되어도 해당 프로세스가 종료되지 않고 동작하는 방식으로 nohup 쉘스크립트에 jar파일을 실행하도록 명령어를 넣고 구동 시켰다. 그리고 nohup.out은 nohup 실행 시 log파일을 생성 시킨다. 나는 이 부분에서 굉장히 빨리 로그파일을 생성할줄 알았지만 기대와 달리 상당히 오랜 시간이 걸리며 자꾸 터미널이 멈춘다. 여기서 굉장히 시간도 빼앗기고 결국 exception 터진 부분도 확인할 수가 없었다.

 

2. 서버를 내리고 java -jar 000.jar 실행  : 이번엔 서버에서 jar파일을 직접 실행하게 하고 exception터지는 것을 로컬에서 터미널 확인하는것처럼 확인을 해서 해당 오류를 해결할 수 있었다. 그런데 만약 어떤 행위를 했을때 그때 서버를 내리고 jar로 실행해서 다시 그 행위를 하도록 하고 에러를 확인하는 게 과연 맞을까? 당연히 아니다. 나는 터진 에러를 실시간으로 기록하는 파일이 있었으면 좋겠다는 생각이 들었고 해당 블로그를 보면서 로깅을 써야겠다는 마음을 먹었다. https://hudi.blog/do-not-use-system-out-println-for-logging/

 

로깅의 역사

스프링은 로그 찍는 거에 많은 변화가 있었다 

처음에 스프링은 JCL(Jakatra Commons Logging)을 사용해서 로깅을 구현했다. 과거 이야기니 간단하게 장점과 단점을 설명해본다

 

- 장점 

• Commons Logging은 adapter만 작성하면 대표적으로 Log4j, Logback의 로깅 구현을 지원한다
• 인터페이스인 LogFactory만 구현하면 얼마든지 다른 로깅 구현체로 쉽게 바꿀 수 있다
• 런타임에 실행되어 코드를 다시 컴파일하지않아도 다른 로깅 구현으로 변경이 가능하다

- 단점

• JCL이 구현체를 선택하는 시점이 런타임이라 클래스 로더에 의존적이다 
• GC가 제대로 작동하지 않은 치명적인 문제가 발생한다 

 

이런 단점을 해결하기 위해서 클래스로더 대신에 컴파일 시점에 구현체를 선택하도록 변경되었다. 이때 도입된 것은 SLF4J 이다. 

SLF4J에서는 Bridging,API,Binding 모듈을 제공하여 컴파일 시점에 로깅 구현체를 결정한다. 

스프링부트에서는 Logback이 기본으로 선택되어 있으니 Logback으로 구현체로 선택해보겠다 

 

SLF4J 그리고 Logback

출처: https://www.youtube.com/watch?v=1MD5xbwznlI&ab_channel=%EC%9A%B0%EC%95%84%ED%95%9C%ED%85%8C%ED%81%AC

• SLF4J API(인터페이스) : 로깅에 대한 추상 레이어를 제공 사용자가 이 추상메서드를 통해 로깅 코드를 작성한다 (slf4j-api)
• SLF4J Binding : SLF4J API를 로깅 구현체로 연결하는 어댑터 역할을 하는 라이브러리 , SLF4J에 구현체를 바인딩하기 위해 사용되며 여러 바인딩 중 하나만 사용 할 것 ([Logback]logback-classic / [Log4j] slf4j-log4j12)
• Logging Framework : 실제 로깅 코드를 실행할 Logging Framework를 정한다.
  ([Logback] logback-core / [Log4J] log4j-core)
• SLF4J Bridging Module : 레거시 로깅 API로의 Logger 호출을 SLF4J API로 연결하여 대신 처리할 수 있도록 하는 어댑터 역할 라이브러리 

만약 Logging Framework를 Logback에서 Log4j로 변경하고 싶다면 Binding과 framework를 바꿔주면 된다 

 

Logback 사용법

해당 springboot web 라이브러리를 가져오면 다음과 같이 로깅 관련 라이브러리들도 같이 가져오는 것을 볼 수가 있다. 

 

ch.qos.logback.classic.Level 클래스에는 로거가 사용 가능한 다섯 가지 레벨인 TRACE, DEBUG, INFO, WARN, ERROR가 정의되어 있다. 즉, Level 속성을 통해서 출력할 로그의 레벨을 조절할 수 있으며 
기본 로그의 레벨은 아래와 같으며, 지정된 레벨 이하의 메서드는 기록되지 않아요. 기본 레벨은 DEBUG에요.

TRACE < DEBUG < INFO < WARN < ERROR

예를 들어 INFO 레벨로 지정한 로거는 INFO, WARN, ERROR 로그만 기록하게 된다 

 

그냥 간단하게 필요한 부분에 적절한 레벨에 맞춰서 적어주면 된다 

  private final Logger logger = LoggerFactory.getLogger(this.getClass().getSimpleName());

  public void log(){
      logger.warn("warn");
      logger.error("error");
      logger.info("info");
      logger.debug("debug");
      logger.trace("trace");
  }

 

각각의 로깅 레벨의 역할을 알아야하는데

 

FATAL : 아주 심각한 에러가 발생한 상태를 나타낸다.

 

ERROR : 어떠한 요청을 처리하는 중 문제가 발생한 상태를 나타낸다.
프로그램 동작에 큰 문제가 발생했다는 것으로 즉시 문제를 조사해야 하는 것 (DB를 사용할 수 없는 상태, 중요 에러가 나오는 상황)

 

WARN : 프로그램의 실행에는 문제가 없지만, 향후 시스템 에러의 원인이 될 수 있는 경고성 메시지를 

나타낸다. WARN에서도 2가지의 부분에선 종료가 일어남

• 명확한 문제 : 현재 데이터를 사용 불가, 캐시값 사용 등
• 잠재적 문제 : 개발 모드로 프로그램 시작, 관리자 콘솔 비밀번호가 보호되지 않고 접속 등

INFO : 어떠한 상태 변경과 같은 정보성 메시지를 나타낸다.

 

DEBUG : 개발시 디버그 용도로 사용하는 메시지를 나타낸다.

 

TRACE : 디버그 레벨이 너무 광범위한 것을 해결하기 위해서 좀 더 상세한 이벤트를 나타낸다. 

 

위의 코드를 실행하면 다음과 같은 결과를 콘솔창에서 확인할 수 있다
(해당 실행파일은 https://github.com/minsang-alt/java/tree/main/src/main/java/com/example/javaspring/log4j 에서 확인가능하다)

 

그런데 로컬 환경에서 개발할때는 콘솔창에서 보는것이 편하고 맞는 행동이지만 배포(prod)환경에서는 콘솔창으로 본다는 것은 번거로운 행동이다 따라서 각각의 환경에 맞게 어느 곳에서는 파일, 어느 곳에서는 콘솔창에 로그를 찍는 것을 설정할 필요가 있다

 

logback-spring.xml

먼저 테스트 환경에서 파일이 아닌 콘솔창에 출력하도록 설정하는 방법을 배워보도록 한다

LOG_PATTERN에 대한 자세한 설정정보는 해당 블로그에서 볼수 있다 https://livenow14.tistory.com/64

[Logging] Logback이란?

팀의 정책을 보고 작성을 하면되고 해당 코드에 대해 설명을 해본다 

 

"[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"

=>

"[로그기록시간출력{yyyy-MM-dd HH:mm:ss}:밀리초를 4칸으로 출력] 초록색([현재thread명]) 색깔다르게(로그레벨)

로깅이 발생한 클래스 명.로깅이 발생한 메소드 명 노란색(로그가 발생한 호출지라인) - 메세지 "

 

 

이런식으로 콘솔창에서 확인할 수 있다

• profile은 !prod 이므로 해당 설정정보는 배포환경 이외에만 적용하도록 하였으며 appender의 이름은 console로 정하고 콘솔에 로그가 출력될 수 있도록 class="ch.qos.logback.core.ConsoleAppender" 해당 클래스를 사용한다 
• log_pattern을 프로퍼티로 정해둔 로그패턴을 가져다 쓴다 
• root-level 은 최상위 계층에 적용할 로그 레벨을 적용하는 것으로 INFO로 설정했으므로 해당 root-level에 들어가는 appender는 INFO이상의 레벨만을 출력한다 즉 INFO,ERROR, WARN의 로그만을 사용한다

 

다음은 로그들을 파일에서 확인하는 방법이다. 이 방법은 향후 에러가 터진 뒤에도 쉽게 백업해둔 파일을 통해 상황을 재연할 수 있으며 필요한 로그들만을 커스텀해서 관리할 수 있는 장점이 있다

 

 

ERROR 뿐 아니라 INFO, WARN도 관리할 수 있으니 추가적인 내용은 다음 링크에서 참조하면 될거같다 

https://github.com/minsang-alt/java/blob/main/src/main/resources/logback-spring.xml

 

• filter 태그에서 onMatch,onMistmatch 태그는 error에 대한 로그만을 찾겠다는 if문으로 보면된다 
• ./log/error/error-${BY_DATE}.log 파일에서 저장되고 있는 계속 축적되고 있는 로그파일은 한 파일에 계속 저장하면 용량이 커지는 문제가 생기므로 관리할 필요가 있다. 그래서 필요한 태그인 rollingPolicy를 사용한다
• maxFileSize는 한 파일에 최대 저장할 수 있는 용량을 정한다 
• maxHistory는 30일이 지나면 자동으로 파일이 삭제가 되며 일단위가 아닌 월단위로 설정할 수 있다
• totalSizeCap은 전체 용량의 크기가 3GB가 넘으면 삭제할 수 있게 한다 
  
  

프로젝트에 적용

현재 사용중인 aws ec2 프리티어는 30GB의 스토리지를 제공한다 그리고 임의로 생각한 것이지만 info는 백업파일로 둘 필요가 없고 error와 warn만을 백업파일로 관리하는게 나은 것 같다

로그파일들이 잘 저장될 수 있게 backup , log 폴더를 aws 인스턴스에 생성하고 테스트를 하기가 까다로워 바로 배포한 부분인 곳에 로그를 사용한다

더 자세한 상황은 해당 사이트에서 확인할 수 있다.

https://github.com/Beacon-2023/Beacon-backend/blob/develop/src/main/java/com/BEACON/beacon/fcm/service/FcmTokenService.java

 

앞으로 로그관리에 대해 또 궁금한 상황이 생기거나 이슈가 생기면 다시 글을 정리해 볼 생각이다  

 

 

레퍼런스

• https://gmlwjd9405.github.io/2019/01/04/logging-with-slf4j.html
• https://commons.apache.org/proper/commons-logging/?ref=sangkon.com 
• https://www.sangkon.com/hands-on-springboot-logging/
• https://spring.io/blog/2009/12/04/logging-dependencies-in-spring?ref=sangkon.com 
• https://livenow14.tistory.com/64