재시도가 실패를 가리고 있었다

외부 연동이 잘 돌고 있는 줄 알았다. 실패 알림이 안 왔으니까. 로그를 자세히 보니 요청마다 두세 번씩 다시 보내고 있었다.

Table of contents

증상 — 재시도가 안에 숨어 있었다

호출 코드를 봤다.

function callApi($url, $data, $tries = 3) {
    for ($i = 0; $i < $tries; $i++) {
        $res = httpPost($url, $data);
        if ($res !== false) return $res;
        sleep(1);
    }
    return false;
}

세 번까지 시도하고 하나라도 성공하면 돌려준다. 부르는 쪽은 성공만 알고 몇 번 만에 성공했는지는 모른다.

실패가 성공으로 덮이면 알림이 갈 이유가 없다. 편의를 위해 넣은 재시도가 문제를 보이지 않게 만들고 있었고 조용한 것과 정상인 것이 구분되지 않는 상태였다.

시도 횟수를 돌려주고 세었다

결과에 시도 횟수를 담았다.

function callApi($url, $data, $tries = 3) {
    for ($i = 0; $i < $tries; $i++) {
        $res = httpPost($url, $data);
        if ($res !== false) {
            return ['ok' => true, 'data' => $res, 'attempts' => $i + 1];
        }
        log_message('warning', "재시도 " . ($i+1) . "/{$tries}: {$url}");
        sleep(1 << $i);
    }
    return ['ok' => false, 'attempts' => $tries];
}

attempts 가 오니 부르는 쪽이 한 번에 성공한 것과 세 번 만에 성공한 것을 다르게 기록할 수 있었다.

로그만 있으면 사람이 봐야 아니까 숫자로도 모았다.

$this->db->insert('api_stat', [
    'api_name' => $name,
    'attempts' => $r['attempts'],
    'ok'       => $r['ok'] ? 1 : 0,
    'reg_date' => date('Y-m-d H:i:s'),
]);

SELECT api_name,
       COUNT(*) AS calls,
       SUM(attempts) AS total_attempts,
       ROUND(SUM(attempts) / COUNT(*), 2) AS avg_attempts,
       SUM(ok = 0) AS failed
FROM api_stat
WHERE reg_date >= DATE_SUB(NOW(), INTERVAL 1 DAY)
GROUP BY api_name;

api_name    calls  total_attempts  avg_attempts  failed
delivery     1204            2891          2.40       12
payment      3102            3118          1.01        0

배송 연동이 평균 2.4회이고 결제는 1.01회였다. 어디에 문제가 있는지가 이 표에서 바로 나왔다.

원인은 짧은 시간 제한이었다

상대에게 물어보기 전에 우리 쪽을 봤다. 그 연동에서 curl_errno 가 28 로 떨어지고 있었는데 CURLE_OPERATION_TIMEOUTED 이다. 연결이 안 된 것이면 7 번 CURLE_COULDNT_CONNECT 가 나왔을 텐데 그것이 아니었다.

둘의 차이가 CURLOPT_CONNECTTIMEOUT 과 CURLOPT_TIMEOUT 이다. 앞의 것은 연결이 붙을 때까지고 뒤의 것은 응답을 다 받을 때까지다. 우리는 뒤의 값을 3초로 짧게 잡아 뒀는데 상대 응답이 평균 2.8초라 자주 넘겼다.

curl_setopt($ch, CURLOPT_TIMEOUT, 10);

10초로 늘리니 평균 시도가 1.05회가 됐다. 상대는 정상으로 처리하는 중인데 우리가 먼저 끊고 다시 보낸 것이었다.

재시도가 덮고 있는 동안에는 이 문제가 보이지 않았다. 숫자를 만들기 전에는 있는지조차 몰랐고 재시도로 가려진 문제는 재시도를 세기 전까지 드러나지 않는다.

재시도하면 안 되는 것

간격도 손봤다. 원래 매번 1초였는데 상대가 잠깐 과부하일 때 1초 뒤에 또 보내면 또 실패한다.

sleep(1 << $i);   // 1, 2, 4초

배씩 늘려 상대에게 회복할 시간을 준다. 여러 대가 동시에 끊기면 재시도까지 겹치므로 mt_rand 로 흔들어 섞었다.

재시도하면 안 되는 것도 갈랐다.

4xx 는 요청 자체가 잘못된 것이라 다시 보내도 같은 결과다.

if ($code >= 400 && $code < 500) {
    return ['ok' => false, 'attempts' => $i + 1, 'no_retry' => true];
}

메서드도 봐야 했다. HTTP 규격은 같은 요청을 여러 번 보낸 결과가 한 번 보낸 것과 같으면 멱등이라 부르고 PUT 과 DELETE 와 조회 계열이 거기 든다.

POST 는 거기 없다. 결제 요청이 POST 라 우리 쪽에서 응답을 못 읽었을 뿐 상대는 처리했을 수 있다.

$reqId = $orderNo . '-' . date('YmdHis');
$data['request_id'] = $reqId;

요청에 식별자를 붙여 상대가 같은 것을 두 번 받으면 한 번만 처리하게 했다. 지원하는지는 문서에서 확인했다.

if ($res === false) {
    $status = queryStatus($reqId);   // 처리됐는지 확인
    if ($status === 'done') return ok();
}

지원 안 하는 연동은 재시도 대신 상태를 조회하게 했다.

정리

• 재시도가 있으면 실패가 성공으로 덮인다. 알림이 안 온다
• 결과에 attempts 를 담아 부르는 쪽이 알게 한다
• 숫자로 모아 평균 시도를 보면 어느 연동에 문제가 있는지 나온다
• 재시도로 덮인 문제는 숫자를 만들기 전에는 안 보인다
• curl_errno 28 은 타임아웃이고 7 은 연결 실패다
• CURLOPT_CONNECTTIMEOUT 과 CURLOPT_TIMEOUT 은 재는 구간이 다르다
• 간격을 배씩 늘리고 mt_rand 로 흔들어 섞는다
• 4xx 는 다시 보내도 같으니 5xx 와 타임아웃만 재시도한다
• PUT 과 DELETE 는 멱등이라 그냥 다시 보낼 수 있다
• POST 는 아니니 식별자를 붙이거나 상태를 조회한다