웹서비스 백단에서 발생되는 로그를
gpdb로 insert하는데 간헐적으로 insert가 잘 안되는 이슈가 발생했다.
# 분석과정
기존의 구조 파악
- api 서버에서 Debug 로그를 읽어 정시마다 롤링 로그를 생성 시킨다 (logback 활용)
- 생성된 롤링 로그를 cron에서 매시 5분마다 한시간전의 log파일을 gpdb로 insert
실제 서버 확인후 차이점
- api 에서 로그를 롤링하는데 시간이 제각각이다
> 14:00, 15:00 이렇게 들어가야하는데 14:55 15:23 ... 등등등
- 하지만 한시간 전파일에 대한 검색이 진행됨으로 앞자리만 현재시간 대비 전시간이면 되는데 이상하다.
- Debug 로그파일 실제 생성시간을 모니터링
#문제점 발견
- 파일 생성 시간과 생성 시점이 다르다
> 15:23 로그가 16:40 에 생성된다
- 로그파일이 크지도 않는데 이상하여 롤링에 사용하는 class 를 확인해보니 메커니즘의 문제였다
##TimeBaseRollingPolicy 의 메커니즘
- 로그파일 생성시점이 다음 시간에 대한 로그가 발생했을 시점으로 매시 5분마다 수집하는 크론과 차이점이 존재한다.
> Debug 로그를 롤링할때의 시점은 로그가 ‘발생’ 했을때 한시간 전 로그에대한 파일을 만든다 > 13:45 에 Debug로그가 발생했을때 롤링로그가 생성되려면 13시가 아닌 다른 시간의 timestamp가 찍힌 로그가 들어와야 롤링로그가 생성된다는 말이다
> 로그가 공백시/분 없이 발생하는 환경에서는 문제가 없었지만 사용자가 별로 없는 해당 웹서비스에서는 시간차가 존재함으로
예상했던것 처럼 생성시점의 문제가 발생한다.
#문제 해결
logback에서 옵셔널을 줄수있나 확인해봤지만 찾지못해
기존 insert 크론에 유효처리를 진행했다.
- 매시5분에 Debug로그에 전시간대에 대한 로그가 남아있다면 로그를 수집하여 롤링로그 tmp 파일을 생성한 뒤 gpdb로 insert 시킨다.
간만에 좀 재밌었다 🙂
'개발일지✏️' 카테고리의 다른 글
개발과 운영분리가 명확하지않은 프로젝트 (0) | 2021.12.28 |
---|