200을 받고 원본을 지웠다

결제 로그를 처리하는 배치가 있다. 파일로 떨어진 로그를 읽어 Redis 리스트에 넣고 워커가 꺼내서 DB 에 쓴다. 한 달쯤 잘 돌다가 정산에서 건수가 안 맞는다는 얘기가 나왔다.

Open Table of contents

코드가 이랬다
넣은 것과 처리된 것은 다르다
성공 응답이 무엇을 보장하는가
세 가지를 고쳤다
검증 — 단계별 건수 대조
정리

코드가 이랬다

foreach (glob($logDir . '/*.log') as $file) {
    $lines = file($file);

    foreach ($lines as $line) {
        $this->redis->rpush('payment_queue', $line);
    }

    unlink($file);   // 다 넣었으니 지운다
}

큐에 넣고 unlink 로 파일을 지운다. 넣는 것은 성공했고 rpush 는 실패하지 않았다. 문제는 그 뒤다.

COUNT(*) 가 원본 로그의 wc -l 보다 적었다.

넣은 것과 처리된 것은 다르다

워커는 별도 프로세스로 돈다.

while (true) {
    $line = $this->redis->lpop('payment_queue');
    if (!$line) { sleep(1); continue; }

    $data = json_decode($line, true);
    $this->paymentModel->insert($data);   // 여기서 실패하면?
}

json_decode 가 실패하거나 insert 가 실패하면 그 줄은 사라진다. lpop 은 이미 큐에서 뺐고 원본 파일은 이미 지웠다. 복구할 수 있는 데이터가 아무 데도 없다.

로그를 뒤져 보니 특정 시점에 DB 연결이 끊긴 구간이 있었다. 그때 처리 중이던 것들이 그렇게 사라졌다.

성공 응답이 무엇을 보장하는가

rpush 가 성공했다는 것은 큐에 들어갔다는 뜻이지 처리됐다는 뜻이 아니다. rpush 가 돌려주는 값 자체도 리스트의 길이다.

이것을 명확히 나눠 보면 이렇다.

단계	무엇을 보장하나
큐에 넣기 성공	큐에 있다
큐에서 꺼내기 성공	워커가 받았다
DB 쓰기 성공	저장됐다

원본을 지워도 되는 시점은 마지막 단계 이후인데 첫 단계에서 지운 것이 문제였다. 접수는 바로 끝나고 처리는 나중에 되는 구조라 두 시점이 떨어져 있다.

세 가지를 고쳤다

먼저 원본을 지우는 시점을 옮겼다.

foreach (glob($logDir . '/*.log') as $file) {
    // 지우는 대신 처리 중 디렉터리로 옮긴다
    $working = $processingDir . '/' . basename($file);
    rename($file, $working);

    foreach (file($working) as $line) {
        $this->redis->rpush('payment_queue', $line);
    }
}

rename 은 같은 파일시스템 안에서 원자적이라 중간 상태가 안 남고 중간에 죽어도 원본은 남는다. 처리 완료 뒤 별도 배치가 오래된 파일을 정리한다. 원본을 지우는 것은 무를 수 없는 동작이라 가장 마지막에 와야 했다.

다음으로 워커에서 실패한 것을 따로 담았다.

$line = $this->redis->lpop('payment_queue');
try {
    $data = json_decode($line, true);
    if ($data === null) {
        throw new Exception('json decode 실패');
    }
    $this->paymentModel->insert($data);
} catch (Exception $e) {
    // 사라지지 않게 실패 큐로 보낸다
    $this->redis->rpush('payment_queue_failed', $line);
    log_message('error', $e->getMessage() . ' | ' . $line);
}

payment_queue_failed 가 쌓이면 알림이 가게 했다. 조용히 사라지는 것보다 쌓이는 것이 낫다.

마지막으로 꺼내기와 처리를 한 번에 잃지 않게 했다.

$line = $this->redis->rpoplpush('payment_queue', 'payment_queue_working');
// ... 처리 ...
$this->redis->lrem('payment_queue_working', 1, $line);   // 처리 끝나면 제거

rpoplpush 는 꺼내는 것과 작업 리스트에 넣는 것이 한 번에 일어나므로 처리 중에 워커가 죽어도 그 줄은 payment_queue_working 에 남아 있다. 재시작할 때 그 리스트를 먼저 훑으면 된다.

검증 — 단계별 건수 대조

가장 크게 바뀐 것이 이것이다. 예전에는 잘 돌고 있는지를 알 방법이 없었다.

각 단계에서 건수를 남기게 했다.

파일에서 읽은 줄     12,847
큐에 넣은 줄         12,847
DB 에 쓴 행          12,839
실패 큐              8

이 표가 매일 나오면 8건이 어긋난 날에 바로 안다. 정산 때 알게 되는 것이 아니다.

보낸 개수가 아니라 도착한 개수를 세야 한다. 보낸 개수는 내가 한 일이고 도착한 개수가 결과다.

정리

큐에 넣기 성공은 처리 완료가 아니다 — rpush 가 돌려주는 것은 리스트 길이다
접수는 바로 끝나고 처리는 나중에 된다
원본 unlink 는 처리가 끝난 뒤로 옮긴다
그 전에는 rename 으로 옮기기만 한다 — 같은 파일시스템이면 원자적이다
꺼내기와 처리 사이에 죽으면 작업을 잃는다
rpoplpush 로 작업 중 리스트에 두고 끝나면 lrem 한다
실패한 것은 별도 실패 큐로 보내 쌓이게 한다
단계별 건수를 남기면 어긋난 날에 바로 안다
보낸 개수가 아니라 도착한 개수를 센다