거래소 백엔드를 이루는 Spring Boot 서비스 몇 개가 ActiveMQ 와 LDAP 에 안 붙어서 출력 로그를 열었더니 오류처럼 보이는 문구가 여러 종류 섞여 있었다. 그중 어느 것이 실제 원인을 가리키는지부터 갈라야 했다.
Table of contents
Open Table of contents
증상 — 오류처럼 보이는 문구들
로그가 길었고 WARN 과 ERROR 로 찍힌 줄만 세어도 다섯 종류쯤 됐다. 전부 조사하면 시간이 얼마나 들지 가늠이 안 되는 양이었다.
그중 몇 개는 정상 동작에서도 늘 찍히는 종류일 수 있었다. 그렇다면 조사 순서를 정하기 전에 신호와 잡음을 나누는 분류가 먼저였다.
판단 기준 — 시작 문구의 유무가 단계를 가른다
두 가지 방법이 있었다. 다섯 문구를 위에서부터 차례로 조사하는 것과, 서비스가 뜨기는 했는지를 알려 주는 문구 하나부터 서비스별로 확인하는 것이다. 뒤쪽을 골랐다. 이유는 Spring Boot 가 기동을 마치면 반드시 Started WalletApplication in 12.3 seconds 를 찍어서, 그 한 줄이 조사할 곳을 절반으로 줄여 주기 때문이다. 대신 그 줄 앞에 찍힌 문구는 일단 뒤로 미루는 것을 감수했다.
셋 중 하나에는 그 문구가 있었고 나머지 둘에는 아예 없었다. Started 가 없으면 서비스 자체가 안 뜬 것이라 application.yml 을 보고, 있으면 뜬 뒤에 실패한 것이라 자격 증명과 네트워크를 본다. 문구 하나의 유무가 조사할 곳을 갈랐다.
원인 — 만료 캐시가 막던 재발급
시작은 했는데 실패한 쪽에서 다음에 나온 문구가 cached token expired, no refresh token 이었다. 그 바로 아래에는 returning cached token 이 붙어 있었다.
두 문구를 붙여 보니 우리 TokenStore 가 /var/cache/svc/token.json 에 만료된 토큰을 남겨 두고 그것을 반환하느라 재발급이 안 도는 구조였다. 결국 남아 있는 캐시 파일을 지우는 것으로 해소되는 종류였다.
신호와 잡음
남은 문구도 하나씩 열어서 무엇을 뜻하는지 확인했다. spring.jpa.open-in-view is enabled by default 는 Spring Boot 소스의 JpaBaseConfiguration 이 설정이 없으면 늘 찍는 WARN 이라 무해했다.
No active profile set, falling back to default profiles 는 -Dspring.profiles.active=prod 를 안 준 것이라 한 줄로 끝나는 것이었고, LDAP 연결 풀이 비활성인데 연결을 시도한다는 것은 우리가 못 고치는 알려진 동작이었다. 다섯 중 셋이 조치가 필요한 신호이고 둘이 정상인데 찍히는 잡음이었다.
패턴표의 값
문구와 그 뜻과 필요한 조치를 세 칸으로 묶은 표를 docs/log-patterns.md 에 남겼다. 다음에 같은 로그를 볼 때 문구를 표에서 찾으면 조치할지 무시할지가 그 자리에서 나온다.
무해한 것을 무해하다고 아는 것이 이 표의 실질인데 전부를 오류로 보면 진짜 신호가 그 안에 묻힌다. 잡음을 먼저 골라내면 남는 신호가 몇 개 안 된다.
정리
- 로그에서
Started문구의 유무가 실패 단계를 가른다 - 시작을 안 했으면
application.yml을 보고 했으면 연결과 인증을 본다 - 만료 캐시가 남아 재발급을 막을 수 있다
open-in-view경고처럼 오류로 보이는데 무해한 문구가 있다- 프로파일 미지정처럼 한 줄로 끝나는 것도 있다
- 못 고치는 잡음은 그렇다고 알아 두고 넘긴다
- 잡음을 먼저 골라내면 신호가 몇 개 안 남는다
- 문구와 뜻과 조치를 묶은 패턴표를 남긴다