[트러블슈팅] 500 에러인데 앱로그가 평화롭다고? discard packet 로그로 쫄았던 이야기

최근에 신기한 이슈를 겪었다.

어떠한 api를 실행했는데 500 에러가 떠서 문의가 왔는데, 우리 쪽에는 아예 로그조차 남지 않은 것이다.

일시적인 네트워크 장애인가 싶어서 한번 더 시도해봐도 결과는 마찬가지.

 

해당 api는 특정 혜택을 요청으로 온 가게들에게 생성시켜주는 역할을 담당한다.

예를 들어 가게A, 가게B 에 20% 할인 혜택을 부여하고 싶다! 그렇다면 해당 api를 사용하면 되는 것!

 

아무튼간에, 500 에러가 떴으니 원인을 파악하고 재발 방지를 해야되니 한번 뜯어보았다.

그런데, 로그에 아무것도 안남았는데 어떻게 파악하지?

좀 더 확인해보니 가게 개수가 좀 적을 때에는 실행도 잘되고 로그도 잘 남았다. 가게 개수가 매우 많을 때에만 발생하는 에러였다. 

어 그렇다면 그냥 서버 성능 및 cpu가 딸려서 그런거 아닌가? 하기엔 CPU는 치솟지 않았고, 로그가 남지 않았다는 것도 특이했다.

뭘까?

---

앱로그, nginx 로그 모두 조회해보자!

보통 애플리케이션 단에서 에러를 반환하면 앱로그에 남기 때문에, 평소에 아래와 같이 그라파나에서 로그를 보곤 했다.

nginx/access.log 를 제외하고 보곤 했다.

 

nginx단 로그까지 조회하면 로그가 꽤 많아 그라파나 속도가 느리다.

그래서 위와 같이 확인했었다.

 

일단 위와 같이 앱로그 상으로 조회했을 때, 해당 api 상에서 찍는 로그로 조회했을 때는 별다른 로그가 없어서

검색조건을 최대한 넓혀서 trace_id 또는 전체 기준으로 검색하되 시간범위를 좁혀서 검색했다.

 

그 결과, 아래 로그가 발견됐다.

 

WARN  c.n.p.p.s.ThriftUdpMessageSerializer     -- discard packet. Caused:too large message. size:121101

 

 

오잉??

이거 패킷이 씹혀서 아무 요청이 안온것인가?

 

결론부터 말하자면 그렇지는 않았다.

팀원분들과 함께 살펴본 결과, 위 로그는 다행히 핀포인트 agent에서 65507 bytes 이상의 패킷 사이즈를 받아들이지 못해 발생한 것으로 확인됐다. (우리 측으로 요청이 안들어온건지는 확인 필요!)

https://github.com/pinpoint-apm/pinpoint/blob/master/thrift-datasender/src/main/java/com/navercorp/pinpoint/thrift/sender/ThriftUdpMessageSerializer.java#L32

pinpoint/thrift-datasender/src/main/java/com/navercorp/pinpoint/thrift/sender/ThriftUdpMessageSerializer.java at master · pinpo

 

하마터면 요청 자체가 안온거라고 착각할뻔~

휴..

 

어? 그런데 우리는 요청 가게수만큼 처리하는 것이 아니고, chunk 단위로 나눠서 처리하는데?? chunk 단위를 더 줄여야 되나?

아니다.

핀포인트 agent 측에게 패킷을 보낼 때, spanEventLists로 이벤트를 묶어서 보내는 것으로 로그가 확인된다.

이 때, spanEventLists 에는 TSpanEvent 들이 존재하고, 이 TSpanEvent 에서 우리가 chunk 단위로 나눴던 묶음들이 확인이 됐다. 

결국 우리가 chunk 단위로 나눠서 처리한다 하더라도, 핀포인트 agent 측에서는 spanEventLists로 배치성으로 로그가 보내지게 되는 것으로 보인다. 따라서 결국 요청 사이즈 자체가 크다면, 아무리 잘게 나눈다 하더라도 핀포인트에게 보내는 패킷 유실은 존재할 수 있는 것으로 보인다. (핀포인트는 왜 이렇게 제한을 빡빡한게 둔걸까 의문이긴 하다.)

실제로, 핀포인트에서 해당 api 에러가 발생한 시점으로 추적해보면 패킷 유실되어서 추적할 수 없다고 뜬다.

---

이번에는 nginx log도 한번 확인해보았다.

nginx 단에서의 로그 조회 화면

 

하지만 실제로 nginx 단에서 조회해보면 에러로그가 남아있었다.

로그의 http_referer를 보니 사용자가 호출한 api가 맞았고, 해당 api 의 응답이 nginx proxy request timeout 설정값보다 오래 걸려서 nginx단에서 요청을 끊어버린 것이다.

 

실제로 해당 api는 특정 밸리데이션 api call 수행 후, 애플리케이션 단에서 동작을 실행한다.

그런데 특정 밸리데이션 api call 응답이 도착하지 않아 nginx 단에서 timeout이 발생해버린 것.

---

해결한 방법

nginx proxy request timeout 설정값을, 밸리데이션 api call 응답시간보다 더 크게 늘렸다.

그리고 가게 수 제한을 조금 빡빡하게 변경하였다. 위 timeout 설정값을 늘린 것 만으로 에러가 뜨는 현상은 해결이 되긴 한다. 하지만 핀포인트 상에서 udp size로 인한 패킷 유실로 로그 추적이 어렵다는 한계가 존재하므로, 가게 수 제한을 좀 더 두도록 하였다.

 

 

요청이 아예 안올 때는 nginx 로그에 status 200이 아닌 경우가 있는지 확인해봐야겠다는 생각이 들었다.

그리괴 한가지 더, 당시 discard packet 이라는 메시지에 `아, 패킷 사이즈가 문제네~` 하고 종결시켰다면 nginx read timeout 설정값이라는 근본적인 원인을 찾지 못했을 것이다. 하지만 discard packet은 핀포인트에서 받는 패킷만 유실됐을 뿐, 요청 http 패킷이 유실된 게 아니라는 점. 이 점을 알게 돼서 좀 신박했다. 해당 메시지를 추후에 발견한다 하더라도, 단순히 `http 패킷 유실이네~` 라고 단정짓지 않도록 조심해야겠다는 생각이 들었다.

 

마지막으로, 그라파나 로그 보는 실력을 좀 늘려야겠다. 앱로그만 볼 생각밖에 못했다ㅋㅋㅋ..