먼저 DailyRollingFileAppender를 사용하는 multiple process에서 동일한 파일들에 작업을 하는 행위 자체가 해서는 안되는 것입니다.
그런데 현상이 좀 희안해서, 혹~시 복합적인 문제일까 싶어서 분석을 해봤습니다.
두괄식으로 말씀드리자면, 복합적인 문제는 아니고 순전히 다중 tomcat 인스턴스 문제입니다.
롤링된 로그 파일들의 내용이 파일명에 기록된 일시의 다음날 로그로 쌓여있습니다.(하루씩 밀려있습니다.)
배포를 수행하면 배포 시점에 pc_all.log.2019-01-01의 write가 끊깁니다. 때문에 배포한 날은 배포 시점 이후의 로그가 날아가게 됩니다.
원인
DailyRollingFileAppender는 아래처럼 동작합니다. pc, 01-02 00:00:00 기준으로 설명하겠습니다.
pc_all.log 파일을 닫고
pc_all.log.2019-01-01 파일이 존재하면 지우고
pc_all.log 명으로 파일을 다시 얻어와서 pc_all.log.2019-01-01으로 mv
새로 쓸 오늘의 pc_all.log 파일을 세팅
문제는 tomcat 인스턴스가 4개라서, 위의 작업이 4번 일어난다는 점입니다.
그 결과 아래와 같은 현상이 벌어집니다.
참고로 write를 하고 있는지 여부는 lsof 명령어로 확인했습니다.
1,2번째로 작업한 tomcat 인스턴스
mv 했던 pc_all.log.2019-01-01는 다음 작업들이 지워버리고, 새로 만든 pc_all.log는 pc_all.log.2019-01-01로 mv 당해버립니다.
mv 당한 pc_all.log.2019-01-01 마저도 다음 작업들이 지워버립니다.
그 결과, 1,2번째로 작업한 tomcat 인스턴스들은 삭제된 pc_all.log.2019-01-01를 참조하고 있게 되고, 로깅을 못하게 됩니다.
3,4번째로 작업한 tomcat 인스턴스
3번째로 작업한 tomcat 인스턴스는 pc_all.log를 만들고 4번째 인스턴스로 인해 pc_all.log.2019-01-01로 mv당합니다.
때문에 3번째 tomcat 인스턴스는 pc_all.log.2019-01-01에 오늘의 로그를 계속 쓰게 됩니다.
마지막으로 작업한 4번째 tomcat 인스턴스는 본인이 만든 pc_all.log를 mv시킬 다음 작업이 존재하지 않으므로, pc_all.log에 오늘의 로그를 쓰게 됩니다.
서버 배포가 수행됐다면 또 달라짐
만약 서버 배포를 수행한다면, 톰캣 인스턴스들이 재시작되며 로그 파일을 새로 잡기 때문에 pc_all.log.2019-01-01의 write가 끊기고, pc_all.log에 모든 인스턴스들이 write를 시작합니다.
하지만 로그 롤링이 이상하게 동작하기 때문에, 이 시점의 pc_all.log는 모두 유실됩니다.
결론
pc의 예시를 들었지만, mobile, api 등 tomcat 인스턴스가 여러개고 동일 파일에 로깅을 하는 경우에는 모두 동일한 현상이 일어납니다.
중요한 에러 로그들은 nelo에 기록되기 때문에 큰 문제는 없어보입니다만, 근 시일 내에 다시 살펴볼 가능성이 꽤 높은 배포 시점 이후, 당일의 로그가 유실된다는게 좀 걸립니다.
그 외에도 로그 파일 명과 내용의 일자가 하루씩 차이난다는 것도 히스토리를 모르는 사람이 보면 매우 이상하게 느껴집니다.
때문에 해결책을 고민해보자면,
단기 해결책
tomcat 인스턴스들이 각기 다른 로그 파일명을 사용하도록 합니다.
롤링도 마찬가지로 각기 다른 파일명으로 수행합니다.
기존에는 결과적으로 1개 인스턴스의 로그만이 남으므로, 단기 해결책으로 인해 로그가 쪼개져서 보기 힘들어졌다고 할 수는 없습니다.
나눠져있는 파일을 합치는건 로깅 일시 정렬 문제가 있어서 힘들 것 같습니다.
장기 해결책
tomact 인스턴스 여러개가 성능상의 이점이 없다는 전제 하에서, 4개 인스턴스를 1개 인스턴스로 줄입니다.
먼저 DailyRollingFileAppender를 사용하는 multiple process에서 동일한 파일들에 작업을 하는 행위 자체가 해서는 안되는 것입니다. 그런데 현상이 좀 희안해서, 혹~시 복합적인 문제일까 싶어서 분석을 해봤습니다. 두괄식으로 말씀드리자면, 복합적인 문제는 아니고 순전히 다중 tomcat 인스턴스 문제입니다.
PC WEB, 01-02 00:00:00 기준으로 설명하겠습니다.
현상
원인
DailyRollingFileAppender는 아래처럼 동작합니다. pc, 01-02 00:00:00 기준으로 설명하겠습니다.
문제는 tomcat 인스턴스가 4개라서, 위의 작업이 4번 일어난다는 점입니다. 그 결과 아래와 같은 현상이 벌어집니다.
1,2번째로 작업한 tomcat 인스턴스
mv 했던 pc_all.log.2019-01-01는 다음 작업들이 지워버리고, 새로 만든 pc_all.log는 pc_all.log.2019-01-01로 mv 당해버립니다. mv 당한 pc_all.log.2019-01-01 마저도 다음 작업들이 지워버립니다.
그 결과, 1,2번째로 작업한 tomcat 인스턴스들은 삭제된 pc_all.log.2019-01-01를 참조하고 있게 되고, 로깅을 못하게 됩니다.
3,4번째로 작업한 tomcat 인스턴스
3번째로 작업한 tomcat 인스턴스는 pc_all.log를 만들고 4번째 인스턴스로 인해 pc_all.log.2019-01-01로 mv당합니다. 때문에 3번째 tomcat 인스턴스는 pc_all.log.2019-01-01에 오늘의 로그를 계속 쓰게 됩니다.
마지막으로 작업한 4번째 tomcat 인스턴스는 본인이 만든 pc_all.log를 mv시킬 다음 작업이 존재하지 않으므로, pc_all.log에 오늘의 로그를 쓰게 됩니다.
서버 배포가 수행됐다면 또 달라짐
만약 서버 배포를 수행한다면, 톰캣 인스턴스들이 재시작되며 로그 파일을 새로 잡기 때문에 pc_all.log.2019-01-01의 write가 끊기고, pc_all.log에 모든 인스턴스들이 write를 시작합니다. 하지만 로그 롤링이 이상하게 동작하기 때문에, 이 시점의 pc_all.log는 모두 유실됩니다.
결론
pc의 예시를 들었지만, mobile, api 등 tomcat 인스턴스가 여러개고 동일 파일에 로깅을 하는 경우에는 모두 동일한 현상이 일어납니다.
중요한 에러 로그들은 nelo에 기록되기 때문에 큰 문제는 없어보입니다만, 근 시일 내에 다시 살펴볼 가능성이 꽤 높은 배포 시점 이후, 당일의 로그가 유실된다는게 좀 걸립니다.
그 외에도 로그 파일 명과 내용의 일자가 하루씩 차이난다는 것도 히스토리를 모르는 사람이 보면 매우 이상하게 느껴집니다.
때문에 해결책을 고민해보자면,
단기 해결책
tomcat 인스턴스들이 각기 다른 로그 파일명을 사용하도록 합니다. 롤링도 마찬가지로 각기 다른 파일명으로 수행합니다. 기존에는 결과적으로 1개 인스턴스의 로그만이 남으므로, 단기 해결책으로 인해 로그가 쪼개져서 보기 힘들어졌다고 할 수는 없습니다.
나눠져있는 파일을 합치는건 로깅 일시 정렬 문제가 있어서 힘들 것 같습니다.
장기 해결책
tomact 인스턴스 여러개가 성능상의 이점이 없다는 전제 하에서, 4개 인스턴스를 1개 인스턴스로 줄입니다.