성공했을 때만 기록을 남기고 있었다

고객 문의가 하나 들어왔다. 오전에 정산 정보를 조회했는데 관리자 화면의 조회 이력에 그 건이 없다는 것이었다. 처음에는 착각이겠거니 했다. 사용자 화면 세션 기록을 보니 조회 버튼을 누른 흔적이 분명히 있었다. 같은 시각 이력에는 다른 건 하나만 남아 있었다.

있었는데 없다

조회 두 건이 2초 간격으로 나갔는데, 뒤의 것은 성공 행이 남아 있었고 앞의 것은 아무것도 없었다. 성공도 실패도 아니고 그냥 없었다. 실패 행이라도 있으면 원인을 좁힐 수 있다. 아무것도 없으면 시작조차 못 한 것인지, 하다가 죽은 것인지, 아니면 기록만 못 남긴 것인지 구분이 안 된다.

기록이 언제 남는지부터 봤다

조회 흐름을 따라가니 기록이 남는 시점이 하나였다. 요청을 받아 수집기를 부르고, 수집기가 자식 프로세스를 띄워 실제로 긁고, 다 끝나면 결과를 돌려주는데 그 결과를 받는 자리에서만 행이 들어갔다.

flowchart TD
  A["조회 요청"] --> B["수집 요청 전달"]
  B --> C["수집기 · 자식 프로세스"]
  C -- "완주" --> D["결과 콜백"]
  D --> E[("조회 이력 INSERT")]
  C -- "중간에 죽음" --> X["아무것도 남지 않음"]

즉 완주하지 못하면 실패 행조차 없어서, 중간에 죽으면 그 조회는 일어나지 않은 일이 된다.

이게 이 사건의 답이었는데, 버그가 아니라 구조였고 그날 처음 생긴 것도 아니었다.

왜 그날 죽었나

남은 것이 없으니 다른 데서 근거를 찾아야 했고, 로그와 지표를 나란히 놓고 시간대를 맞췄다.

보려던 것	본 곳
수집이 시작은 했나	수집기 시작·종료 로그의 짝
요청이 전달은 됐나	요청 측의 전달 실패 로그
프로세스가 죽었나	재시작 횟수와 종료 사유 지표

수집기 파드 세 대가 40분 사이에 네 번 메모리 부족으로 강제 종료돼 있었다. 문제의 조회는 시작 로그가 찍히고 11초 뒤 파드가 죽는 구간에 정확히 걸려 있었다.

죽은 이유는 우리 쪽이 아니었다. 한 판매 채널의 응답이 오전 내내 오류를 반환했고, 그 때문에 재시도가 쌓이면서 수집이 길어졌다. 길어진 작업이 메모리에 남아 겹치다가 한계를 넘었다.

세 곳을 겹쳐 시간선을 복원했다

어느 하나만 봐서는 확정이 안 됐다. 요청을 보낸 쪽 로그, 수집기 쪽 로그, 그리고 파드 재시작 지표를 같은 시간축에 올려 놓고 겹쳤다.

10:12:00  조회 요청  -> 수집기에 "시작" 로그 없음
10:13:18  요청 측에서 전달 실패 로그가 초당 한 건씩 연속
10:19~23  파드 A 강제 종료 2회 (재시작 카운터 0 -> 1 -> 2)
10:28:43  재조회    -> 10:28:46 시작 로그 -> 11초 뒤 파드 B 종료
10:28:57  파드 B 재기동 (정상 종료 로그 없음)
10:48:34  재조회    -> 10:50:09 성공 -> 이력 행 남음

같은 시각에 성공한 조회가 하나 있었던 것이 도움이 됐다. 2초 차이로 나간 두 건 중 하나는 남고 하나는 없으니, 요청 자체나 사용자 조작을 의심할 필요가 없어졌다. 대조군이 우연히 생긴 셈이다.

재시작 카운터를 본 것이 결정적이었다. 로그는 죽는 순간을 못 남기지만 카운터는 죽었다는 사실을 남긴다. 남지 않는 것을 조사할 때는 남는 쪽에서 접근해야 한다.

타임아웃 가설을 버렸다

처음 세운 가설은 수집이 제한 시간을 넘겨 강제 종료됐다는 것이었다. 그런 경로가 실제로 코드에 있었다. 그런데 그 경로로 죽으면 부모 프로세스가 종료 로그를 남긴다. 해당 시간대에 그 로그가 0건이었으니 부모까지 함께 죽었다는 뜻이고, 그래서 이 가설은 성립하지 않았다.

가설을 버릴 근거가 로그의 부재였다는 점이 남는데, 있어야 할 것이 없다는 사실도 증거가 된다. 다만 그러려면 그 로그가 평소에는 남는다는 것을 알고 있어야 한다.

무흔적 경로가 하나가 아니었다

이 건을 계기로 같은 형태의 경로를 찾아보니 기록 없이 끝나는 길이 셋 더 있었다.

파드가 죽음        -> 콜백 없음 -> 행 없음
제한 시간 초과 종료 -> 콜백 없음 -> 행 없음
콜백 전송 실패     -> 수집은 됐는데 -> 행 없음
로그인 예외 처리   -> 캐시만 갱신 -> 행 없음

마지막 것이 특히 눈에 걸렸다. 예외를 잡아 처리하고 있으니 코드를 읽으면 다뤄지는 것처럼 보이는데, 남는 것은 임시 저장소의 상태뿐이라 나중에 조회할 방법이 없다.

사용자 화면은 계속 돌고 있었다

기록만 안 남은 것이 아니었다. 진행 중이라는 표시가 임시 저장소에 남는데 그걸 지워 줄 사람이 죽어 버리니, 사용자 화면에서는 조회가 한참 돌다가 결과 없이 끝났다.

그 표시에는 만료 시간이 한 시간으로 걸려 있었다. 실패한 뒤 한 시간 동안 같은 조회를 다시 시도해도 이미 진행 중이라고 나온다. 실패가 다음 시도까지 막고 있었다.

데이터는 무사했다

다행히 잃은 데이터는 없었다. 30분쯤 뒤 다시 조회한 건이 정상으로 끝나 값이 채워져 있었다.

그래서 이 건 자체는 조치할 것이 없었다. 문의에는 수집 서버가 재시작되면서 조회가 완료되지 못했고, 그 경우 이력에 남지 않는 구조이며, 이후 재조회로 데이터는 정상이라고 안내했다.

기록을 성공에만 걸지 않는다

남은 것은 구조에 대한 판단인데, 작업이 끝났을 때만 기록을 남기면 실패는 관측되지 않는다. 관측되지 않는 실패는 통계에도 안 잡히고, 알람도 못 걸고, 사람이 물어봐야 알게 된다.

고쳐야 할 방향은 분명했다. 시작할 때 먼저 한 줄 남기고 끝날 때 상태를 갱신하는 형태다. 그러면 시작만 있고 끝이 없는 행이 곧 미완주 신호가 된다.

비슷한 판단을 신용평가 배치에서도 했다. 거기서는 거부된 이벤트가 로그에만 남아 아무도 못 봤고, 여기서는 아예 남지 않았다. 실패를 데이터로 만들어 두지 않으면 결국 사람이 발견해야 한다는 점이 같다.

아직 기록 시점은 그대로다

기록 시점을 바꾸는 작업은 아직 안 했다. 이번 건은 데이터 손실이 없어서 급한 조치가 아니었고, 시작 시점에 행을 넣으면 지금 재사용 로직이 그 행을 어떻게 볼지부터 정해야 한다.

진행 중 표시가 한 시간 동안 재시도를 막는 문제도 남아 있다. 실패로 끝난 것을 감지해 표시를 지워 주는 쪽이 맞는데, 실패를 감지하지 못하는 것이 원래 문제라 앞의 것부터 풀어야 한다.

고친 코드는 없고 질문 하나가 남았다. 어떤 흐름을 볼 때 성공하면 무엇이 남는지만 확인하고 끝내지 않게 됐는데, 실패하면 무엇이 남는지를 같이 물어보면 대부분의 흐름에서 답이 잘 안 나온다.