RCA: Editing with id 1204740 not found after 6 retries

Overview#

What Happened#

SavePartialJsonToFileWorker가 after_commit으로 enqueue된 직후 자기 자신이 처리하는 Editing 레코드를 6회 재시도(총 약 6.3초) 동안 찾지 못하고 실패했다. 2026-07-02 15:31 KST부터 16:27 KST까지 us-west-2 / eu-central-1 / ap-northeast-1 세 리전에서 총 70건이 발생했으며, 같은 시각에 다른 워커(EditingSplitWorker, LogEditingStateWorker)도 동일 Editing ID를 찾지 못했다. 이는 부모 트랜잭션이 열려 있는 상태에서 자식 레코드용 after_commit 콜백이 실행되어 워커를 enqueue하기 때문이다.

Quick Facts#

Affected Teams#

Timeline#

Representative case (Editing id 1204740, region-scoped one worker instance):

1. 2026-07-02 15:31:50 KST — EditingEntity.create_editing_with_geo_bucket가 Editing 1204740 생성 후 save! 완료 로그 (set geo_bucket_key on editing 1204740)
2. 2026-07-02 15:31:50 KST — Statable::Editing.before_transition 로그 (state has transitioned from waiting to ready on Editing 1204740) — 같은 콜백 안에서 LogEditingStateWorker.perform_async 및 (after_commit을 통해) SavePartialJsonToFileWorker.perform_async 가 enqueue됨
3. 2026-07-02 15:31:50 KST — EditingSplitWorker가 즉시 실행되어 Couldn't find Editing with 'id'=1204740 로 실패 (retry: 2)
4. 2026-07-02 15:31:50 KST — SavePartialJsonToFileWorker Retry 1~4가 100ms 간격으로 계속 실패
5. 2026-07-02 15:31:54 KST — Retry 6 (지연 3.2초) 이후에도 여전히 not found
6. 2026-07-02 15:31:56 KST — Editing with id 1204740 not found after 6 retries 최종 실패 로그, return false
7. 2026-07-02 16:27:48 KST — 동일 패턴의 마지막 발생 (Editing 132157/132158/132159)

Error Log#

Datadog Logs

Editing with id 1204740 not found after 6 retries

Impact#

• Service: cupixworks-worker
• 발생 횟수: 70
• 최초 발생: 2026-07-02 15:31 KST
• 최근 발생: 2026-07-02 16:27 KST
• Regions: us-west-2, eu-central-1, ap-northeast-1 (전 리전)
• 비즈니스 임팩트: Editing partial JSON이 데이터 웨어하우스로 forwarding되지 못해 초기 생성 이벤트가 웨어하우스에 반영되지 않을 수 있음. 이후 update/destroy 콜백은 정상 작동하므로 최종 상태는 결국 반영되지만, "created" 이벤트 자체가 유실됨.

Root Cause Summary#

Editing 레코드가 EditingFactory.create!로 생성될 때 DataWareHouse::PartialJson concern의 after_commit :save_partial_json_to_file_as_created 콜백이 SavePartialJsonToFileWorker.perform_async를 호출한다. 그러나 이 create!가 부모 EditingEntity의 after_ready_state 콜백(즉 EditingEntity의 state transition transaction) 안에서 실행되고 있어서, Rails는 nested/outer transaction이 커밋될 때까지 자식 레코드의 after_commit을 지연시킨다. 결과적으로 Sidekiq에 job이 enqueue되는 시점(Sidekiq client는 Redis에 즉시 push)과 워커가 pickup하는 시점 사이에 Editing 레코드가 아직 DB에 커밋되지 않은 창(window)이 열린다. 게다가 같은 이벤트 안에서 Statable::Editing.before_transition이 LogEditingStateWorker.perform_async를 호출하고 _stamp_editing_id_on_elements가 EditingSplitWorker.perform_async를 호출한다 — 이 두 워커는 after_commit을 거치지 않고 트랜잭션 내부에서 직접 enqueue되므로 확실히 커밋 이전에 큐로 나간다. 세 워커 모두 동일 순간에 "not found"를 겪는 로그가 이를 확인시켜준다.

Technical Analysis#

Code Path#

Entry point: EditingEntity#assign_editing_to_editing_entity가 EditingEntity의 after_ready_state 콜백으로 호출됨.

    included do
      include ::Finalization

      after_ready_state :assign_editing_to_editing_entity
      after_skipped_state :skipped_state_callback_editing_entity
      after_done_state :done_state_callback_editing_entity

      def assign_editing_to_editing_entity
        retries = 0
        begin
          _do_assign_editing_to_editing_entity

Editing 생성:

      def create_editing_with_geo_bucket(geo_bucket_key)
        editing = create_editing
        return nil if editing.nil?

        editing.geo_bucket_key = geo_bucket_key
        editing.save!
        Cupix::Logger.info("set geo_bucket_key on editing #{editing.id}",
                           class: self.class.name, function: __method__,
                           editing: { id: editing.id, geo_bucket_key: geo_bucket_key })
        editing
      end

이후 EditingEntity 흐름에서 _editing_in_ready.ready_state! 로 Editing에 state transition을 트리거:

        _editing_in_ready.save!

        Cupix::Logger.info("candidate_editings type: #{entity_type}, count: #{_candidate_editings.count}", class: self.class.name, function: __method__, entity: { id: entity.id, type: entity_type })

        _editing_in_ready.ready_state! if _editing_in_ready.state_waiting?

        self.update(editing_id: _editing_in_ready.id)
        self.entity.update(editing_id: _editing_in_ready.id) if entity.has_attribute?(:editing_id) && entity.editing_id.blank?

Editing의 state transition은 before_transition 안에서 워커 enqueue를 수행:

        before_transition do |model, transition|
          Cupix::Logger.info("state has transitioned from #{transition.from} to #{transition.to} on Editing #{model.id}",
                             class_name: self.class.name,
                             function: __method__,
                             editing: { id: model.id, state: model.state, editing_type: model.editing_type, entity_type: model.entity_type },
                             transition: { from: transition.from, to: transition.to })

          if transition.from != transition.to
            # ...
            LogEditingStateWorker.perform_async(model.id, transition.from, transition.to, model.editor_id)

DataWareHouse::PartialJson 은 Editing에 after_commit 훅을 걸어 SavePartialJsonToFileWorker를 enqueue:

    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', class: self.class, module: 'DataWareHouse', function: 'save_partial_json_to_file_in_worker', id: self.id, model: self.class.name)

        return nil
      end

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

Failure point — SavePartialJsonToFileWorker의 6회 재시도 후 최종 실패:

    $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

전체 재시도 지연: 0.1 + 0.2 + 0.4 + 0.8 + 1.6 + 3.2 = 6.3초. 부모 트랜잭션이 6.3초 이상 열려 있으면 워커는 결국 포기하고 return false를 반환한다 (Sidekiq retry: false 이므로 재시도 없음, dead 큐로도 가지 않음).

기대 동작: after_commit이 진짜로 outermost transaction commit 후에 발화되어 워커가 조회 시점에 Editing이 존재.

실제 동작: create!가 outer transaction 안에 nested savepoint로 감싸지므로, after_commit은 outer commit 시점까지 지연된다. 그러나 Sidekiq perform_async는 Redis에 즉시 push되고 워커는 다른 프로세스에서 즉시 pickup하므로, DB 커밋 전에 워커가 실행될 수 있다. 게다가 LogEditingStateWorker(before_transition에서 호출)와 EditingSplitWorker(_stamp_editing_id_on_elements에서 직접 호출)는 after_commit을 거치지도 않고 트랜잭션 내부에서 직접 enqueue되므로 더 확실하게 커밋 이전에 큐로 나간다.

Log Evidence#

Datadog 쿼리:

service:cupixworks-worker "Editing with id" "not found after"

service:cupixworks-worker "1204740"

동일 순간에 세 개의 서로 다른 워커가 같은 Editing ID를 찾지 못하는 로그:

2026-07-02 15:31:50 INFO  set geo_bucket_key on editing 1204740
                          class: EditingEntity function: create_editing_with_geo_bucket
2026-07-02 15:31:50 INFO  state has transitioned from waiting to ready on Editing 1204740
2026-07-02 15:31:50 ERROR Editing split failed: Couldn't find Editing with 'id'=1204740
                          class: EditingSplitWorker function: perform
2026-07-02 15:31:50 WARN  Retry 1 - Editing with id 1204740 not found, retrying in 0.1 seconds
                          class: SavePartialJsonToFileWorker function: perform
2026-07-02 15:31:50 WARN  Retry 2 - Editing with id 1204740 not found, retrying in 0.2 seconds
2026-07-02 15:31:50 WARN  Retry 3 - Editing with id 1204740 not found, retrying in 0.4 seconds
2026-07-02 15:31:50 WARN  Retry 4 - Editing with id 1204740 not found, retrying in 0.8 seconds
2026-07-02 15:31:52 WARN  Retry 5 - Editing with id 1204740 not found, retrying in 1.6 seconds
2026-07-02 15:31:54 WARN  Retry 6 - Editing with id 1204740 not found, retrying in 3.2 seconds
2026-07-02 15:31:56 ERROR Editing with id 1204740 not found after 6 retries

두 번째 사례 (Editing 132157/132158/132159, 16:27 KST) 에서도 같은 순서로 재현됨:

2026-07-02 16:27:40 INFO  state has transitioned from waiting to ready on Editing 132159
2026-07-02 16:27:40 INFO  editing not found: 132159
                          class: LogEditingStateWorker function: perform
2026-07-02 16:27:42 WARN  Retry 1 - Editing with id 132159 not found, retrying in 0.1 seconds
2026-07-02 16:27:48 ERROR Editing with id 132159 not found after 6 retries

LogEditingStateWorker는 자체적으로 find_by(id: editing_id) 후 blank?이면 조용히 리턴하기 때문에 error가 아닌 info 레벨로 남지만 (app/workers/log_editing_state_worker.rb:6-10), 이 역시 부모 트랜잭션 미커밋의 증거이다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

트랜잭션 내부에서 워커를 enqueue하는 두 지점을 after_commit 이후로 이동시키거나, Sidekiq의 perform_async를 after_commit_everywhere 헬퍼로 감싼다:

• app/models/concerns/statable/editing.rb:102 — LogEditingStateWorker.perform_async가 before_transition 안에서 호출됨. after_transition 콜백으로 이동시키고, 또한 outer transaction까지 안전하게 지연시키기 위해 Editing 모델에 after_commit :log_state_change_worker_enqueue를 추가하는 형태로 재설계.
• app/models/concerns/finalization/editing_entity.rb:455 — ::EditingSplitWorker.perform_async(editing.id)가 _stamp_editing_id_on_elements 실행 흐름(EditingEntity의 state transition transaction 내부) 안에서 호출됨. 이 블록 전체를 ActiveRecord::Base.transaction { ... }.after_commit { ... } 패턴으로 감싸거나, 상위 호출부에서 트랜잭션 종료 후 enqueue.

또한 SavePartialJsonToFileWorker 의 after_commit 훅은 nested transaction 시나리오에서 outer commit까지 지연되기 때문에, outer transaction commit 이후에 실제로 enqueue되도록 보장해야 한다. Rails 7의 after_commit 은 기본적으로 outermost transaction commit 후 동작하지만, EditingFactory.create! 흐름에서 실제로 outer transaction commit 시점이 언제인지를 검증 필요. Sidekiq sidekiq-transaction-guard 같은 gem으로 트랜잭션 내부 perform_async 호출을 감지/경고하는 것을 도입 검토.

단기 개선 (1주 이내)#

• 재시도 로직 강화: SavePartialJsonToFileWorker.$MAX_RETRIES = 6 은 총 6.3초만 대기. 큰 트랜잭션에서는 부족. Sidekiq의 내장 retry 메커니즘(retry: N with exponential backoff) 을 사용하도록 sidekiq_options queue: :data_changes, retry: false 를 retry: 5 등으로 변경 후, 워커 내부의 sleep 루프 제거. Sidekiq retry는 프로세스를 blocking하지 않으므로 리소스 효율도 개선됨.
• fail-loud 원칙: 현재 return false로 조용히 종료 → 데이터 웨어하우스에 이 이벤트가 누락되어도 알림 없음. 최종 실패 시 Sentry/Datadog에 확실히 metric을 남겨야 함.
• 테스트 케이스 추가: spec/workers/save_partial_json_to_file_worker_spec.rb 및 spec/models/concerns/finalization/editing_entity_spec.rb 에 nested transaction에서 Editing 생성 후 워커 실행 시점 시나리오 재현 스펙 추가.

장기 개선 (재발 방지)#

• Sidekiq transaction guard 도입: sidekiq-transaction-guard gem 또는 커스텀 미들웨어로 perform_async 호출이 열려 있는 트랜잭션 안에서 발생하면 dev/test/staging에서 raise. 이 패턴을 근본적으로 차단.
• DataWareHouse forwarding 아키텍처 재검토: 현재 각 model의 after_commit에서 개별 워커를 enqueue하는 방식은 nested transaction 문제와 스로틀링 부재를 야기. Outbox pattern (동일 DB 트랜잭션 내에 outbox_events 테이블에 insert → 별도 poller가 forwarding) 검토.
• State machine 콜백 컨벤션: before_transition에서 perform_async를 절대 호출하지 않는 팀 룰 문서화. 모든 job enqueue는 after_commit 또는 명시적 after_transition (transaction 종료 후) 에서만.

Monitoring#

• Datadog dashboard에 다음 timeseries widget 추가:

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

service:cupixworks-worker status:error @class:EditingSplitWorker "Couldn't find Editing"

• Sidekiq retry warn 카운트 (fix가 실제로 창을 줄였는지 확인):

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

• 알림: 최근 15분간 "not found after 6 retries" 발생 건수 > 5 이면 warn 알림.

Risk Assessment#

• Risk level: medium — 데이터 웨어하우스로의 initial partial JSON forwarding이 유실되지만, 후속 update/destroy 이벤트로 최종 상태는 결국 반영됨. 다만 데이터 파이프라인에서 "created" 이벤트에 의존하는 downstream 계산이 있다면 영향 확대 가능.
• 예상 복잡도: standard — 두 워커 enqueue 지점을 트랜잭션 밖으로 이동하는 리팩터링. state_machines 라이브러리의 콜백 순서를 다뤄야 하며, 테스트가 필수. 3개 파일 이내 변경 예상.