RCA: Bookmark with id 4738 not found after 6 retries

Overview#

What Happened#

2026-07-10 07:41–07:42 KST 사이 cupixworks-worker 의 SavePartialJsonToFileWorker 가 Bookmark 8건 (id 4738–4745) 에 대해 "not found after 6 retries" 로 실패했다. 해당 Bookmark 들은 생성 후 수 분 내 destroy 된 뒤 워커 실행 시점에는 이미 DB 에서 사라진 상태였다. 이 실패는 DWH partial JSON 파일 생성만 유실시키며, 사용자 요청 경로는 영향을 받지 않는다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-10 05:35 KST — API 에서 Bookmark id 4738 생성 (Cachable::ReviewLoad | Invalidated facility review cache on create | model=Bookmark | model_id=4738 | facility_id=19481). after_commit :save_partial_json_to_file_as_created 콜백이 SavePartialJsonToFileWorker.perform_async('Bookmark', 4738, ...) 를 enqueue.
2. 2026-07-10 05:41 KST — 같은 Bookmark id 4738 destroy (Cachable::ReviewLoad | Invalidated facility review cache on destroy | model=Bookmark | model_id=4738 | facility_id=19481). 생성 후 약 6분 만에 삭제됨.
3. 2026-07-10 07:40 KST — 워커가 enqueue 된 지 약 2시간 뒤에 처음 실행 (Retry 1 - Bookmark with id 4738 not found, retrying in 0.1 seconds). exponential backoff 로 6회 재시도 (0.1+0.2+0.4+0.8+1.6+3.2 ≈ 6.3s).
4. 2026-07-10 07:41 KST — Bookmark with id 4738 not found after 6 retries 로그와 함께 워커가 false 리턴하며 종료. 이후 4739~4745 에 대해 동일 실패가 07:42 KST 까지 연달아 발생.

Error Log#

Datadog Logs

Bookmark with id 4738 not found after 6 retries

Impact#

• Service: cupixworks-worker
• 발생 횟수: 8 (Bookmark id 4738–4745, 각 1건)
• 최초 발생: 2026-07-10 07:41 KST
• 최근 발생: 2026-07-10 07:42 KST
• 사용자 영향: 없음 (API 응답 경로와 무관한 백그라운드 CDC 워커)
• 데이터 영향: 해당 Bookmark 8건의 partial JSON 파일이 S3 로 전송되지 않아 데이터 웨어하우스에서 (created)/(updated) 이벤트가 누락됨. 다만 destroy 콜백은 인라인으로 실행되어 별도 처리됨.

Root Cause Summary#

SavePartialJsonToFileWorker 는 Bookmark after_commit :on => :create/:update 콜백에서 perform_async 로 enqueue 된다. 워커는 DB replication lag 를 견디기 위해 find_by_id 가 nil 이면 최대 6회 exponential backoff (총 약 6.3초) 로 재시도하지만, 레코드가 실제로 destroy 되어 사라진 경우에는 어떤 재시도로도 복구가 불가능하다. 이번 인시던트에서 Bookmark 4738 은 05:35 KST 에 생성되어 05:41 KST 에 삭제되었고, 워커는 07:40 KST (enqueue 후 약 2시간) 에서야 실행되어 이미 삭제된 레코드를 6회 재시도한 뒤 error 로그를 남기며 종료했다. 즉, (1) enqueue 후 워커 실행까지의 큐 지연이 레코드 lifetime(6분) 보다 훨씬 길었던 것과, (2) 실패 원인이 "삭제됨" vs "replication lag" 을 구분하지 않고 무조건 error 레벨로 로깅하는 것이 결합되어 반복적인 노이즈 에러가 발생했다.

Technical Analysis#

Code Path#

• Entry point: app/models/concerns/data_ware_house/partial_json.rb:6 — Bookmark 는 include ::DataWareHouse::Bookmark 를 통해 이 concern 을 상속하며, after_commit 콜백 3종이 등록된다.
• Enqueue: app/models/concerns/data_ware_house/partial_json.rb:123 — 생성/업데이트 시 SavePartialJsonToFileWorker.perform_async 호출.
• Failure point: app/workers/save_partial_json_to_file_worker.rb:41-60 — find_by_id 가 nil 인 경우 exponential backoff 재시도 후 error 로그.

included do
  after_commit :save_partial_json_to_file_as_created, on: :create
  after_commit :save_partial_json_to_file_as_updated, on: :update, if: :not_new_record?
  after_commit :save_partial_json_to_file_as_destroyed, on: :destroy
end

def save_partial_json_to_file_in_worker(operation: '(updated)', all_data: false, changes: nil, timestamp: nil)
  if !all_data && changes.blank? && operation == '(updated)'
    Cupix::Logger.debug('No changes detected, skipping partial JSON generation', ...)
    return nil
  end

  SavePartialJsonToFileWorker.perform_async(self.class.name, self.id, { operation: operation, all_data: all_data, changes: changes, timestamp: timestamp }.to_json)
end

model = nil

$MAX_RETRIES.times do |retries|
  model = model_class.find_by_id(id)

  if model.nil?
    delay = 0.1 * (2**retries)
    Cupix::Logger.warn("Retry #{retries + 1} - #{class_name} with id #{id} not found, retrying in #{delay} seconds", class: self.class, function: 'perform')

    sleep(delay)

    next
  else
    break
  end
end

if model.nil?
  Cupix::Logger.error("#{class_name} with id #{id} not found after #{$MAX_RETRIES} retries", class: self.class, function: 'perform')

  return false
end

• 기대 동작: after_commit :create 콜백으로 enqueue 된 워커가 곧바로 실행되어 partial JSON 을 S3 로 업로드. replication lag 로 잠깐 nil 이 나오면 6회 재시도 (~6.3s) 내에 복구.
• 실제 동작: enqueue 후 약 2시간이 지난 뒤 워커가 실행되었고, 그 사이 레코드는 이미 destroy 됨. find_by_id 는 계속 nil 을 반환하며 6회 재시도 후 error 로그로 종료. destroy 콜백 자체는 이미 05:41 KST 에 인라인으로 처리됐으므로 downstream 데이터 정합성상 큰 손실은 아니지만, (created) 이벤트는 유실됨.

Log Evidence#

Datadog query 재현:

service:cupixworks-worker "Bookmark" "4738"

Bookmark 4738 워커 실행 시퀀스 (UTC → KST 로 환산):

2026-07-09T22:40:50.707Z  warn   Retry 1 - Bookmark with id 4738 not found, retrying in 0.1 seconds
2026-07-09T22:40:52.708Z  warn   Retry 2 - Bookmark with id 4738 not found, retrying in 0.2 seconds
2026-07-09T22:40:52.708Z  warn   Retry 3 - Bookmark with id 4738 not found, retrying in 0.4 seconds
2026-07-09T22:40:52.708Z  warn   Retry 4 - Bookmark with id 4738 not found, retrying in 0.8 seconds
2026-07-09T22:40:54.710Z  warn   Retry 5 - Bookmark with id 4738 not found, retrying in 1.6 seconds
2026-07-09T22:40:56.715Z  warn   Retry 6 - Bookmark with id 4738 not found, retrying in 3.2 seconds
2026-07-09T22:41:00.716Z  error  Bookmark with id 4738 not found after 6 retries

API 측 create/destroy 로그 (service:cupixworks-api "Bookmark" "4738"):

2026-07-09T20:35:07.822Z  info  Cachable::ReviewLoad | Invalidated facility review cache on create  | model=Bookmark | model_id=4738 | facility_id=19481
2026-07-09T20:41:01.191Z  info  Cachable::ReviewLoad | Invalidated facility review cache on destroy | model=Bookmark | model_id=4738 | facility_id=19481

주요 시간 간격:

• create → destroy: 5분 53초 (레코드 lifetime)
• create/enqueue → 워커 첫 실행 (Retry 1): 2시간 5분 43초 (큐 지연)
• Retry 1 → 최종 error: 10.0초 (재시도 예산; 이론값 ~6.3s + sleep 오버헤드)

같은 시간대 다른 SavePartialJsonToFileWorker 잡들은 정상 처리되고 있어 큐가 일반적으로 밀린 상태는 아님. 워커 처리 시간은 0.005~0.24s 로 짧다 (service:cupixworks-worker "SavePartialJsonToFileWorker" status:info 22:41 UTC 창 결과):

2026-07-09T22:41:59.367Z  info  SavePartialJsonToFileWorker JID-9e5c51ce...: done: 1.017 sec
2026-07-09T22:41:57.365Z  info  SavePartialJsonToFileWorker JID-1aa1c18e...: done: 0.005 sec

동일 패턴이 다른 모델에서도 확인됨 (service:cupixworks-worker "not found after 6 retries" 24h):

2026-07-09T22:42:40Z  error  Bookmark with id 4745 not found after 6 retries
2026-07-09T22:42:32Z  error  Bookmark with id 4744 not found after 6 retries
...
2026-07-09T14:52:22Z  error  Editing with id 1265612 not found after 6 retries
2026-07-09T14:51:26Z  error  Editing with id 1265610 not found after 6 retries
2026-07-10T07:37:14Z  error  FacilityPermission with id 600444 not found after 6 retries

즉, 이 실패 모드는 Bookmark 뿐 아니라 Editing, FacilityPermission, WorkspacePermission 등 짧은 lifetime 을 갖는 모델 전반에서 재발하고 있다.

Hypotheses Considered#

Confirmed root cause: H1 — 워커 큐 지연이 레코드 lifetime 을 초과하면서 destroy 된 레코드에 대해 재시도가 무한히 nil 을 만나는 구조.

Fix Recommendation#

즉시 조치 (Critical)#

• 파일: app/workers/save_partial_json_to_file_worker.rb:44-60
• 접근 방식: find_by_id 가 nil 인 케이스에서 "삭제된 레코드" 와 "replication lag" 를 구분한다. 삭제 여부는 (a) enqueue 시점을 옵션으로 함께 전달받아 현재 시각과의 차이가 예: 60초를 넘으면 destroy 로 간주하거나, (b) 삭제된 레코드를 조회하기 위해 unscoped / soft-delete 컬럼 확인 (모델에 deleted_at 이 있는 경우), (c) 애초에 after_commit :on => :destroy 콜백에서 destroy timestamp 를 담은 payload 를 워커에 함께 넘기고 워커가 그 시각 이후 create/update 이벤트는 스킵하도록 처리하는 방식이 있다.
• 로그 레벨: 최소한 "레코드 삭제로 판단되는 경우" 는 warn (또는 info) 로 강등해 인시던트 알림/에러 대시보드를 오염시키지 않도록 한다. 현재는 delete 인지 lag 인지 구분 없이 무조건 error 로 남는다.
• 근거: 재시도 예산은 최대 6.3초로 replication lag(수백 ms) 대응용으로 설계됐지만 실패는 항상 destroy 케이스로 판별되고 있음(H1). 따라서 destroy 케이스만 별도 처리하면 에러 노이즈가 사라진다.

단기 개선 (1주 이내)#

• 파일: app/models/concerns/data_ware_house/partial_json.rb:74-90, 92-102
• 방향: after_commit :on => :create/:update 콜백이 워커에 넘기는 payload 에 record snapshot (현재 attributes) 또는 최소한 create 시각을 포함하도록 확장. 워커가 원본 레코드 조회 없이도 partial JSON 을 만들 수 있으면 destroy race 자체가 사라진다. 성능/저장소 부담이 크다면 최소한 deleted? 를 판별할 수 있는 정보만이라도 함께 전달.
• 큐 지연 관측: SavePartialJsonToFileWorker 의 enqueued_at → started_at latency 를 Datadog 메트릭으로 추가. 이번 케이스처럼 특정 잡만 2시간 지연되는 원인(예: 특정 shard/queue routing, retry set 잔여) 을 확인해야 한다. uncertain -- needs verification.

장기 개선 (재발 방지)#

• CDC (change data capture) 파이프라인을 콜백 기반 워커에서 DB WAL 기반 streaming (예: Debezium, RDS Data API, logical replication) 으로 전환 검토. 콜백 + Sidekiq 조합은 워커 큐 지연/재시도 예산에 항상 취약하다.
• 짧은 lifetime 을 갖는 리소스(Bookmark, Editing 등) 는 create 직후 destroy 되면 CDC 이벤트를 "compact" 할 수 있는 dedup 레이어를 워커 앞단에 두어, destroy 가 이미 큐잉된 create 이벤트를 취소하도록 한다.

Monitoring#

추가할 대시보드 위젯 (release dashboard timeseries 용):

• 이 워커의 "not found after N retries" error 발생률:

service:cupixworks-worker status:error "not found after 6 retries"

• 클래스별 실패 분포 확인:

service:cupixworks-worker status:error @class:SavePartialJsonToFileWorker "not found after"

• Bookmark 모델 create/destroy 균형 (짧은 lifetime 감지):

service:cupixworks-api "Cachable::ReviewLoad | Invalidated facility review cache" model=Bookmark

알림: service:cupixworks-worker status:error "not found after 6 retries" count 가 5분간 10건 초과 시 warning. 현재 상태에서는 CDC 유실을 조기 감지할 유일한 수단.

Risk Assessment#

• Risk level: low (사용자 요청 경로 영향 없음, destroy 콜백은 인라인 처리되므로 데이터 웨어하우스 정합성 손실은 create/update 이벤트의 일부에 한정)
• 예상 복잡도: standard (즉시 조치는 워커의 nil 분기 로직 확장으로 국소적; 장기 개선은 CDC 아키텍처 검토 필요)