현재 회사에서 운영 중인 프로젝트는 Logback 라이브러리를 활용하여 로그를 남기고 있습니다.
하지만 아무도 그 로그를 보지 않습니다. 로그가 제대로 남지 않거든요.
임시 방편으로 미들웨어에서 콘솔 아웃으로 로그를 확인했습니다.
하지만 로그 확인 및 관리의 불편함, 로그 이중 IO(미들웨어 콘솔 아웃, 비정상 로그 파일) 비용을 해결하기 위해 로그를 뜯어 고쳤습니다.
문제 해결을 위해 비슷한 사례를 찾아봤지만 여러 키워드로 검색해봐도 회사에서 겪고 있는 상황과 동일한 경우가 없어 무엇이 문제인지 파악이 어려웠습니다.
문제를 해결한 지금, 해결한 내용과 방법을 공유하면 혹시 비슷한 문제를 겪고 계신 분들께 도움이 되지 않을까 싶어 간만에 블로그 포스팅을 합니다!
로그 이슈 내용
로그 정상화를 위해 이슈가 있던 상황을 먼저 정리했습니다.
서버 로그 상황
- 프로젝트를 실행하면 처음에는 로그가 정상적으로 남는다.
- logback-spring.xml에서 설정한 TimeBasedRollingPolicy에 의해 매 시 정각에 로그가 한번 롤 아웃 되면 이후 실시간 로그에 스케줄링 로그만 남는다.
- 롤 아웃 된 로그 파일의 파일명에 남는 시간이 한시간 이전이다.
(예를 들어 오전 10시 정각이 되어 9시~10시 까지의 로그가 롤 아웃 되는 파일의 파일명이 8시 로그라고 남는다.) - 파일로 남는 로그에는 이런 문제가 발생하여 개발 및 운영 담당자는 미들웨어의 콘솔 아웃으로 로그를 확인한다.
logback-spring.xml의 설정 내용
- TimeBasedRollingPolicy로 매 시 정각 파일을 롤링하여 yyyyMMdd 패턴의 디렉토리에 저장한다.
- 로거는 root 로거 하나만 설정되어 있다.
- root 로거에 console과 file appender가 추가되어 있다.
- console appender는 미들웨어의 콘솔 아웃으로 연결된다.
- file appender는 서버 로그 상황에서 언급한 이슈가 있다.
문제 해결 시도
사실 기존 소스나 설정 내용을 봤을 때는 문제가 없는 것 처럼 보였기 때문에 정확히 어떤 부분을 처리해야 할 지 감이 잘 안잡혔습니다.
그래서 하나하나 시도해보며 문제를 해결해 나가보기로 했습니다.
logger 및 appender 재설정
우선 서버 로그 상황의 2번 문제를 해결하고 로그가 한 차례 롤링 된 이후에도 전체 로그가 계속 남도록 하고 싶었습니다. 혹시나 롤링 이후 로거에 문제가 생기는 것은 아닐까 하는 생각에 스케줄링 로직의 경로를 별도의 로거로 분리해봤습니다.
그리고 로컬이 아닌 서버에서는 더 이상 콘솔 아웃으로 로그를 남기지 않게 하기 위해 SpringProfile 태그를 활용하여 프로필별로 남기는 로그 appender를 다르게 설정 했습니다. 서버에 올리기 전 로컬에서도 테스트 해보기 위해 로컬 환경일 때도 File Appender를 추가해두었구요.
로컬에서는 제가 의도한 대로 로그가 작동했습니다.
OOO.log 이름으로 떨어지는 실시간 로그 파일은 한차례 롤링 된 이후에도 정상적으로 모든 로그가 찍혔고, 위 캡처와 같이 OOO.yyyyMMdd_HH24.log 이름으로 롤링 되는 로그에도 해당 시간대의 로그가 모두 남아있었습니다.
하지만 서버에서는 어떠한 문제도 해결되지 않고 동일한 문제가 계속해서 발생하고 있었습니다.
로컬에서는 정상적으로 작동하는 것을 확인했기 때문에 애플리케이션 소스나 설정의 문제는 아니라고 판단했습니다.
프로세스 별 로그 디렉토리 분리
하염없이 로그를 바라보며 로컬과 서버의 어떠한 환경 차이가 이런 문제를 만드는지 고민하던 중 서버에서 남는 스케줄링 로그의 양이 다르다는 것을 발견했습니다.
서버에서는 같은 프로젝트를 office, agency, bank, merchant라는 각기 다른 네 개의 프로필을 적용하여 독립적인 프로세스로 실행하고 있습니다. 그리고 이 모든 프로세스에서 남기는 로그의 디렉토리와 파일명이 같다는 사실이 떠올랐습니다.
로컬에서는 서버와 달리 하나의 프로세스로 프로젝트를 수행시킨다는 점에서 두 개 이상의 프로세스에서 같은 경로에 같은 이름으로 파일을 생성하는 것이 원인일 가능성이 높다고 판단했습니다.
개발 서버에서 세 개의 프로세스를 내린 뒤 로그를 지켜보았습니다.
이제서야 의도한 대로 전체 로그 파일에 전체 로그가 남기 시작했습니다.
네 개의 프로필이 각기 다른 프로세스에서 수행되어야 하기 때문에 프로필 별로 로그 디렉토리를 분리 시켜주었고, 로컬에서는 콘솔만 확인하면 되어서 파일 appender를 다시 제거해주었습니다.
프로세스 별로 로그 파일 생성에 충돌이 생기지 않도록 하니 실시간 로그도, rolling 파일의 파일명 시간과 내용도 모두 정상화 되었습니다.
하나의 프로젝트를 프로필 별로 실행하는 독립적인 네 개의 프로세스가 로그를 남기는 위치를 분리 시키는 것이 key였습니다.
로그 파일에 PID 활용하기
위 경우는 프로필별로 프로세스가 나눠지기 때문에 각 프로필에서 일어난 로그를 확인하기 쉽도록 디렉토리를 분리했습니다.
하지만 같은 문제가 있던 다른 프로젝트는 네 개의 프로세스가 각각 프로젝트를 실행하는 점은 같지만, 네 프로세스가 RoundRobin으로 요청을 처리하는 아키텍처를 갖고 있습니다.
이 경우에는 디렉토리를 나누는게 큰 의미가 없다고 생각하여 파일명에 PID를 추가하여 로그 파일 명이 유니크하게 설정하여 해결했습니다.
마무리
히스토리를 거슬러 올라가보니 수 년 전 프로젝트 초기부터 로그에 문제가 있었습니다.
그 누구도 해결하지 못했던 것인지 해결할 의지가 없어 건들지 않았던 것인지는 알 수 없으나..
앞으로 로그를 확인하고 관리하는 것이 수월해졌다는 점, 서버에서 로그를 남기는 비용을 줄였다는 점, 무엇보다 최소 5년 이상 묵은 오랜 이슈를 해결했다는 점에서 뿌듯함이 상당합니다😆
혹시나 이와 같은 문제를 겪고 계신 분들이 계시다면 문제 해결에 도움이 되면 좋겠습니다!
