Rebounder Tech Blog

運用している当事者が書く、本番システムの記録。

AbortSignal.timeoutをサーバー内部処理より短くすると成功した配信まで恒久失敗扱いになる

公開 読了時間 約10分執筆: Rebounder 開発チーム(当該システムの運用当事者)

※本記事にはアフィリエイトリンクを含む場合があります。内容は広告の有無に影響されません。

結論

受信側(v2)が同じリクエスト内で15秒かかる処理をしているのに、送信側(portal)のAbortSignal.timeoutが8秒だと、v2では成功していてもportal側は先にタイムアウトして同じ失敗を積み重ね続ける。

受信側(v2)が同じリクエスト内で15秒かかる処理をしているのに、送信側(portal)のAbortSignal.timeoutが8秒だと、v2では成功していてもportal側は先にタイムアウトして同じ失敗を積み重ね続ける。

結論

広告配信の連携(portal→v2のPOST)で、送信側はAbortSignal.timeout(8000)=8秒でリクエストを中断していたが、受信側(v2)は同じリクエストの中で素材の取得とGCSへの再ホスト(最大15秒)を行っていた。 v2側の処理がportal側のタイムアウトより構造的に長いため、v2が実際には配信に成功していても、portalは8秒で自分から通信を切り、その結果を「再送すれば直る一時的な失敗(transient)」として記録していた。直し方はタイムアウトの値を30秒に延ばしただけで、受信側の処理やエラー分類のロジックは変えていない。

症状

  • portalからv2への広告配信は、承認直後の即時配送でもcronの再送でも同じsendV2Delivery関数経由でPOSTする
  • v2側は受け取ったリクエストの中で、素材の署名URL(assetFetchUrl)から実体を取得し、GCSへ再ホストしてから200を返す。この取得処理には15秒のタイムアウトが設定されている
  • portal側は8秒でこのPOST自体を中断し、catchブロックに入って「ネットワーク断・タイムアウト=transient」として処理を終える
  • v2側では取得・再ホストが8秒を超えて進行中でも処理自体は止まらず、最終的に200を返すが、portalはすでに通信を切っているため誰も受け取らない
  • 再送のたびに同じ理由(8秒経過)で同じtransient失敗が記録され続け、v2側では同じ配信が重複して何度も成功している可能性がある

原因

修正前のv2-delivery.tsは、POST自体のタイムアウトを8秒に固定していた。

// v2-delivery.ts(2bed6a9f3c, 57-77行)
// v2 への POST。即時配送(承認直後・ユーザーリクエスト内)でも使われるため
// タイムアウトを明示(v2 が hang しても呼び出し元の操作を塞がない。失敗は cron 再送)。
let res: Response;
try {
  res = await fetch(`${v2Url}/api/partner/delivery`, {
    method: "POST",
    headers: {
      "Content-Type": "application/json",
      Authorization: `Bearer ${secret}`,
    },
    body: JSON.stringify(built.payload),
    signal: AbortSignal.timeout(8000),
  });
} catch (e) {
  // ネットワーク断・タイムアウト = transient(再送で回復の余地あり)
  return {
    ok: false,
    fatal: false,
    error: `network error: ${e instanceof Error ? e.message : String(e)}`,
  };
}

コメントが示す通り、8秒という値は「v2がhangしても呼び出し元の操作(即時配送時のユーザーリクエスト)を塞がない」という目的で選ばれている。これは妥当な目的だが、v2側が同じリクエストの中でどれだけの処理をしているかは考慮されていない。

v2側の受信エンドポイントは、配信POSTを受けた際に素材の取得と再ホストを自前のタイムアウト付きで行っていた。

// asset-rehost.ts(e8092c09, 116-120行)
/** 取得バイト数の実務上限(暴走入力防止)。広告クリエイティブは画像/短尺動画想定。 */
const MAX_ASSET_BYTES = 50 * 1024 * 1024; // 50 MiB

/** asset 取得のタイムアウト(内部宛先での hang や巨大取得を防ぐ)。 */
const FETCH_TIMEOUT_MS = 15_000;
// asset-rehost.ts(e8092c09, 182-192行)
// 1. 取得(transient: 署名 URL 失効・ネットワーク断 → AssetRehostError → route 5xx)。
//    redirect:'manual' でリダイレクトを追わない(公開→内部 IP への 30x 迂回を遮断、SSRF)。
let res: Response;
try {
  res = await doFetch(target, {
    redirect: "manual",
    signal: AbortSignal.timeout(FETCH_TIMEOUT_MS),
  });
} catch (cause) {
  throw new AssetRehostError("asset fetch failed", { cause });
}

v2のFETCH_TIMEOUT_MS(15秒)は、素材取得だけにかかる時間であり、portalからのPOSTを受理してからレスポンスを返すまでの総時間はこれにさらにGCSアップロードの時間が加わる。portal側の8秒は、この総時間より構造的に短かった。

v2側が8秒を過ぎてから実際に200を返しても、portal側はfetchをすでに中断しているため、res.okの分岐には一切到達しない。この分岐には、v2からの200応答を使ってK1広告主IDの書き込みを行う処理がある。

// v2-delivery.ts(cf19ac2424, 90行〜)
if (res.ok) {
  // K1 自動紐付け: v2 が確定した advertiser UUID を companies.kimiteras_v2_advertiser_id ...

タイムアウトでcatchに落ちた場合、この分岐自体が実行されない。さらに、outboxワーカー側では配信が"sent"状態になった初回だけ、実際に映り始めた時点を契約に記録する処理を呼んでいる。

// outbox-worker.ts(45339105c2, 88-100行)
await admin.from("sync_outbox").update(patch).eq("id", row.id);

// 「実際に映り始めた」瞬間を契約へ刻む(初回のみ・0095)。承認時点ではなく v2 が受理した
// この時点なのは、承認しても連携が失敗していれば映っていないため。掲載開始日(period_start)
// との差がそのまま「課金しているのに映っていない期間」になる。best-effort(配信は成立済み)。
if (d.status === "sent" && row.kind === "delivery") {
  try {
    const payload = (row.payload ?? {}) as { placement_id?: string | null };
    await markDeliveryStarted(admin, payload.placement_id ?? null);
  } catch (e) {
    console.error("[outbox] failed to mark delivery start:", e);
  }
}

d.statusはsendV2Deliveryの結果から決まるため、transient(タイムアウト含む)の間は"sent"にならず、markDeliveryStartedは一度も呼ばれない。この関数自体の役割は、delivery_started_atという「実際に映り始めた日時」を契約に一度だけ刻むことだ。

// delivery-schedule.ts(4257484719, 51-75行)
/**
 * 実配信の開始を契約へ記録する(初回のみ・不変)。
 * 呼ぶのは outbox ワーカーが v2 への配信成功を確認した瞬間=「本当に映り始めた」時点。
 * 承認時点ではなく配信成功時点なのは、承認しても連携が失敗していれば映っていないため。
 * best-effort(失敗しても配信は成立している)。
 */
export async function markDeliveryStarted(
  admin: Admin,
  placementId: string | null | undefined
): Promise<void> {
  if (!placementId) return;
  const { data: placement } = await admin
    .from("placements")
    .select("contract_id")
    .eq("id", placementId)
    .maybeSingle();
  const contractId = (placement?.contract_id as string | null) ?? null;
  if (!contractId) return;
  // 初回だけ書く(is null 条件)=差し替え・再配信で上書きしない。
  await admin
    .from("contracts")
    .update({ delivery_started_at: new Date().toISOString() })
    .eq("id", contractId)
    .is("delivery_started_at", null);
}

結果として、v2側では実際に配信が成功していても、portal側の早すぎるタイムアウトのせいでmarkDeliveryStartedが呼ばれる条件(d.status === "sent")に一度も到達せず、「課金しているのに映っていない期間」を測るためのdelivery_started_atが永久に刻まれないままになる。

直し方

修正は送信側のタイムアウト値を30秒に延ばし、その理由をコメントに残しただけだった。

// v2-delivery.ts(cf19ac2424, 64-88行)
// v2 への POST。即時配送(承認直後・ユーザーリクエスト内)でも使われるため
// タイムアウトを明示(v2 が hang しても呼び出し元の操作を塞がない。失敗は cron 再送)。
let res: Response;
try {
  res = await fetch(`${v2Url}/api/partner/delivery`, {
    method: "POST",
    headers: {
      "Content-Type": "application/json",
      Authorization: `Bearer ${secret}`,
    },
    body: JSON.stringify(built.payload),
    // v2 は assetFetchUrl の取得(timeout 15 秒)+ GCS 再ホストを**リクエスト内で**行うため、
    // 大きめの動画素材では正常処理が 8 秒を構造的に超える。送り側が先に切ると「v2 では配信
    // 成功したのに portal は failed → 毎回タイムアウト → dead」になり、さらに 200 応答を
    // 読めないため K1 advertiserId ライトバックと delivery_started_at 刻印が永久に走らない。
    signal: AbortSignal.timeout(30_000),
  });
} catch (e) {
  // ネットワーク断・タイムアウト = transient(再送で回復の余地あり)
  return {
    ok: false,
    fatal: false,
    error: `network error: ${e instanceof Error ? e.message : String(e)}`,
  };
}

v2側のFETCH_TIMEOUT_MS(15秒)や、取得→再ホスト→応答という処理の流れは一切変えていない。変えたのは、送信側が「相手の処理に必要な時間」を自分のタイムアウトに正しく反映させた、その1点だけだ。タイムアウト・ネットワーク断を同じtransientとして扱う分類ロジックも変えていないため、同じ原因で今後また失敗が起きれば、同じく自動再送の対象になる。

再発防止

根拠ファイルには、この種のタイムアウト不整合を検知する仕組み(送信側・受信側のタイムアウト値を比較するテストや契約チェック)についての記述は無い。この修正は9件の欠陥をまとめて棚卸しした監査コミットの一部であり、個別の再発防止策は明記されていない。

構造的に見れば、この不整合が長く気づかれなかったのは、タイムアウトと通常のネットワーク断を同じ「再送すれば直る一時的な失敗」として扱っていたためだ。中断の理由を区別して記録していれば「8秒ちょうどで毎回失敗している」という偏りが見え、v2側の処理時間との比較に気づけた可能性がある。別リポジトリの2つのサービスが1つのリクエストで同期的に重い処理をやり取りするとき、呼び出し元のタイムアウトは「相手が応答しない場合の上限」ではなく「相手が正常に完了するまでに実際にかかる時間の上限」として設計する必要がある。

よくある質問

Q1v2側では配信は成功していたのに、なぜportal側はエラーとして記録したのですか?

portalはAbortSignal.timeout(8000)で8秒経過すると自分からfetchを中断し、その結果を「ネットワーク断・タイムアウト=再送すれば直る一時的な失敗(transient)」として記録していました。実際にはv2側のレスポンスがまだ返っていないだけで、v2内部の処理(最大15秒)は裏で正常に完了していました。portalは中断した時点のソケットしか見ていないため、v2が後から200を返しても誰も受け取っていません。

Q2タイムアウトを長くするだけで直るなら、なぜ最初から長くしていなかったのですか?

根拠ファイルにその経緯は残っていません。確認できるのは、8秒という値が「v2がhangしても呼び出し元の操作を塞がない」という別の目的(即時配送時のユーザー操作を待たせない)のために設定されていたことだけです。v2側が同じリクエスト内でasset取得+GCS再ホストという重い処理をしている事実と、その処理に要する時間(15秒)を、送信側のタイムアウト設計が考慮していませんでした。

Q3このタイムアウトのずれは、エラー画面やアラートで気づけましたか?

気づけません。タイムアウトも通常のネットワーク断も同じtransient扱いで、cronによる自動再送の対象になるだけです。再送のたびに同じ理由(8秒経過)で同じ失敗を繰り返すため、ログ上は「時々失敗する配信」に見え、v2側で実際には何度も重複して配信成功していたことまでは追えません。

確認した環境

  • kimiteras-portal: next 16.2.7 / @supabase/supabase-js ^2.106.2
  • 送信側(portal)AbortSignal.timeout修正: 2026-07-25
  • 受信側(v2)FETCH_TIMEOUT_MS=15_000 実装: コミットe8092c09時点で既存

この記事の根拠

  • TypeScriptファイル 57〜77行目コミット 2bed6a9
  • TypeScriptファイル 64〜88行目コミット cf19ac2
  • TypeScriptファイル 116〜120行目コミット e8092c0
  • TypeScriptファイル 182〜192行目コミット e8092c0
  • TypeScriptファイル 88〜100行目コミット 4533910
  • TypeScriptファイル 51〜75行目コミット 4257484

本文の主張は、上の記録に書かれていることだけです。運用しているリポジトリは非公開のため リンクは張れませんが、どのファイルの何行目を、どのコミット時点で見て書いたかは 記事ごとに残しています。推測で書いた箇所はありません。