RCA: error occurred while reprocess. capture_id: 2356, reason:Capture is not invokable status

Overview#

What Happened#

2026-07-06 10:24:50 KST 에 cupixworks-worker 에서 capture 2356 에 대한 reprocess (CaptureOperation.reinvoke_captures) 시도가 실패했다. create_capture_invokable? 체크가 Capture is not invokable status 사유로 Cupix::Errors::Entity 를 raise 했고, 이는 outer rescue StandardError 블록에서 잡혀 로그로 기록되었다. 1회 발생, 단일 capture 에 국한된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-06 10:24:44 KST — capture 2356 에 대한 선행 reprocess 파이프라인이 진행: reconstruction_state 가 none → queued 로 전이되고 create_3d_reconstruction 관련 job 이 생성됨 (Datadog 로그).
2. 2026-07-06 10:24:50 KST — 후속 reinvoke_captures 호출이 실행되어 reset_capture → ready_to_process_state! → save! → after_commit :invoke_capture 흐름을 실행. create_capture 진입 시 create_capture_invokable? 체크가 실패하며 Cupix::Errors::Entity 예외 발생.
3. 2026-07-06 10:24:50 KST — CaptureOperation.reinvoke_captures 의 rescue StandardError 블록에서 예외를 잡고 error occurred while reprocess. capture_id: 2356, reason:Capture is not invokable status 로그를 남김. 결과는 { id: 2356, status: 'error', error: ... } 로 반환됨.
4. 2026-07-06 10:25:16 KST / 10:31:44 KST — 이후 Updating associated deviations/sitetracks for Capture 2356 info 로그가 남아 있어, 관련 파이프라인은 정상 진행됨을 확인.

Error Log#

Datadog Logs

error occurred while reprocess. capture_id: 2356, reason:Capture is not invokable status

Impact#

• Service: cupixworks-worker
• 발생 횟수: 1
• 최초 발생: 2026-07-06 10:24:50 KST
• 최근 발생: 2026-07-06 10:24:50 KST

단일 capture 에 국한된 1회성 실패이며, 재시도로 회복 가능한 상태이다. 시스템 전체 영향은 없다.

Root Cause Summary#

CaptureInvoker#reprocess_capture 는 reset 이후 ready_to_process_state! + save! 를 실행하고, Rails after_commit :invoke_capture, if: :processing_required? 콜백이 이어서 CaptureInvoker#create_capture 를 호출한다. create_capture 는 @model.create_capture_invokable? 를 호출하고, 이 체크의 마지막 가드인 unless invokable? 는 upload_state == :upload_done state 블록에 정의된 invokable? = !jobs.processing.exists? 를 평가한다. capture 2356 의 경우 직전 10:24:44 KST 에 이미 3D reconstruction 관련 job 이 생성되어 jobs.processing 상태로 남아 있었기 때문에 invokable? 가 false 를 반환했고, Cupix::Errors::Entity(code: 'ENT10000', reason: 'Capture is not invokable status') 가 raise 되었다. 즉, 선행 reprocess 로 생성된 processing job 이 아직 진행 중인 상태에서 중복 reprocess 요청이 들어와 정상 방어 로직이 발동한 것이 원인이다.

Technical Analysis#

Code Path#

• Entry point: app/operations/capture_operation.rb:25 — CaptureOperation.reinvoke_captures(capture_ids, current_user)
• 각 capture 순회하며 CaptureInvoker#reprocess_capture 호출: app/operations/capture_operation.rb:33
• Reset 흐름: app/invokers/capture_invoker.rb:272 — reprocess_capture
• State 전이 + save: app/invokers/capture_invoker.rb:284-285
• after_commit 훅으로 invoke_capture 호출: app/models/concerns/processible_capture.rb:11
• invoke_capture 에서 capture_invoker.create_capture 호출: app/models/concerns/processible_capture.rb:36-37
• create_capture_invokable? 호출: app/invokers/capture_invoker.rb:13
• Failure point: app/models/concerns/invokable/capture.rb:24-26 — invokable? 가 false 를 반환 시 Cupix::Errors::Entity raise
• 최종 로깅: app/operations/capture_operation.rb:39

def reinvoke_captures(capture_ids, current_user)
  captures = ::Capture.where(id: capture_ids)
  results = []

  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 Cupix::Errors::PermissionDenied => e
      Cupix::Logger.warn("permission denied while reprocess. capture_id: #{capture.id}, user_id: #{current_user.id}")
      results << { id: capture.id, status: 'error', error: e.message }
    rescue StandardError => e
      Cupix::Logger.warn("error occurred while reprocess. capture_id: #{capture.id}, reason:#{e.message}, user_id: #{current_user.id}", reprocess: { error: e })
      results << { id: capture.id, status: 'error', error: e.message }
    end
  end

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}")

after_uploaded_state :ready_to_process_state
after_commit :invoke_capture, on: :update, if: :processing_required?

# ...

def invoke_capture
  Cupix::Logger.info("invoke capture processing for capture #{self.id}.", ...)
  self.processing_required = false

  if singleshot?
    process_singleshot!
  elsif json_upload? || migrated_from_einstein_v2? || reality_capture?
    run_pano_postprocessor
  elsif skymap_video?
    Cupix::Logger.info("Skipping processing for skymap_video capture #{self.id}", ...)
  else
    capture_invoker = CaptureInvoker.new(model: self, current_user: self.user)
    job = capture_invoker.create_capture
    run_preprocessor_agent(job)
  end

  finalize_processing_skippable_capture
end

def create_capture(opts = {})
  raise Cupix::Errors::Argument.new(code: 'ARG10000', reason: 'user is required') if self.current_user.blank?

  @model.create_capture_invokable?

def create_capture_invokable?
  unless upload_state_upload_done?
    raise Cupix::Errors::Entity.new(code: 'ENT10000', reason: 'Capture must be upload_done state to process')
  end

  if singleshot?
    raise Cupix::Errors::Entity.new(code: 'ENT10000', reason: 'Invocation of singleshot capture does not available after Tesla 1.3.0')
  end

  unless invokable?
    raise Cupix::Errors::Entity.new(code: 'ENT10000', reason: 'Capture is not invokable status')
  end
  # ...
end

state_machine :upload_state, initial: :created, namespace: :upload_state do
  state :upload_done do
    def invokable?
      !jobs.processing.exists?
    end
  end

기대 동작: reprocess_capture 는 reset_capture(force: true) 로 진행 중인 job 을 정지/정리한 뒤 create_capture 시점에는 processing job 이 없어야 한다.

실제 동작: capture 2356 에 대해 직전에 이미 reprocess 가 수행되어 (10:24:44 KST reconstruction_state: none → queued 로그) processing 상태 job 이 남아 있었다. 그 상태에서 후속 reprocess 요청이 들어와 create_capture_invokable? 의 invokable? 가드가 정상적으로 실패했다.

Log Evidence#

Datadog 쿼리:

service:cupixworks-worker "error occurred while reprocess. capture_id: 2356"

service:cupixworks-worker (2356)

핵심 이벤트 (시간순, KST):

2026-07-06 10:24:44  info  reconstruction_state has transitioned from none to queued on Capture 2356
2026-07-06 10:24:44  info  CaptureIntelligence skipped: capture intelligence not enabled (facility key=2wjse6). capture_id: 2356
2026-07-06 10:24:50  info  Capture 2356 reset refinement job              (function: reset_refinement)
2026-07-06 10:24:50  info  Capture 2356 reset 3d_reconstruction           (function: reset_3d_reconstruction)
2026-07-06 10:24:50  info  refinement_state has transitioned from refined to draft on Capture 2356
2026-07-06 10:24:50  info  Capture 2356 reset refinement job done         (function: reset_refinement)
2026-07-06 10:24:50  info  Capture 2356 reset 3d_reconstruction           (function: reset_3d_reconstruction)
2026-07-06 10:24:50  error error occurred while reprocess. capture_id: 2356, reason:Capture is not invokable status
2026-07-06 10:25:16  info  Updating associated sitetracks for Capture 2356
2026-07-06 10:25:16  info  Updating associated deviations for Capture 2356
2026-07-06 10:31:44  info  Updating associated sitetracks for Capture 2356
2026-07-06 10:31:44  info  Updating associated deviations for Capture 2356
2026-07-06 12:34:19  info  timeout voxels agent - Capture id: 2356         (class: Capture, function: timeout_voxel_agent)

10:24:44 KST 에 이미 reconstruction job 이 queued 상태로 존재했고, 6초 뒤 10:24:50 KST 의 후속 reprocess 흐름에서 reset → ready_to_process 후 invoke_capture → create_capture → invokable? 순으로 진행하며 jobs.processing.exists? == true 이므로 방어 로직이 발동했다. 12:34:19 KST 의 timeout voxels agent 로그는 해당 시점 voxel agent 가 이후 타임아웃된 사실을 보여주어, processing 상태 job 이 존재했다는 정황을 뒷받침한다.

로그 레벨 관찰: 코드는 Cupix::Logger.warn(...) 로 남기지만 (app/operations/capture_operation.rb:39), Datadog 에는 status: error 로 인덱싱되어 error-sweeper 클러스터로 승격되었다. reprocess: { error: e } 컨텍스트에 Exception 객체가 첨부되면서 Datadog 로그 파이프라인이 상위 레벨로 승격했을 가능성이 있다 (uncertain -- Datadog 파이프라인 설정 미확인).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 코드 변경 불필요. create_capture_invokable? 의 raise 는 의도된 방어 로직이며, 상위 pipeline (reinvoke_captures) 은 다른 capture 처리에 영향을 주지 않고 { status: 'error' } 를 반환한다. 필요 시 잠시 후 재요청으로 해결 가능.

단기 개선 (1주 이내)#

• 로그 레벨/컨텍스트 정합성: app/operations/capture_operation.rb:17, 39 는 코드상 Cupix::Logger.warn 이지만 Datadog 에 error 로 인덱싱되고 error-sweeper 클러스터로 승격된다. "예상 가능한 운영 시나리오(중복 reprocess, 진행 중 job 존재)" 가 반복적으로 error 클러스터에 올라오지 않도록:
  • rescue 블록에서 Cupix::Errors::Entity(code ENT10000) 를 별도 분기로 처리하여 info/warn 만 남기고 exception 객체 첨부는 제거하는 방향 검토 (reprocess: { error: e } → reprocess: { error_message: e.message }).
• 재요청 사전 필터링: reprocess 트리거 지점 (app/controllers/cli/v1/captures_controller.rb, app/controllers/api/v1/admin/captures_controller.rb:38) 에서 이미 jobs.processing.exists? 인 capture 를 사전에 걸러 사용자에게 명확한 사유를 응답으로 돌려주는 방향 검토.

장기 개선 (재발 방지)#

• reprocessible? (app/models/concerns/processible_capture.rb:67-72) 은 jobs.processing.exists? 를 이미 검사하지만, save! 이후 after_commit 에서 다시 create_capture_invokable? 가 별도로 검사한다. 두 검증기가 일관된 계약을 갖도록 통합해 사용자에게 실패 사유를 진입 시점에 알리는 방향 검토.
• invokable? 를 state :upload_done 블록 안에서만 정의하는 패턴은 다른 upload_state 에서 NoMethodError 로 이어질 수 있어 예측 가능성이 낮다. 명시적 default (def invokable?; false; end) 를 추가하는 방향 검토.

Monitoring#

Reprocess 실패 빈도 추적 timeseries (dashboard widget 삽입용):

sum:logs.hits{service:cupixworks-worker,@environment:production,message:"error occurred while reprocess"}.as_count()

Capture 별 방어 로직 발동 여부:

sum:logs.hits{service:cupixworks-worker,@environment:production,message:"Capture is not invokable status"}.as_count()

같은 capture 에 대한 중복 reprocess 감지 (반복성 확인):

sum:logs.hits{service:cupixworks-worker,@environment:production,message:"start reprocess captures"}.as_count()

Risk Assessment#

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