일요일 저녁 6시 28분, 메일 한 통이 왔다.
예전이었다면 이런 문제는 늘 이렇게 시작됐다. 프론트 개발자가 "로그인이 안 되는데요?"라고 말한다. 나는 로컬에 서버를 다시 켠다. 재현되지 않는다. 그럼 내가 할 수 있는 말은 두 가지뿐이었다. "한 번만 다시 해보시겠어요?" 아니면 "로그아웃했다가 다시 로그인해보세요."
운이 좋으면 그렇게 넘어갔다. 원인은 끝내 모른 채로.
이번엔 달랐다. EC2에서 클라우드 와치로 로그를 보내고 로그 그룹을 만들어 로그를 기록하도록 했기 때문이다.
메일을 받고 CloudWatch를 열었을 때, 운영 서버의 스택 트레이스가 그대로 남아 있었다. 나는 "다시 해보시겠어요?" 대신
"혹시 이 시간에 뉴진스 검색하시고 401 받으셨죠?"라고 물을 수 있었다.
그리고 그 대화 끝에서, 코드를 고치는 대신 지우는 결론이 나왔다.
먼저 로깅은 왜 필요할까?
로깅이 중요하다고 말하는 사람은 많다. 검색해보면 요청이 오는 모든 것을 기록해야 한다는 사람도 있고, 비즈니스적인 분석을 위해 유저의 액션을 로깅해야 한다는 사람들도 존재했다.
그런데 그렇게 다 남기면 정작 필요할 때 아무것도 찾지 못한다. 그래서 로깅에 관해 내가 생각하는 본래 목적을 달성하고 잘 사용할 수 있게 나만의 기준을 만들기로 결심했다.
기준은 하나로 좁혀졌다. 나중에 "서비스의 핵심 기능들 중 에러가 난다면 그때 무슨 일이 있었지?"라고 물었을 때 대답할 수 있는가. 불가능 하다면 해당 부분을 로깅했다. 아래는 그 기준으로 만든 로깅 시스템이 실제로 대답해준 것들이다.
재현되지 않는 버그
알람 메일에 딸려 온 로그는 이랬다.
ERROR c.e.global.securitycore.jwt.JWTFilter : Unexpected error in JWTFilter
java.lang.NullPointerException: Cannot invoke "Object.toString()"
because the return value of "io.jsonwebtoken.Claims.get(Object)" is null
at JWTUtil.getUsername(JWTUtil.java:50)
at JWTFilter.doFilterInternal(JWTFilter.java:62)
토큰에서 username 클레임을 꺼내는데 그게 null이라 터졌다는 뜻이다.
여기서 처음 든 생각은 "토큰이 만료돼서 클레임이 날아갔나?"였다. 하지만 그건 추측이었고, 로깅에 관한 글을 쓰면서 추측으로 결론을 내릴 수는 없었다. 다행히 필터가 그 시점의 토큰을 함께 남겨두고 있었다.
토큰을 디코딩해봤다.
// NPE가 난 토큰
{ "category": "access", "userId": 862334017546895868,
"email": "", "role": "USER", "iat": 1785058157, "exp": 1785094157 }
// 정상적으로 처리된 토큰
{ "category": "access", "userId": 863600244246139338,
"email": "", "username": "E54EB420-EEA6-4AD1-A41B-697C55DF362F",
"role": "USER", "iat": 1783735143, "exp": 1783771143 }
만료 문제가 아니었다. NPE가 난 토큰에는 username이라는 키 자체가 처음부터 없었다. 반면 정상 토큰에는 기기 UUID가 들어 있었다.
더 결정적인 건 iat였다. 1785058157, 그러니까 NPE가 터지기 1초 전에 발급된 토큰이었다. 그 시각으로 로그를 거슬러 올라갔다.
09:29:17.674 Incoming Request: URL=/user/guest, Method=POST, Body={}
09:29:18.105 bearerToken = eyJ... (username 없음)
09:29:18.109 ERROR Unexpected error in JWTFilter
빈 바디로 게스트 로그인 요청이 들어와 있었다. 정상 요청과 나란히 놓으니 차이가 분명했다.
Body={"deviceId":"***","provider":"GUEST"} → username 있음
Body={} → username 없음
username은 곧 deviceId였다. 그리고 deviceId 없이 들어온 요청에 대해 서버는 거절 대신 토큰을 발급하고 있었다. jjwt는 null인 클레임을 조용히 빼고 서명하기 때문에, 겉보기엔 멀쩡한 토큰이 하나 태어난 것이다. 그 토큰을 들고 온 다음 요청부터 필터가 터졌다.
정리하면 이렇다.
빈 바디 게스트 로그인 → username 없는 토큰 발급 → 다음 요청에서 필터 NPE → 프론트가 본 401
한 문장으로 줄이면, 서버는 잘못된 요청을 거절하는 대신 잘못된 토큰을 발급했다.
세 군데를 고쳤다
첫째, /user/guest에서 deviceId를 검증하도록 했다. 없으면 400이다. 애초에 깨진 토큰을 만들지 않는 게 근본 해결이었다.
둘째, getUsername()을 null-safe하게 바꿨다. 원래 코드는 이랬다.
String username = claims.get("username").toString();
get()이 null을 반환하면 .toString()에서 바로 터진다. 뒤에 null 체크를 붙여봐야 거기까지 도달하지 못한다. jjwt의 타입 지정 getter를 쓰면 깔끔해진다.
String username = claims.get("username", String.class);
if (username == null || username.isBlank()) {
throw new InvalidTokenException("username 클레임이 없는 토큰");
}
셋째, 필터의 catch (Exception e) 하나가 모든 걸 삼키던 구조를 나눴다. 잘못된 토큰은 WARN과 함께 401로, 정말 예상하지 못한 것만 ERROR로 남긴다.
이게 생각보다 중요했다. 클라이언트 잘못까지 ERROR로 찍히면 ErrorCount 지표가 오염되고, 정작 알람이 울려야 할 때 묻혀버린다. 로그 레벨은 취향이 아니라 알람의 정확도 문제였다.
그리고 만료기한을 지웠다
EEUM은 기기 고유값으로 로그인하는 서비스라, 프론트 개발자와 이야기하다 보니 액세스 토큰의 만료기한이 사실상 의미가 없다는 결론에 이르렀다. 어차피 만료되면 같은 기기로 다시 발급받을 뿐이다. 그래서 기존 2주 만료기한과, 만료를 검증하던 필터를 함께 삭제했다.
다만 이건 공짜가 아니다. 만료기한을 없앤다는 건 잘못 발급한 토큰을 회수할 방법도 없앤다는 뜻이다. 위에서 만들어진 username 없는 토큰들은 이미 사용자 기기에 남아 있고, 이제 스스로 죽지 않는다. 그 사용자들은 401을 받고 다시 로그인해야만 정상 토큰을 받는다.
지금은 다루는 데이터의 성격을 보고 이 트레이드오프를 받아들이기로 했다. 하지만 "위험이 없다"가 아니라 "위험을 알고 선택했다"에 가깝다.
로깅 민감 정보는 마스킹하자
여기까지가 로그가 문제를 찾아준 이야기다. 그런데 같은 로그를 다시 읽다가, 이번엔 로그 자체가 문제라는 걸 알게 됐다.
요청 바디에서 deviceId는 이미 마스킹하고 있었다.
Incoming Request: URL=/user/guest, Body={"deviceId":"***","provider":"GUEST"}
잘하고 있다고 생각했다. 그런데 바로 다음 줄이 이랬다.
JWTFilter : bearerToken = eyJhbGciOiJIUzI1NiJ9.eyJjYXRlZ29yeSI6...
토큰 전문이 INFO 레벨로 남고 있었다. 그리고 JWT의 페이로드는 암호화가 아니라 그냥 base64 인코딩이다. 디코딩하면 username, 즉 조금 전에 ***로 가렸던 그 deviceId가 그대로 나온다.
- 한 줄에서는 deviceId를 가렸고
- 다음 줄에서는 그 deviceId가 담긴 서명된 토큰을 통째로 남겼고
- 그 토큰은 만료기한이 없어서 영원히 유효하다
마스킹은 한 군데만 막아서는 의미가 없었다. 가려야 할 값이 아니라, 그 값이 흘러가는 모든 경로를 봐야 했다. 지금은 토큰 로깅을 걷어냈다.
알람이 알려주지 않는 것
두 번째는 성격이 달랐다.
알람은 왔다. ERROR 로그가 쌓여서 임계값을 넘겼고, 메일도 정상적으로 도착했다. 그런데 알람이 알려준 건 "에러가 났다" 그것뿐이었다. ErrorCount는 숫자다. 1이 0보다 크다는 것 말고는 아무 말도 하지 못한다.
새 배포의 버그인지, 외부 API 장애인지, 아니면 전혀 다른 무엇인지. 그걸 알려면 로그를 열어야 했다.
열어보니 이런 게 있었다.
09:37:40.374 URL=/
09:37:40.984 URL=/robots.txt
09:37:41.290 URL=/sitemap.xml
09:37:41.578 URL=/.well-known/security.txt
1.2초 만에 네 개. 사람이 브라우저로 낼 수 있는 간격이 아니다. 그리고 이 경로들은 우리 iOS 앱이 부를 이유가 하나도 없다. EEUM에는 robots.txt도 sitemap.xml도 없다.
이상해서 기록을 더 뒤졌다. 그러자 /nmaplowercheck가 나왔다. nmap이 서비스 종류를 판별하려고 던지는 프로브다. 그 옆에는 톰캣이 HTTP가 아닌 요청을 받고 parseRequestLine에서 뱉은 에러도 있었다. RTSP 프로토콜로 문을 두드려본 흔적이었다. 알람을 울린 ERROR의 정체가 이것이었다.
누군가 우리 서버를 훑고 있었다.
그런데 진짜 질문은 그다음이었다. 이 요청들은 대체 어떻게 여기까지 들어왔지? 모든 트래픽은 Nginx를 거치게 되어 있었고, 애플리케이션 포트인 8080이 밖에서 직접 보일 이유가 없었다.
보안 그룹을 열어봤다. 인바운드 규칙에 모든 트래픽 허용이 남아 있었다.
언제 넣었는지도 기억나지 않는 규칙이었다. 개발 초기에 뭔가 안 될 때 급하게 열어두고 그대로 잊은 것이다. 그 한 줄 때문에 8080이 Nginx를 건너뛰고 인터넷에 그대로 노출돼 있었다.
해당 규칙을 삭제하고 HTTP, HTTPS, SSH만 남겼다.
이 문제에서 인상 깊었던 건, 어떤 사용자도 이걸 신고할 수 없었다는 점이다. 서비스는 그동안 아주 멀쩡하게 동작했다. 화면이 깨진 것도 아니고 응답이 느려진 것도 아니다. 사용자 입장에서는 알아챌 방법이 없는 문제였다.
로그가 아니었다면 나도 몰랐을 것이다.
정리하며
로깅 시스템을 붙이고 나서 알게 된 건, 지표와 로그가 서로 다른 질문에 답한다는 것이었다.
지표는 무언가 잘못됐다고 말하고, 로그는 무엇이 잘못됐는지 말한다.
알람만 있었다면 나는 계속 "에러가 났대"까지만 알았을 것이다. 로그만 있었다면 그걸 열어볼 계기가 없었을 것이다. 둘이 붙어야 비로소 굴러갔다.
그리고 하나 더. 로그의 가치는 내가 그걸 전부 해석해낼 수 있다는 데 있지 않았다. 해석할 수 있는 형태로 남아 있다는 데 있었다. 위의 두 문제 모두 나 혼자 노려본다고 풀린 게 아니라, 남아 있는 기록을 놓고 사람과, 때로는 AI와 함께 뜯어보면서 풀렸다.
넘길 것이 있어야 도움도 받을 수 있다.
로그는 그 넘길 것을 만들어주는 일이었다.