RCA: ReviewPermission with id 131231 not found after 6 retries

Overview#

What Happened#

SavePartialJsonToFileWorker Sidekiq worker가 방금 생성된 ReviewPermission 레코드(id 131231~131236, 총 6건)를 find_by_id로 조회하지 못해 6회 재시도 후 최종 실패했다. 재시도 지연은 exponential backoff(0.1s → 3.2s, 총 약 6.3s)였고, 그 사이 레코드가 결국 조회 가능해지지 않아 error 로그를 남기며 종료됐다. 이로 인해 해당 ReviewPermission 6건은 CDC(partial JSON) 파이프라인에 전달되지 않아 데이터 웨어하우스 반영이 누락됐다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-17 03:54:41 KST — Sidekiq worker가 ReviewPermission#131231 조회 시작, retry 1/6 실패 (not found, retrying in 0.1 seconds).
2. 2026-07-17 03:54:41~45 KST — retry 2~6 순차 실패 (delay 0.2s → 3.2s).
3. 2026-07-17 03:54:49 KST — #131231 최종 실패, error 로그 (not found after 6 retries).
4. 2026-07-17 03:54:49~51 KST — 동일 패턴으로 #131232~#131236도 실패, 총 6건.
5. 2026-07-10 19:18:35~37 KST — 동일 워커에서 ReviewPermission#130447, #130448 실패한 이전 사례 확인 (재발 패턴).

Error Log#

Datadog Logs

ReviewPermission with id 131231 not found after 6 retries

Impact#

• Service: cupixworks-worker
• 발생 횟수: 6
• 최초 발생: 2026-07-17 03:54:49 KST
• 최근 발생: 2026-07-17 03:54:51 KST

Root Cause Summary#

ReviewPermission 모델은 DataWareHouse::PartialJson concern을 통해 after_commit :save_partial_json_to_file_as_created, on: :create 콜백을 등록하며, 이 콜백이 SavePartialJsonToFileWorker.perform_async로 Sidekiq 작업을 enqueue한다. 워커는 실행 시점에 ReviewPermission.find_by_id(id)로 원본 레코드를 조회하는데, 6회(총 약 6.3s) 재시도해도 nil이 반환됐다. tesla는 단일 MySQL 인스턴스(config/database.yml 참조 — read_replica/makara/connects_to 설정 없음)이므로 read replica lag 는 원인이 아니다. 남은 유력 가설은 (1) ReviewPermission가 짧은 수명 뒤 삭제되어(예: permissions.destroy_all — transferable/facility.rb:99,206, cyclable/user.rb:39) 워커 실행 전에 사라졌거나, (2) 매우 긴 outer transaction 안에서 생성돼 after_commit이 enqueue한 job이 실제 커밋 전에 실행됐거나 커밋 자체가 6.3s 이상 지연됐거나, (3) 트랜잭션이 롤백되어 레코드가 존재하지 않는 상태. after_commit은 outermost 커밋 이후에만 fire되므로 (2)는 커밋이 여전히 지연됐을 가능성을 시사한다. 로그상 6건이 순차 ID(131231~131236)로 동시(초 단위 내) 발생한 점, 이전 7/10일에도 순차 ID(130447/130448)에서 동일 실패가 있었던 점은 "대량 생성 후 즉시 삭제/롤백" 시나리오(가설 1/3)와 정합적이다.

Technical Analysis#

Code Path#

Entry point: app/models/concerns/data_ware_house/partial_json.rb:6-8 (after_commit 등록)

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

Enqueue: app/models/concerns/data_ware_house/partial_json.rb:116-124

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: ReviewPermission includes DataWareHouse::ReviewPermission → DataWareHouse → DataWareHouse::PartialJson.

class ReviewPermission < ApplicationRecord
  include ::Searchable::Permission
  include ::PermissionsHelper::ReviewPermission
  include ::DataWareHouse::ReviewPermission

  belongs_to :review, optional: true
  belongs_to :facility_permission, optional: true
  belongs_to :accessor, polymorphic: true

  before_create :create_facility_permission
  after_save :check_facility_permission, if: :saved_change_to_permission?

Failure point: app/workers/save_partial_json_to_file_worker.rb:41-60

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(on: :create)은 outermost 트랜잭션 커밋 이후에만 실행되므로 워커가 job을 pick up 할 때에는 레코드가 primary DB에 존재해야 한다. 최대 6.3s 지연이면 임시적인 지연/락 해제 시간으로 충분하다.

실제 동작: 6.3s 뒤에도 find_by_id가 nil 반환. tesla는 단일 MySQL이므로 replication lag 배제. 남는 시나리오는 (a) 레코드가 삭제됨(destroy_all in transferable/facility.rb:99 등), (b) 트랜잭션이 rollback되어 실제 레코드가 존재하지 않음, (c) 매우 긴 outer transaction 이 6.3s 이후에도 미커밋 상태. Sidekiq은 sidekiq_options queue: :data_changes, retry: false로 실패 시 재시도가 없으므로 이 6건은 CDC에서 영구 손실된다.

관련 파괴 경로:

if current_class.respond_to?(:permissions) && transfer_model.team_changed?
  current_class.where(facility_id: id) do |model|
    model.permissions.destroy_all
  end
end
# ...
def _remove_permissions
  permissions.destroy_all
end

model.review_permissions.destroy if model.review_permissions.exists?

Log Evidence#

Datadog 쿼리 (재현용):

service:cupixworks-worker "ReviewPermission" "not found after"

service:cupixworks-worker "131231"

Retry 시퀀스 (단일 record 131231):

2026-07-17 03:54:41  warn   Retry 1 - ReviewPermission with id 131231 not found, retrying in 0.1 seconds
2026-07-17 03:54:41  warn   Retry 2 - ReviewPermission with id 131231 not found, retrying in 0.2 seconds
2026-07-17 03:54:41  warn   Retry 3 - ReviewPermission with id 131231 not found, retrying in 0.4 seconds
2026-07-17 03:54:43  warn   Retry 4 - ReviewPermission with id 131231 not found, retrying in 0.8 seconds
2026-07-17 03:54:43  warn   Retry 5 - ReviewPermission with id 131231 not found, retrying in 1.6 seconds
2026-07-17 03:54:45  warn   Retry 6 - ReviewPermission with id 131231 not found, retrying in 3.2 seconds
2026-07-17 03:54:49  error  ReviewPermission with id 131231 not found after 6 retries

동시 발생한 순차 ID들 (모두 class:SavePartialJsonToFileWorker function:perform):

2026-07-17 03:54:49  ReviewPermission with id 131231 not found after 6 retries
2026-07-17 03:54:49  ReviewPermission with id 131232 not found after 6 retries
2026-07-17 03:54:49  ReviewPermission with id 131233 not found after 6 retries
2026-07-17 03:54:49  ReviewPermission with id 131234 not found after 6 retries
2026-07-17 03:54:49  ReviewPermission with id 131235 not found after 6 retries
2026-07-17 03:54:51  ReviewPermission with id 131236 not found after 6 retries

이전 재발 사례 (7/10):

2026-07-10 10:18:35  ReviewPermission with id 130447 not found after 6 retries
2026-07-10 10:18:37  ReviewPermission with id 130448 not found after 6 retries

주변 시간대(±5분)에서 tesla DB 관련 error(예: ActiveRecord::Deadlocked, LockWaitTimeout)는 발견되지 않음. 검색 쿼리:

service:cupixworks-worker status:error @environment:production (time window 2026-07-16 17:54:00 ~ 19:55:00 UTC)

결과: AwsTask#batch_pull! 관련 IAM 및 taskId 길이 에러만 다수 존재. ReviewPermission 이슈와 무관.

DB 설정 확인 — 단일 MySQL, replica 미사용:

development: &development
  <<: *default
  reconnect: true
  adapter: mysql2
  pool: 50
  host: <%= ENV['RAILS_DB_HOST'] || '127.0.0.1' %>
  ...

config 전체에서 replica, reading_role, writing_role, connects_to, makara 매칭 없음.

Hypotheses Considered#

Confirmed root cause: H2 또는 H3 중 하나 — "생성된 ReviewPermission 6건이 워커 실행 시점(약 6.3s 후) 이전에 삭제되었거나 트랜잭션이 rollback/미커밋 상태". 정확한 판별에는 MySQL binlog 또는 애플리케이션 트랜잭션 로그가 필요 (uncertain -- needs verification).

Fix Recommendation#

즉시 조치 (Critical)#

• app/workers/save_partial_json_to_file_worker.rb:57 — 최종 실패 로그에 판별용 컨텍스트를 추가한다: 조회 시점에 삭제 여부 확인(model_class.unscoped.find_by(id: id, deleted_at: !nil) 또는 paranoid 스코프 검사), 그리고 options_json 원본, worker jid, Time.now - created_at 같은 진단 필드를 로그에 남겨 다음 재발 시 삭제/롤백/지연을 구분할 수 있게 한다. 파괴적 코드 변경 없이 진단 향상만 수행.
• errors/의 resolution 필드는 파이프라인이 관리하므로 이 RCA에서 직접 수정하지 않는다.

단기 개선 (1주 이내)#

• app/workers/save_partial_json_to_file_worker.rb:41-60 — 재시도 반복 대신 Sidekiq 표준 재시도(sidekiq_options retry: N)와 exponential backoff로 전환하고, find_by_id nil 시 예외를 raise하여 Sidekiq이 job을 재시도 큐로 옮기도록 한다. 현재 retry: false + 인라인 sleep 방식은 프로세스 스레드를 6.3s 동안 점유하고 최종 실패 시 job이 영구 손실된다.
• ReviewPermission 생성 코드를 감사(audit): create_facility_permission before_create 콜백은 별도 트랜잭션 저장(FacilityPermission.create!)을 수행하므로, 부모 트랜잭션 지연이 커질 수 있다. bulk 생성 경로가 있다면 BulkSavePartialJsonToFileWorker처럼 배치화 검토.

장기 개선 (재발 방지)#

• CDC(partial JSON) 파이프라인의 손실 감지: 워커 최종 실패 이벤트를 별도 dead-letter 큐 또는 DWH reconciliation 잡으로 흘려보내 누락된 레코드를 주기적으로 backfill.
• after_commit + Sidekiq 패턴 대신 outbox pattern(같은 트랜잭션 내 outbox 테이블 insert → 별도 relay가 CDC 발행)로 전환 검토. 트랜잭션 커밋 시점과 레코드 가시성이 일치.

Monitoring#

• Datadog에서 워커 최종 실패 카운트 알림 (권장: 15분 window에 1건 이상):

service:cupixworks-worker "not found after 6 retries" @environment:production

• 특정 모델별 실패 비율 추적:

service:cupixworks-worker "ReviewPermission" "not found after"

• 관련 재시도 warn 로그 추이 (선행 지표):

service:cupixworks-worker @class:SavePartialJsonToFileWorker "Retry"

Risk Assessment#

• Risk level: medium — 데이터 손실(DWH 누락)이 발생하지만 사용자 대면 기능에는 즉각적 영향 없음. 재발 이력(7/10, 7/17) 존재.
• 예상 복잡도: standard — 워커 로직 개선(재시도/재큐잉)과 진단 로깅 강화는 격리된 파일 변경.