RCA: Floorplan with ids [6434, 6435, 6436, 6437] does not match after 6 retries

Overview#

CopyRequest 워크플로가 하나의 outer ActiveRecord::Base.transaction 안에서 child model 을 insert_all! 로 삽입하고 즉시 BulkSavePartialJsonToFileWorker.perform_async 를 enqueue 하면서, Sidekiq worker 가 커밋 전 스냅샷을 조회해 6 회 재시도(총 6.3 s backoff) 안에 행을 보지 못하고 에러로 종료된 사례.

What Happened#

2026-07-09 21:00:43 KST(eu-central-1, production, tenant cupix), CopyRequest#run_copies_by_sql 이 실행 중이던 outer transaction 내부에서 Floorplan 등 다수 child model 에 대해 insert_all! 후 BulkSavePartialJsonToFileWorker.perform_async 를 호출했다. Worker 는 다른 DB connection 에서 Model.where(id: ids) 를 수행하지만 outer transaction 이 아직 커밋되지 않아 대상 행이 보이지 않았고, 6 회 지수 backoff 재시도(0.1 s → 3.2 s, 총 6.3 s) 후 does not match after 6 retries 로 실패했다. 같은 초에 Floorplan, Level, Room, Pointcloud, Cluster, Capture, Bim, BimRevision, AnnotationLayer, Category, Review, Record, FloorplanSource 등 13 개 child model 클래스에서 동일 패턴의 15 개 error 로그가 발생했다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-09 21:00:37 KST — BulkSavePartialJsonToFileWorker 가 Floorplan [6434, 6435, 6436, 6437] 조회 실패, retry 1 시작 (0.1 s)
2. 2026-07-09 21:00:37 KST — retry 2~4 연속 실패 (0.2 s, 0.4 s, 0.8 s)
3. 2026-07-09 21:00:37 KST — retry 5 실패 (1.6 s)
4. 2026-07-09 21:00:39 KST — retry 6 실패 (3.2 s)
5. 2026-07-09 21:00:41 KST — FloorplanSource [3357, 3358] 첫 error 로그 발생
6. 2026-07-09 21:00:43 KST — Floorplan/Level/Record/Capture/Cluster 5 건 error 로그 발생 (본 cluster 포함)
7. 2026-07-09 21:00:45 KST — CopyRequest 가 Begin/Finished Copying Room, AnnotationLayer, BimRevision, Bim, Deviation, Reference, Category, Review, Bookmark, Comment, Report 등 다수 child model 처리 로그 방출 (outer transaction 은 아직 진행 중)
8. 2026-07-09 21:00:51 KST — Room/Pointcloud/AnnotationLayer/BimRevision/Bim/Review/Category 등 8 건 error 로그 발생, 이후 동일 error 재발생 없음

Error Log#

Datadog Logs

Floorplan with ids [6434, 6435, 6436, 6437] does not match after 6 retries

Impact#

• Service: cupixworks-worker
• 발생 횟수: 1 (본 cluster)
• 동시 발생: 같은 burst 에서 13 개 child model 클래스, 총 15 개 error 로그
• 최초 발생: 2026-07-09 21:00:43 KST
• 최근 발생: 2026-07-09 21:00:43 KST
• 비즈니스 영향: Data Warehouse (save_partial_json_to_file) 로 발행되는 CDC 스트림에서 CopyRequest 로 생성된 레코드의 (created) 이벤트가 파일로 flush 되지 않음. Elasticsearch 재인덱싱(BulkIndexWorker)이나 사용자 API 응답과는 무관.

Root Cause Summary#

CopyOperator::CopyRequest#run_copies_by_sql 는 outer ActiveRecord::Base.transaction 안에서 child_models 를 순회하며 각 model 에 대해 insert_all! + BulkSavePartialJsonToFileWorker.perform_async 를 호출한다. Sidekiq 은 Redis 큐 기반이라 outer transaction 의 commit 을 기다리지 않고 즉시 job 을 pick up 한다. Worker 프로세스가 별도 DB connection 에서 model_class.where(id: ids) 를 실행하면, PostgreSQL 의 READ COMMITTED 격리 하에서 아직 커밋되지 않은 outer transaction 이 삽입한 행은 보이지 않는다. Worker 는 최대 6 회, 지수 backoff (0.1 · 0.2 · 0.4 · 0.8 · 1.6 · 3.2 = 6.3 s) 로 재시도하지만, CopyRequest 는 여러 child model 을 순차 처리하기 때문에 transaction 전체 지속 시간이 6.3 s 를 훨씬 초과하며, 결과적으로 worker 는 대상 레코드를 보지 못한 채 error 를 로깅하고 return false 로 종료한다.

Technical Analysis#

Code Path#

Entry point (outer transaction 열림):

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
rescue Cupix::Errors::System => e
  # ...
end

Child model 순회 및 batch 삽입:

def run_copy_by_sql!(model_name)
  Cupix::Logger.info("Begin Copying #{model_name}", ...)

  parent_params = get_parent_params(model_name)
  records = model_name.constantize.where(parent_params).copyable_candidates
  # ...
  (0..1).each do |_depth|
    records.copyable_ancestry(depth = _depth).in_batches(of: self.batch_size).each_with_index do |group, batch_index|
      self._run_insert_all!(model_name, group, batch_index, ancestry: _depth)
    end
  end
  # ...
end

Failure point — insert_all! 직후 outer transaction commit 없이 perform_async 호출:

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

Worker 조회 — commit 되지 않은 행은 다른 connection 에서 보이지 않음:

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 호출 시점에 target_ids 는 이미 커밋되어 있어야 하며, worker 가 즉시(또는 1 초 이내) 조회 시 모든 행이 보여야 함.

실제 동작: perform_async 는 outer transaction 안에서 호출되며 Sidekiq 은 Redis 큐에 job 을 즉시 push 한다. Redis 쓰기는 DB transaction 과 분리되어 있어 rollback 되지도 않고 commit 을 기다리지도 않는다. Worker 는 별도 DB connection 에서 where(id: ids) 를 수행하지만 outer transaction 미커밋 상태에서는 신규 행이 보이지 않는다. 6.3 s backoff 는 여러 child model 을 순차 처리하는 CopyRequest 의 전체 transaction 시간을 커버하지 못한다.

Log Evidence#

Datadog query (retry 경로 재현):

service:cupixworks-worker @environment:production "Retry" "Floorplan"

Retry 로그 (본 cluster 대상):

2026-07-09 21:00:37 warn  Retry 1 - Floorplan with ids [6434, 6435, 6436, 6437] count does not match, retrying in 0.1 seconds
2026-07-09 21:00:37 warn  Retry 2 - Floorplan with ids [6434, 6435, 6436, 6437] count does not match, retrying in 0.2 seconds
2026-07-09 21:00:37 warn  Retry 3 - Floorplan with ids [6434, 6435, 6436, 6437] count does not match, retrying in 0.4 seconds
2026-07-09 21:00:37 warn  Retry 4 - Floorplan with ids [6434, 6435, 6436, 6437] count does not match, retrying in 0.8 seconds
2026-07-09 21:00:37 warn  Retry 5 - Floorplan with ids [6434, 6435, 6436, 6437] count does not match, retrying in 1.6 seconds
2026-07-09 21:00:39 warn  Retry 6 - Floorplan with ids [6434, 6435, 6436, 6437] count does not match, retrying in 3.2 seconds
2026-07-09 21:00:43 error Floorplan with ids [6434, 6435, 6436, 6437] does not match after 6 retries

Datadog query (CopyRequest 활동 확인):

service:cupixworks-worker @environment:production "Begin Copying" OR "Finished Copying" OR "CopyRequest"

CopyRequest 는 error 발생 이후에도 계속 child model 을 순차 처리했음:

2026-07-09 21:00:45 info Begin Copying Room       class:CopyRequest function:run_copy_by_sql!
2026-07-09 21:00:45 info Begin Copying AnnotationLayer
2026-07-09 21:00:45 info Begin Copying BimRevision
2026-07-09 21:00:45 info Begin Copying Bim
2026-07-09 21:00:45 info Begin Copying Reference
2026-07-09 21:00:45 info Begin Copying Category
2026-07-09 21:00:45 info Begin Copying Review
2026-07-09 21:00:45 info Begin Copying Report
2026-07-09 21:00:45 info Begin Copying Comment

동일 burst 에서 발생한 다른 model 에러 (Datadog query service:cupixworks-worker @environment:production "does not match after"):

2026-07-09 21:00:41 error FloorplanSource with ids [3357, 3358] does not match after 6 retries
2026-07-09 21:00:43 error Floorplan with ids [6434, 6435, 6436, 6437] does not match after 6 retries
2026-07-09 21:00:43 error Level with ids [57476, 57477, 57478] does not match after 6 retries
2026-07-09 21:00:43 error Record with ids [7668, 7669, 7670] does not match after 6 retries
2026-07-09 21:00:43 error Capture with ids [42404, 42405, 42406, 42407, 42408, 42409, 42410, 42411, 42412] does not match after 6 retries
2026-07-09 21:00:43 error Cluster with ids [127698...127716] does not match after 6 retries
2026-07-09 21:00:43 error Cluster with ids [127717...127728] does not match after 6 retries
2026-07-09 21:00:51 error Pointcloud with ids [131253...131269] does not match after 6 retries
2026-07-09 21:00:51 error Pointcloud with ids [131270...131285] does not match after 6 retries
2026-07-09 21:00:51 error Room with ids [171732...171756] does not match after 6 retries
2026-07-09 21:00:51 error Bim with ids [1697, 1698] does not match after 6 retries
2026-07-09 21:00:51 error BimRevision with ids [2216, 2217] does not match after 6 retries
2026-07-09 21:00:51 error AnnotationLayer with ids [23193, 23194] does not match after 6 retries
2026-07-09 21:00:51 error Review with ids [35346, 35347, 35348] does not match after 6 retries
2026-07-09 21:00:51 error Category with ids [2292] does not match after 6 retries

동일 error 는 지난 14 일 로그에서 전부 이 10 초 burst 안에 집중되어 있으며, 그 이전에는 발생 이력이 없다 (query status:error @class:BulkSavePartialJsonToFileWorker — 15 건 모두 21:00:41~21:00:51 사이).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/concerns/copy_operator/copy_request.rb:210 의 BulkSavePartialJsonToFileWorker.perform_async 호출을 outer transaction commit 이후에 실행하도록 지연시킨다. Rails 표준 패턴은 after_commit 콜백 또는 인메모리 큐(예: pending_partial_json_jobs) 에 model_name/target_ids 를 모아 뒀다가 run_copies_by_sql 의 transaction do ... end 블록이 성공적으로 반환된 뒤에 일괄 perform_async 하는 것.
• app/repositories/concerns/bulkable_repository.rb:71 의 bulk_save_changes_to_partial_json, app/factories/bulkable_factory.rb:63 의 동일 호출도 outer transaction 안에서 호출될 여지가 있는지 재검토 필요. Bulkable 은 controller 에서 감싸는 rails-implicit transaction 밖일 확률이 높으나, bulk action 내부에서 다시 transaction 을 열지 않는지 확인.
• 즉시 hotfix 가 어렵다면 BulkSavePartialJsonToFileWorker 의 $MAX_RETRIES (app/workers/bulk_save_partial_json_to_file_worker.rb:5) 를 상수화하고 backoff cap 을 늘리는 것으로는 근본 해결 안 됨 — CopyRequest transaction 은 초 단위가 아니라 수십 초 이상 지속 가능. Retry 튜닝은 임시 완화책일 뿐.

단기 개선 (1주 이내)#

• perform_async 를 transaction 안에서 호출하는 모든 지점을 찾아 (Grep: BulkSavePartialJsonToFileWorker.perform_async 총 8 개 호출 지점) 각각 outer transaction 밖으로 이동. 후보 파일:
  • app/models/concerns/copy_operator/copy_request.rb:210, 311
  • app/repositories/field_repository.rb:392
  • app/factories/work_order_factory.rb:108
  • app/factories/concerns/bulkable_factory/annotation.rb:304
  • app/factories/concerns/bulkable_factory/asset_category.rb:194
  • app/factories/concerns/bulkable_factory/asset_instance.rb:282
  • app/factories/concerns/bulkable_factory/trade_task_trace.rb:131
  • app/models/concerns/finalization/editing_entity.rb:560
• Worker 실패 시 CDC 유실을 보완할 수 있도록 실패한 (class_name, ids) 를 재-enqueue 하는 dead-letter/재처리 경로 추가 검토. 현재는 return false 로 종료.

장기 개선 (재발 방지)#

• Sidekiq 5+ 의 perform_async 를 transaction 안에서 호출하지 못하도록 lint 규칙(예: RuboCop custom cop 또는 sorbet 시그니처)을 도입해 CI 에서 차단. 유사 사례는 Rails/Sidekiq 커뮤니티의 알려진 함정.
• after_commit 콜백 기반 CDC 이벤트 발행으로 아키텍처 통일 검토. insert_all! 은 콜백을 우회하므로 별도 헬퍼(enqueue_after_commit(&block)) 를 정의해 모든 bulk 삽입 후 안전하게 워커 예약.

Monitoring#

• 새로운 alert: BulkSavePartialJsonToFileWorker 의 does not match after 6 retries error 발생 시 Slack 알림 (5 분 rate > 3 이면 fire).
• Datadog timeseries query 예시:

sum:trace.sidekiq.job.errors{service:cupixworks-worker,resource_name:bulksavepartialjsontofileworker}.as_count()

logs("service:cupixworks-worker @environment:production status:error \"does not match after 6 retries\"").index("*").rollup("count").by("@class").last("5m")

• CopyRequest 실행 시간 tracking: Cupix::Logger.info("finished", ..., copy_request: { duration }) 를 이미 방출하므로 duration facet 를 index 에 추가하고 p95 duration 이 6.3 s (worker backoff 총합) 초과 여부를 대시보드에 노출.

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard

CDC / Data Warehouse 파일 발행 실패는 사용자 실시간 흐름에는 영향이 없으나, 다운스트림 분석 파이프라인에서 CopyRequest 로 생성된 신규 레코드가 누락된다. Fix 자체는 "transaction 밖으로 enqueue 이동" 이라는 명확한 방향이며, 영향 지점이 8 개로 한정되어 있어 표준 리팩터링으로 처리 가능.