RCA: error occurred while reprocess. capture_id: 30152, reason:Model has invalid state to reprocess

Overview#

What Happened#

2026-04-29 22:58:35 UTC에 eu-central-1 리전의 cupixworks-worker에서 user_id 8이 capture 30152에 대해 reprocess를 시도했으나, capture가 done 상태가 아니어서 ENT10000 에러가 발생했다. 해당 capture는 최소 1시간 전부터 queue에 stuck 상태로 감지되고 있었다.

Quick Facts#

Timeline#

1. 22:00:33 UTC — Cron job이 capture 30152를 stuck in queue로 감지 (Cupix::Cron::Capture#notify_stuck_capture)
2. 22:30:29 UTC — Cron job 두 번째 stuck 감지
3. 22:57:13 UTC — user_id 3615 reprocess 시도 → Permission denied (PERM10000)
4. 22:57:47 UTC — user_id 2012 reprocess 시도 → Permission denied (PERM10000)
5. 22:58:35 UTC — user_id 8 reprocess 시도 → Model has invalid state to reprocess (ENT10000)
6. 23:00:03 UTC — capture 30152 processing 정상 invoke됨 (Capture#invoke_capture)

Error Log#

Datadog Logs

error occurred while reprocess. capture_id: 30152, reason:Model has invalid state to reprocess, user_id: 8

Impact#

• Service: cupixworks-worker
• 발생 횟수: 1
• 최초 발생: 2026-04-29T22:58:35.654Z
• 최근 발생: 2026-04-29T22:58:35.654Z

이 에러는 사용자에게 reprocess 실패 응답을 반환하지만, 약 2분 후 capture processing이 정상 invoke된 것으로 보아 사용자 영향은 일시적이었다.

Root Cause Summary#

Capture 30152가 queued 상태에서 stuck되어 있는 동안 user_id 8이 reprocess를 시도했다. CaptureInvoker#reprocess_capture의 @model.reprocessible? 검증은 capture가 done 상태일 때만 true를 반환하므로, queued 상태의 capture에 대해 Cupix::Errors::Entity(ENT10000) 에러가 발생했다. 이는 설계된 동작(guard clause)이지만, stuck된 capture에 대해 관리자가 reprocess를 시도하는 운영 시나리오에서 에러 로그가 남는 것은 불필요하게 노이즈를 생성한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/cli/v1/captures_controller.rb:5 — #reinvoke action
• Operation layer: app/operations/capture_operation.rb:22 — reinvoke_captures 메서드가 capture를 조회하고 각각에 대해 reprocess 시도
• Invoker validation: app/invokers/capture_invoker.rb:274 — reprocessible? 체크 실패 시 Cupix::Errors::Entity raise
• State validation: app/models/concerns/processible_capture.rb:67 — reprocessible? 메서드가 state_done?과 processing jobs 부재를 확인

def reprocess_capture(opts = {})
  raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied') unless Pundit.policy(self.current_user, @model).reinvoke?
  raise Cupix::Errors::Entity.new(code: 'ENT10000', reason: 'Model has invalid state to reprocess') unless @model.reprocessible?

  self.reset_capture(opts, force: true)

  post_slack("[Repositories::Capture] Begin to reprocess capture #{@model.id}")

  @model.sys['reprocessed_at'] = DateTime.now
  @model.sys['reprocessed_by_id'] = self.current_user.id if self.current_user.present? && self.current_user.is_a?(::User)
  @model.reprocess_count += 1

  @model.ready_to_process_state!
  @model.save!

  post_slack("[Repositories::Capture] Finished to reprocess capture #{@model.id}")
  @model.log_trace_event(__method__.to_s)

  true
end

def reprocessible?
  return false if self.jobs.processing.exists?
  return false unless state_done?

  true
end

reprocessible? 메서드는 두 가지 조건을 확인한다:

1. 현재 processing 중인 job이 없어야 함
2. Capture 상태가 반드시 done이어야 함

Capture 30152는 cron에 의해 "stuck in queue"로 감지되었으므로, queued 상태에 머물러 있었을 가능성이 높다. queued는 done이 아니므로 state_done?이 false를 반환하여 reprocess가 거부되었다.

captures.each do |capture|
  Cupix::Logger.info("start reprocess captures. capture_id: #{capture.id}, user_id: #{current_user.id}")
  begin
    capture_invoker = CaptureInvoker.new(model: capture, current_user: current_user)
    capture_invoker.reprocess_capture
    results << { id: capture.id, status: 'success' }
  rescue StandardError => e
    Cupix::Logger.error("error occurred while reprocess. capture_id: #{capture.id}, reason:#{e.message}, user_id: #{current_user.id}", reprocess: { error: e })

Operation layer에서 StandardError를 catch하고 error 레벨로 로깅하고 있다. 이 guard clause 실패는 예상된 비즈니스 로직 거부인데, error 레벨로 기록되어 불필요한 알림을 유발한다.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-worker "error occurred while reprocess"
Time range: 2026-04-29T21:58:35Z to 2026-04-29T23:28:35Z

service:cupixworks-worker "30152"
Time range: 2026-04-29T21:58:35Z to 2026-04-29T23:28:35Z

Cron이 capture 30152를 stuck으로 두 번 감지한 로그:

{
  "timestamp": "2026-04-29T22:00:33.266Z",
  "status": "info",
  "message": "stuck in queue capture found: 30152",
  "class": "Cupix::Cron::Capture",
  "function": "notify_stuck_capture"
}

{
  "timestamp": "2026-04-29T22:30:29.466Z",
  "status": "info",
  "message": "stuck in queue capture found: 30152",
  "class": "Cupix::Cron::Capture",
  "function": "notify_stuck_capture"
}

Reprocess 시도와 에러 로그:

{
  "timestamp": "2026-04-29T22:58:35.654Z",
  "status": "info",
  "message": "start reprocess captures. capture_id: 30152, user_id: 8"
}

{
  "timestamp": "2026-04-29T22:58:35.654Z",
  "status": "error",
  "message": "error occurred while reprocess. capture_id: 30152, reason:Model has invalid state to reprocess, user_id: 8"
}

에러의 structured 필드:

{:code=>"ENT10000", :reason=>"Model has invalid state to reprocess"}

에러 발생 약 2분 후 processing이 정상 invoke됨:

{
  "timestamp": "2026-04-29T23:00:03.662Z",
  "status": "info",
  "message": "invoke capture processing for capture 30152.",
  "class": "Capture",
  "function": "invoke_capture"
}

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

없음. 이 에러는 설계된 guard clause의 정상 동작이며, capture processing은 2분 후 정상 수행되었다.

단기 개선 (1주 이내)#

• 로그 레벨 변경: app/operations/capture_operation.rb:33 — Cupix::Logger.error를 Cupix::Logger.warn으로 변경. 비즈니스 로직에 의한 예상된 거부(state validation, permission denied)는 error가 아닌 warn으로 기록해야 한다. 이렇게 하면 error monitoring에서 노이즈가 줄어든다.
• Stuck capture에 대한 reprocess 허용 검토: app/models/concerns/processible_capture.rb:67 — queued 상태에서 일정 시간 이상 stuck된 capture에 대해 관리자가 reprocess할 수 있도록 reprocessible? 조건을 확장하는 것을 검토. 예: state_done? || (state_queued? && stuck_duration > threshold).

장기 개선 (재발 방지)#

• Stuck in queue 상태가 1시간 이상 지속되는 capture에 대해 자동 recovery 메커니즘 구현 (현재는 cron이 감지만 하고 알림만 보냄)
• Reprocess 요청의 거부 사유를 API 응답에 더 상세하게 포함하여 사용자가 현재 상태를 이해할 수 있도록 개선 (예: "Capture is currently in 'queued' state. Only 'done' captures can be reprocessed.")

Monitoring#

• Stuck capture 빈도 추적:

service:cupixworks-worker "stuck in queue capture found"

• Reprocess 실패 추적 (로그 레벨 변경 후 warn으로):

service:cupixworks-worker "error occurred while reprocess" status:warn

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial

이 에러는 단건 발생이며, capture processing은 2분 후 정상 수행되었다. 사용자 영향이 일시적이고 데이터 손실이 없으므로 위험도는 낮다. 로그 레벨을 warn으로 변경하는 것만으로 monitoring 노이즈를 제거할 수 있다.