Slack으로 서버 로그 모니터링하기 (Feat. Spring AOP, Logback)

프로젝트를 진행하면서 로그는 정말 중요한 요소라는 것을 깨닫고 있다. 예상치 못한 request 형태가 오거나, 서버 내부적으로 오류가 발생하면 로그를 읽고 해결을 계속하고 있기 때문이다. 하지만 ssh로 Ec2에 직접 접속해 로그 파일을 확인하는 것은 여러 불편함이 있어 이를 해결하기 위해 모니터링 툴을 만들어보기로 했다! 과정부터 결과까지 시간의 흐름 순으로 출발~

기존 로그의 문제점

ec2 접속해서 vim으로 로그 확인하기

사진 자체만으로도 문제이다. 일단 ui가 불편하고 음... 그냥 불편하다. 다른 문제점을 정리해 보자면 아래와 같다.

1. 에러 로그가 발생해도 실시간으로 확인할 수가 없다. -> 지금은 운영 전 개발용이어서 괜찮지만 실제 운영을 하게 된다면 에러가 발생하면 즉시 해결해야 하는데 위의 사진을 계속 켜놓고 확인하고 있지 않는 이상 즉시 반응할 수 없다.
2. 다른 파트 팀원이 서버의 상태를 알 수 없다. -> 프론트 개발자가 개발용 서버를 사용해 테스트를 할 때 문제가 발생했을 때 상황을 정확히 알 수 없다. 로그를 공유하면 예외처리한 메세지를 읽고 상황을 이해할 수 있다. 또한 로그 모니터링을 쉽게 할 수 있으면 보는 눈이 많기 때문에 뭔가 빨간 글씨가 생기거나 하면 문제 상황을 빠르게 공유할 수 있다.
3. 기본 로그만 출력되어 중요한 정보를 많이 알 수 없다. -> 로그를 커스텀한다면 필요한 정보를 쉽고 빠르게 얻을 수 있다.

생각한 해결 방법

문제점을 해결하기 위해서 지금 필요한 것은 로그 커스텀, 로그 모니터링 툴을 구축하는 것이었다.

로그 커스텀

로그 커스텀을 하는 방법은 AOP를 사용하면 된다. 관점 지향 프로그래밍이라는 뜻으로 핵심 기능이나 공통 기능을 분리하여 모듈화 하는 것이다. (각각의 서비스, 레포지토리, 컨트롤러 메서드에 직접 로그를 작성하는 것이 아니라 로깅 역할을 하는 모듈을 만들면 된다는 의미!)

로그 모니터링

모니터링 툴은 처음에 Grafana, Prometheus, Promtail 조합을 생각했다. 메트릭 데이터도 함께 시각화하고 로그 수집까지 진행할 계획이였다. 이 방법을 사용할 예정이다~ 라고 팀원들한테 공유를 했는데...

생각하지도 못했던 부분이었는데 팀원분께서 리소스 부족에대한 얘기를 하셔서 ec2에 접속해 free -h 명령어로 확인해 보았더니

전체 메모리 1GB..

그렇다.. 우리는 EC2 프리티어(메모리 1기가)를 사용 중이며 그 안에 Prod/Dev 서버 2개, Redis까지 실행시키고 있었다. 이미 메모리를 3분의 2 이상 사용 중이기 때문에 다른 방법을 우선 생각해 보기로 했다. 다른 방법을 탐색하던 중 전에 slack으로 모니터링 툴을 구축하는 블로그 글을 본 기억이 떠올라서 이것저것 찾아본 결과 적합하다 판단이 들어서 모니터링 툴로 slack을 선택했다! 

최종 요구사항 정리

AOP를 활용한 로그 커스텀 + slack을 활용한 로그 모니터링 툴을 구축하기에 앞서서 어떤 식으로 로그를 출력하고, 어떻게 모니터링을 할 것 인지 계획을 정리해 보았다. (이쁘게 출력하고 필요한 정보를 선택하는 이런 계획 짜는 게 은근히 오래 걸린다.)

• 유저 id 값 + request의 http 메서드와 endpoint + response를 전달하기까지 호출된 모든 메서드의 개별 실행시간
  + response까지 걸린 총 시간
  -> 어떤 유저가 무슨 요청을 했는지, 그 요청을 해결하는데 걸린 시간을 확인할 수 있다. 개별 메서드 실행 시간을 출력하는 이유는 response 전에 에러가 났다면 마지막으로 호출된 메서드가 문제라는 것을 유추할 수 있고, response까지 시간이 오래 걸린다면 어느 메서드에서 지연되는지 확인할 수 있다.
• 오류 발생 시, 발생한 메서드 이름 + 오류 메시지
  -> 오류가 발생한 지점을 빠르게 찾을 수 있다.
• 전체 로그를 전달하는 채널 + 에러만 전달하는 채널
  -> 전체 로그는 트래픽 흐름을 파악할 수 있고, 테스트 환경에서 프론트 개발자들도 함께 확인할 수 있어 편리하다.
  -> 에러 로그는 별도의 채널로 분리해 빠르게 확인할 수 있도록 한다.
  -> 전체 로그는 알림을 끄고 에러 로그는 켜놓으면 에러가 발생했을 경우 핸드폰, 노트북에서 슬랙 알림이 띵 울린다. 이래서 슬랙에 연동하면 편리한 것이라고 생각한다. 슬랙에서 제공하는 기능과 함께 사용할 수 있으니까!

AOP 활용한 로그 커스텀

LogAspect

위의 요구 사항을 바탕으로 로그 커스텀을 진행하였다.

• controller 메서드 실행 전,  request에 대한 정보를 출력
• repository / service method 실행 후,  메서드 정보 및 실행시간 출력 
• controller 메서드 return 후, 전체 실행 시간 출력
• 에러 발생 시, 에러 발생한 메서드 및 에러 메시지 출력

이 과정에서 제일 중요했던 것은 단일 요청에 대한 로그를 한 번에 모아서 확인할 수 있어야 한다는 것이었다. 즉 동시에 여러 요청이 오면 많은 로그가 생성되는데 섞이지 않았는 것을 원했다. 아래 그림과 같이 나오는 것을 원치 않은 것이다.

이렇게 나오면 안돼!!!

이 문제를 해결하기 위해서 처음 request가 왔을 때 (@Before("controllerPointcut()")에서 ) request의 속성에 StringBuilder를 저장해 주었다. -> 이후에 log가 생성되면 계속해서 request에 저장되어 있는 StringBuilder에 로그를 저장하고, response가 return or 에러가 발생했을 경우 StringBuilder에 있는 내용을 출력하도록 하였다.

StringBuidler로 선언한 logbuilder에 로그 쌓아두기

response 반환 또는 에러가 발생했을 경우 최종 출력하기

request 별 로그 수집하기 성공~

Slack 활용한 모니터링 툴

이제 AOP로 만들어낸 로그를 슬랙으로 보내야 한다. 그러기 위해서는 logback을 커스텀하여 슬랙과 연동을 해야 한다. logback-spring.xml 파일을 만들면 되는데 이것을 만드는 순간 스프링에서 갖고 있던 default 로그 설정이 다 사라지게 된다. 그렇게 되면 스프링을 실행해도 콘솔 창에 아무것도 보이지 않는 마법을 볼 수 있다. (스프링 너 나를 위해서 몰래 열심히 많은 것을 하고 있었구나..) 

기존에 default 로그 형태를 그대로 유지하고 싶다면 아래의 패턴을 사용하면 된다. 정규식 찔끔씩 고쳐가며 얻어낸 귀한 패턴이다.

<pattern>%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr([%t]){faint} %clr(%5p) %clr(%logger){cyan} %clr(:){faint} %m%n%ex
</pattern>

슬랙으로 보내는 전체 로그도 비슷하게 설정했고 슬랙에서 제공하는 slack-appender 라이브러리와 slack 앱의 webhook 기능을 통해 나름 쉽게 구현을 할 수 있었다.

모든 로그 보여주는 슬랙 화면

좀 이쁘게 꾸미고 싶은데..

기본 로그는 인텔리제이 콘솔이나 vim에서 보는 형태와 거의 비슷하게 만들었는데 에러 로그에서는 눈에 확 보였으면 좋겠다는 생각이 있어서 error용 slack-appender를 커스텀해주었다. slack-appender를 직접 열어 구조를 파악해서 필요한 컴포넌트들을 커스텀할 수 있었다. dev-all-log, dev-error-log, prod-all-log, prod-error-log 이렇게 다양하게 모니터 링 채널을 만들 예정이어서 url, env와 같은 변수들은 yml에 저장한 후, xml을 통해 로딩하는 방식을 사용했다.

slack appender 커스텀

logback-spring.xml에서 yml 값 불러오기, source에 yml에 key 값을 적어준다

logback-spring.xml의 appender 부분: <url>, <env>는 클래스의 변수 ${}에는 위의 name 값을 작성!

yml에 값 지정!!

appender에서 값들을 동적으로 사용하고 싶어서 적용하는 방법이 xml 파일 형식을 자주 사용하지 않았어서 어려웠다. 위의 예시를 참고해서 한다면 쉽게 이해할 수 있을 것이다. 나와 같은 고민을 하던 사람이 이 글을 봐줬으면 좋겠다 :]

결과

이렇게 해서 나온 결과물은~!

에러 로그 환경 분리

env 별 채널

처음에 말했듯이 all_log는 채널 알림을 끄고, error_log 채널은 알림을 켜놓고 사용 중이다. 애플워치로 에러 알림이 뜰 때마다 흠칫흠칫 하고 있다. -> 아주 효과가 좋다!

팀원분들도 너무 편리하다고 해주시고 나도 사용하면서 너무 만족하고 있다. 부가적인 이 점으로 github actions에서 ci/cd를 활용해 재배포를 했을 때 이쯤이면 스프링 켜졌나..? 하고 기다리지 않아도 된다. 슬랙에서 로그가 쫘자작 찍히기 때문에  
"Started NanalandApplication in xxxx seconds"라는 문구를 눈으로 확인할 수 있다. (ssh로 ec2에 접속한 상태로 서버를 재실행하면 항상 deploy에서 실패가 난다. 이제는 접속 안 해도 된다~)

오늘도 보람차게 해~결~