최근 며칠 간 원인 파악이 굉장히 힘들었던 이슈가 한가지 있었다. 해결한 과정이 참 기묘하고 느낀게 많아서 정리해두려고 한다.
발단
우리 서비스에서는 사용자가 웹에서 코딩을 하고 실행을 요청하면 서버에서 컴파일 및 실행 후 그 결과를 보여주는 online judge 서비스를 제공한다. 그런데, 어느날 한 사용자 분께서 코드 실행을 몇 번 하다보면 어느 순간부터 갑자기 안되는 이슈가 있다고 제보해주셨다. 일부 사용자에게만 나타나는 현상이었고 나 또한 그러한 문제를 확인해볼 수 없었다. 그리고 실제 컴파일 및 실행을 담당하는 백엔드 서버(이하 실행기)에 Sentry를 연결해두었는데, 에러 알람이 뜨지 않았다. 그래서 사용자와 가장 가까운 프론트 단에서 발생한 이슈일 것이라고 생각했다.
첫번째 시도
에러 핸들링 세분화
우리 online judge 서비스가 실행 요청을 처리하는 단계는 다음과 같다.
- 세션 초기화
- 언어 설정 (C++, Python)
- 코드 전송 (프론트 -> 실행기)
- 컴파일
- 실행
- 결과 전송 (실행기 -> 프론트)
프론트 소스를 확인해보니, 사용자의 코드 전달 이후 프론트에서 실행기의 응답을 확인하는 로직이 없었다. 그러니까 실행기가 코드를 제대로 받았는지 확인하지 않고 다음 단계(컴파일)로 넘어가는 것이었다. 그래서 실행기에서 응답을 받은 뒤 "ok" 사인을 받았는지 확인하게끔 에러 핸들링을 세분화했다. 문제를 해결해주진 않겠지만 어느 단계에서 문제가 발생하는 지는 알려줄 수 있을 것이다.
그 결과
다음 날 제보자분이 에러 화면을 다시 보여주셨다. 예상대로 코드를 실행기로 보내고 나서 실행기에서 온 응답이 "ok"가 아니었다. 그러나 왜 실행기가 잘못된 응답을 보낸건지는 알 수 없었다. 나에게서는 같은 문제가 발생하지 않았기 때문에 원인 파악을 어떻게 해야할지 감이 오지 않았다. 에러 핸들링 추가 -> 사용자가 에러 확인 -> 전달받고 다시 확인 이건 대리 디버깅이나 다름이 없다. 실제 배포 중인 서비스를 가지고 이슈를 이렇게 해결하는 것은 여러가지로 무리가 있다. 시간이 너무 오래걸리고 사용자도 불편할 것이며 커밋 로그가 지저분해지는 등...
두번째 시도
HAR
크롬의 개발자 도구에서 Network 탭에 들어가면, 현재 페이지를 표시하기 위해 오간 HTTP, WebSocket 등 패킷을 확인할 수 있다. 그리고 왼쪽 상단에 빨간 원이 하나 있는데, 이는 "녹화 중"을 표시한다고 생각하면 된다. 그럼 "녹화"를 멈추면 어떻게 될까? "녹화 된" 패킷들을 HAR 파일로 저장할 수 있다.
반대로 HAR 파일을 크롬에서 불러와, "녹화 된" 패킷들을 확인해 볼 수 있다. 이번 상황처럼, 일부 사용자에게만 어떤 이슈가 나타나고 개발자가 이를 직접 확인할 수 없을 경우, 사용자에게 이렇게 HAR 파일을 부탁한다면 배포 중인 서비스에 영향을 미치지 않고 이슈 해결에 필요한 꽤 유용한 정보를 얻을 수 있다.
그 결과
다음 날 제보자분께 HAR 파일을 보내주셨다. 실행기와 주고 받은 WebSocket 패킷이 잡혀있었다. 단번에 어디서부터 잘못됐는지 확인할 수 있었다. 코드 전송 후 에러가 발생한 것이 아니라, 그 직전 언어 설정 과정에 문제가 있었던 것이었다. 그런데 문제는 서버측에서 에러 발생 시 보내는 익셉션 응답의 종류가 세분화 되어있지 않아서 정확히 무엇이 원인인지는 알아낼 수 없었다.
세번째 시도
일단 뭐라도...
이슈의 근본적인 원인이 무엇인지는 모르겠지만 일단 언어 설정 과정과 관련이 있음을 알아냈다. 그래서 프론트쪽과 실행기쪽을 모두 살펴보니, 언어 C++를 표현하는 리터럴이 맞지 않음을 확인했다. 프론트에서는 "c_cpp"를, 실행기에서는 "cpp"을 사용하고 있었다. 그런데 이게 정말 근본적인 원인이었다면 사용자마다 에러 발생 여부가 다르다는 점이 이해가 되지 않는 상황이었다. 이렇다면 모두에게서 에러가 발생해야하는데, 왜 일부에게서만 나타날까? 이게 근본적인 원인은 아닐 것 같다고 생각했지만 우선 뭐라도 고쳐보자는 생각으로 빠르게 고쳤다.
그 결과
당연히 이슈는 해결되지 않았을 것이라고 생각하고 열심히 코드를 살펴보고 있었는데 2일, 3일이 지나도 같은 이슈가 발생했다는 제보가 없었다. 진짜 literal mismatch가 이슈의 근본적인 원인이었을까? 그렇다면 왜 일부에게서만 에러가 발생했으며, 실행기에서는 잘못된 언어 요청을 전달받았으므로 에러가 났을텐데, Sentry에 에러 알림은 왜 오지 않았지? 여러모로 찜찜한 구석이 있어서 코드를 다시 살펴보았다.
결말
사건의 전말은 이러했다.
1. 백엔드 소켓 커넥션 관리
백엔드에서 소켓 커넥션을 사용자의 id와 도커 컨테이너의 id로 관리한다.
무슨 말이냐면, 사용자에게서 실행 요청이 왔을때 그 사용자의 id에 대해 도커 컨테이너가 이미 존재하는지 확인한다.
존재 한다면, 소켓 커넥션 설정(언어 설정이 포함된)을 초기화 하지 않고 그대로 가져다 쓴다.
도커 컨테이너를 생성하고 삭제하는 것에도 자원이 필요하고 시간이 어느정도 필요하기 때문에 이렇게 설정해둔 것으로 예상된다.
2. 백엔드 언어 설정 과정 에러 핸들링
백엔드에서 언어 설정 함수 중간에, 잘못된 언어로 설정 요청이 들어왔을 경우("c_cpp"), 익셉션을 던지지 않고 중간에 그냥 리턴한다. 그러니 Sentry에도 이 알림은 가지 않는다.
사실 잘못된 언어 설정 요청은 프론트에서 보내 온 것이기 때문에, 백엔드 로직의 문제로 발생할 수 있는 문제가 아니므로 익셉션을 던지지 않는 게 맞는가 싶기도 하다. 하지만 프론트에서 언어 설정 이후 서버의 응답을 확인하지 않는 것 때문에 문제가 됐다.
위 두 설계는 하나하나 따로 보았을 때 분명 별 문제 없어 보인다. 그리고 literal mismatch가 없었다면 실제로 문제가 없었을 것이다.
3. Literal mismatch
하지만 이건 개발 환경이 아니고 수많은 사용자가 있는 실제 서비스다. 그래서 사용자 마다 실행기에서 도커 컨테이너가 생성된 시점, 즉 소켓 커넥션 설정이 초기화된 시점이 다를 것이다. Literal mismatch는 원래 없었다가 예전에 프론트를 리팩토링하는 도중에 발생한 것으로 보인다.
따라서, 이전에 "cpp"로 언어를 설정한 적이 있는 사용자의 경우, 잘못된 언어 설정 요청("c_cpp")이 오더라도 언어 설정 함수는 중간에 그냥 리턴해버리고 실행 시에는 이전에 설정된 "cpp"를 가져다 쓰니 문제가 없게 된다.
하지만 "cpp"로 설정한 적이 없는 (아마도 비교적 최근에 가입한) 사용자의 경우 "c_cpp"로 언어 설정 요청을 했을 때 언어 설정 함수가 설정을 하지 않고 리턴 해버리고, 프론트에서는 이렇게 언어가 설정되지 않았다는 서버의 응답을 확인하지 않고 코드를 전송해버린다. 백엔드에서는 사용자의 언어가 설정되어 있지 않으므로 코드를 받는 과정에서 에러가 발생한다.
처음 제보된 이슈는 "잘 실행되다가 어느 순간 부터 안된다"였는데, 그렇다면 왜 처음에는 실행이 제대로 되었을까? 이건 아직도 미스테리다.
4. 문제의 Sentry
Sentry에는 에러 알림이 왜 안 왔을까. 왔어도 (2) 때문에 금방 해결되진 않았겠지만, 그래도 원인 파악이 훨씬 쉬웠을텐데!
인수인계 이후 Sentry에 등록된 계정에 변화가 생겨서인지, 처음부터 실수였는지는 모르겠지만 Sentry DSN 키가 잘못 설정되어 있었다. 역시 조금이라도 미심쩍은 부분은 무조건 확인해봐야 하는 것 같다. 아니 땐 굴뚝에 연기 날까 라는 말도 있지 않은가?
그래서...
여러모로 느낀 게 많았다. 개발 환경에서 발생하지 않는 이슈를 다룰 때 제보자와 소통하는 방법(HAR은 좋은 방법인 듯 하다), 프론트 개발자와 백엔드 개발자의 소통의 중요성(literal mismatch...), 에러 핸들링 세분화(프론트에서 이게 잘 되어 있었다면 이렇게까지 어렵진 않았을 것이다)의 중요성 등등...
