RCA: BulkSavePartialJsonToFileWorker — Cluster ids do not match after 6 retries

Overview#

What Happened#

2026-07-09 21:00 KST, cupixworks-worker Sidekiq queue data_changes 에서 BulkSavePartialJsonToFileWorker 가 방금 insert_all! 로 생성된 19 개의 Cluster 레코드(id 127698–127716)를 6 회 재시도(총 ~6.3 초) 동안 DB 에서 찾지 못하고 실패했다. 동일 시점에 12 개 이상의 다른 모델(Category, Review, Room, Bim, Pointcloud, AnnotationLayer, BimRevision 등)에서 같은 패턴이 관측되어 svc:cupixworks-worker::unknown 스코프의 서비스 저하 인시던트가 열렸다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-09 21:00:37 KST — BulkSavePartialJsonToFileWorker#perform 시작, 첫 번째 where(id: ids).count != ids.count 관측 → Retry 1 (delay 0.1s)
2. 2026-07-09 21:00:37 KST — Retry 2 (0.2s), Retry 3 (0.4s), Retry 4 (0.8s) 연속 실패
3. 2026-07-09 21:00:39 KST — Retry 5 (1.6s), Retry 6 (3.2s) 실패
4. 2026-07-09 21:00:43 KST — 6 회 재시도 모두 실패, error 로그 기록 후 return false (첫/마지막 발생, cluster first_seen/last_seen)
5. 2026-07-09 21:00:45 KST — CopyRequest#bulk_index_document 가 동일 id 범위(127698–127728) 를 index 처리 (class:CopyRequest, bulk_index_document of Cluster(127698-127728) 0 batches finished) — 이 시점에 부모 트랜잭션이 커밋됨을 시사

Error Log#

Datadog Logs

Cluster with ids [127698, 127699, 127700, 127701, 127702, 127703, 127704, 127705, 127706, 127707, 127708, 127709, 127710, 127711, 127712, 127713, 127714, 127715, 127716] does not match after 6 retries

Impact#

• Service: cupixworks-worker
• 발생 횟수: 2
• 최초 발생: 2026-07-09 21:00:43 KST
• 최근 발생: 2026-07-09 21:00:43 KST
• 동일 인시던트 스코프(svc:cupixworks-worker::unknown, id 2026-07-09-svc-cupixworks-worker--unknown-1) 에 13 개 클러스터가 묶여 있으며 최소 8 개 모델 클래스(Cluster, Category, Review, Room, Bim, Pointcloud, AnnotationLayer, BimRevision, Field 등)에서 동시에 동일한 “does not match after 6 retries” 실패 확인.

Root Cause Summary#

CopyRequest#_run_insert_all! 은 ActiveRecord::Base.transaction do ... end 블록 안에서 insert_all! 로 새 레코드를 만든 직후, 아직 커밋되지 않은 상태에서 BulkSavePartialJsonToFileWorker.perform_async(model_name, target_ids, ...) 로 Sidekiq 잡을 enqueue 한다. Sidekiq 워커는 Redis 로 즉시 잡을 받아 별도의 DB 세션으로 model_class.where(id: ids) 를 수행하는데, 부모 트랜잭션이 아직 열려 있으므로 다른 세션에서는 새 행이 보이지 않는다. Worker 는 6 회(0.1 → 3.2s exponential backoff, 총 ~6.3 초) 재시도하지만, 대량 복사 트랜잭션이 그 시간 안에 커밋되지 않아 models.count != ids.count 상태로 실패한다. 로그에서 트랜잭션 커밋 이후 실행되는 CopyRequest#bulk_index_document 가 워커 실패(21:00:43) 보다 나중인 21:00:45 에 기록된 점이 이를 뒷받침한다.

Technical Analysis#

Code Path#

• Entry point (enqueue): app/models/concerns/copy_operator/copy_request.rb:79 — run_copies_by_sql 이 ActiveRecord::Base.transaction do 로 트랜잭션을 연다.
• Insert + enqueue: app/models/concerns/copy_operator/copy_request.rb:205-211 — insert_all! 직후, 같은 트랜잭션 내부에서 perform_async 호출.
• Failure point (consumer): app/workers/bulk_save_partial_json_to_file_worker.rb:50-69 — 워커가 별도 DB 세션에서 새 id 를 읽지 못하고 6 회 재시도 후 error 로 종료.

def run_copies_by_sql(model_name = 'Facility')
  ActiveRecord::Base.transaction do
    run_copies_by_sql!(model_name)
    self.reset_handbook
    self.update(progress: 100.0)
  end

ActiveRecord::Base.connection.query_cache.clear

model_name.constantize.insert_all!(sorted)
source_ids = sorted.map { |attr| attr['sys'][:copy_origin_id] }
target_ids = self.get_inserted_ids(model_name)

if target_ids.present? && model_name.constantize.include?(DataWareHouse::PartialJson)
  BulkSavePartialJsonToFileWorker.perform_async(model_name, target_ids, { operation: '(created)', all_data: true }.to_json)
end

models = []

$MAX_RETRIES.times do |retries|
  models = model_class.where(id: ids)

  if models.count != ids.count
    delay = 0.1 * (2**retries)
    Cupix::Logger.warn("Retry #{retries + 1} - #{class_name} with ids #{ids} count does not match, retrying in #{delay} seconds", class: self.class, function: 'perform')

    sleep(delay)

    next
  else
    break
  end
end

if models.count != ids.count
  Cupix::Logger.error("#{class_name} with ids #{ids} does not match after #{$MAX_RETRIES} retries", class: self.class, function: 'perform')

  return false
end

기대 동작: perform_async 로 enqueue 된 잡이 워커에서 실행될 때 대상 레코드가 반드시 DB 에서 조회 가능해야 한다. 실제 동작: 부모 트랜잭션이 아직 커밋되지 않은 상태에서 잡이 실행되어 다른 세션에서 새 id 가 보이지 않는다. 재시도 총 ~6.3 초 안에 트랜잭션이 커밋되지 못한 배치(대규모 카피)는 최종 실패.

Log Evidence#

Datadog query:

service:cupixworks-worker "127698"

전체 재시도 시퀀스 (동일 잡, 동일 id 리스트):

2026-07-09 21:00:37  warn   Retry 1 - Cluster with ids [127698, ..., 127716] count does not match, retrying in 0.1 seconds
2026-07-09 21:00:37  warn   Retry 2 - Cluster with ids [127698, ..., 127716] count does not match, retrying in 0.2 seconds
2026-07-09 21:00:37  warn   Retry 3 - Cluster with ids [127698, ..., 127716] count does not match, retrying in 0.4 seconds
2026-07-09 21:00:37  warn   Retry 4 - Cluster with ids [127698, ..., 127716] count does not match, retrying in 0.8 seconds
2026-07-09 21:00:39  warn   Retry 5 - Cluster with ids [127698, ..., 127716] count does not match, retrying in 1.6 seconds
2026-07-09 21:00:39  warn   Retry 6 - Cluster with ids [127698, ..., 127716] count does not match, retrying in 3.2 seconds
2026-07-09 21:00:43  error  Cluster with ids [127698, ..., 127716] does not match after 6 retries
2026-07-09 21:00:45  info   index - id: 127698 - 127728                                (class:Cluster, function:bulk_operation!)
2026-07-09 21:00:45  info   bulk_index_document of Cluster(127698-127728) 0 batches finished  (class:CopyRequest)

핵심 신호:

• 재시도 delay 합 0.1+0.2+0.4+0.8+1.6+3.2 = 6.3s. Retry 1 (21:00:37) → error (21:00:43) 관측 간격과 일치.
• 워커 실패(21:00:43) 이후 21:00:45 에 CopyRequest 가 동일 id 범위를 bulk_index_document 하는데, 이 index 단계는 트랜잭션 커밋 이후에 실행되는 경로다 → 커밋 시점이 워커 실패 후에 발생.
• 같은 21:00:43 / 21:00:51 초에 8 개 이상 다른 모델 클래스(Category, Review, Room, Bim, Pointcloud, AnnotationLayer, BimRevision, Field) 에서 동일 “does not match after 6 retries” 관측 → 특정 데이터/id 문제가 아니라 공통 경로(대량 복사 트랜잭션) 문제임을 확증.

Status board 는 이 클러스터가 2026-07-09-svc-cupixworks-worker--unknown-1 인시던트의 일부이며, 지난 7 일 안에 동일 스코프(svc:cupixworks-worker::unknown) 에서 3 건이 이미 resolved 로 기록됨(2026-07-03, 07-06, 07-07) — 재발성 문제.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/concerns/copy_operator/copy_request.rb:210 의 BulkSavePartialJsonToFileWorker.perform_async(...) 호출을 트랜잭션 커밋 이후로 지연시켜야 한다. 방향:
  • 옵션 A: _run_insert_all! 를 감싸는 트랜잭션 종료 시점까지 대기 후 enqueue. 예를 들어 상위 run_copies_by_sql 에서 모델별로 (model_name, target_ids) 를 누적하고 트랜잭션 블록이 성공적으로 종료된 다음 한 번에 perform_async 를 호출.
  • 옵션 B: Rails 의 ActiveRecord::Base.connection.current_transaction 상태를 확인해 after_commit 훅(예: 임시 ActiveRecord::AfterCommitEverywhere 헬퍼 또는 컨트롤 모델의 after_commit) 에서 enqueue.
• app/repositories/concerns/bulkable_repository.rb:102-104 의 bulk_save_changes_to_partial_json 도 동일 위험을 갖는다(호출자가 트랜잭션 안에서 bulk! 를 호출하는 경우). Rails 트랜잭션 컨텍스트 안에서 enqueue 되지 않도록 동일한 after_commit 패턴으로 일반화하는 것이 안전.
• 접근 근거: Sidekiq 공식 가이드가 명시하는 "Enqueue jobs only after DB transactions commit" 문제이며, 재시도 6 회로 mitigation 이 이미 시도되었으나 대규모 복사에서는 트랜잭션 커밋이 그보다 오래 걸릴 수 있음이 로그로 확증됨.
• 구현 코드는 이 문서에서 제시하지 않음.

단기 개선 (1주 이내)#

• 재시도 실패 시 이 실패가 partial-JSON forwarding 만 놓치는지, downstream 소비자에 어떤 영향을 주는지 명시적으로 계측: 실패 카운트 + 모델별 태그된 메트릭.
• sidekiq_options 에 retry: false 가 설정되어 있음(bulk_save_partial_json_to_file_worker.rb:3). 트랜잭션 문제를 근본적으로 고친 뒤에도 일시적 커밋 지연에 대비해 소수 재시도(예: 3–5 회, Sidekiq native retry) 로 전환하는 것을 검토.
• retries 총 예산(현재 최대 ~6.3 초)을 대량 복사 트랜잭션 소요 시간의 p95 이상으로 조정하거나, 아예 후속 enqueue 방식(after_commit) 으로 대체하고 워커 내부 재시도는 제거.

장기 개선 (재발 방지)#

• 사내 공통 헬퍼(예: enqueue_after_commit(worker_class, *args)) 도입 후, 트랜잭션 컨텍스트에서 Sidekiq 잡을 던지는 모든 지점(BulkSavePartialJsonToFileWorker, bulk_save_changes_to_partial_json, 기타 factory/copy 경로) 을 이 헬퍼로 마이그레이션.
• RuboCop 사내 cop 또는 CI grep 규칙으로 “transaction do 블록 안에서의 perform_async 호출” 을 감지해 신규 도입 차단.

Monitoring#

Datadog dashboard timeseries widget 에 그대로 쓸 수 있는 쿼리:

BulkSavePartialJsonToFileWorker 재시도 소진 실패율 (건/분):

service:cupixworks-worker status:error @class:BulkSavePartialJsonToFileWorker "does not match after"

재시도 발생률(정상/비정상 경계 지표, warn):

service:cupixworks-worker status:warn @class:BulkSavePartialJsonToFileWorker "count does not match, retrying"

CopyRequest 대량 카피 활동(상관 관계):

service:cupixworks-worker @class:CopyRequest ("Begin Copying" OR "Finished Copying")

권장 알림:

• 위 첫 번째 쿼리가 5 분 창에서 5 건 초과 시 alert (현재 대량 복사 후 안정적으로 반복 발생하므로 threshold 튜닝 필요).

Risk Assessment#

• Risk level: medium — 사용자 요청 성공/실패에는 영향 없음(카피 자체는 성공). Downstream DataWareHouse partial-JSON 이 누락되어 분석/리포트 데이터 최신성 저하. 재발성(지난 7 일 동안 4 개의 동일 스코프 인시던트) 이므로 지속 노이즈 및 실제 데이터 정합성 리스크.
• 예상 복잡도: standard — 수정은 국소적(copy_request.rb:210 과 bulkable_repository.rb:102-104) 이지만, after_commit 도입 후 bulk_save_changes_to_partial_json 을 호출하는 15 개 지점의 트랜잭션 컨텍스트를 회귀 테스트해야 함.