RCA: Api::V1::CapturesController#analysis_done_callback (avg 11.1s, max 11.1s)

Overview#

What Happened#

2026-07-29 07:04 KST 무렵 cupixworks-api 의 Api::V1::CapturesController#analysis_done_callback 엔드포인트에서 2건의 요청이 평균 11.1초의 응답 지연을 기록했다. 콜백 자체는 정상적으로 204 응답을 반환했지만, controller path 안에서 done_analysis_state! 상태 전이 후 after_transition hook 이 동기적으로 CreateSiLiteSyncJob AR 레코드 생성 + AWS SQS send_message 호출까지 수행하는 구조 때문에 다운스트림 지연이 요청 시간에 그대로 반영되었다. 500 에러는 발생하지 않았고, 유사 콜백 대다수는 초 이하로 응답하고 있어 systematic bug 가 아닌 transient latency 로 판단된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-29 07:04:08 KST — capture 743234 의 analysis_done_callback 요청 도착
2. 2026-07-29 07:04:08 KST — capture 743234: 동일 요청 내에서 SI Lite job 생성 + SQS 전송 + 204 응답 완료 (sub-second, 정상 case)
3. 2026-07-29 07:04:08 KST — capture 744140 의 analysis_done_callback 요청 도착 (추정)
4. 2026-07-29 07:04:13 KST — capture 744140: SI Lite sync job is created for capture 744140. job_id: 1233554 (요청 시작 후 약 5초 경과)
5. 2026-07-29 07:04:17 KST — capture 744140: Sending message to https://sqs.us-west-2.amazonaws.com/002596530511/cupix-si-lite-agent-production (job 생성 후 약 4초 경과)
6. 2026-07-29 07:04:19 KST — capture 744140: si_lite_state 전이 완료 + analysis_done_callback | done on 744140 + [204] 반환 (SQS log 후 약 2초 경과, 총 약 11초)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::CapturesController#analysis_done_callback",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11111,
  "max_ms": 11111,
  "sample_trace_id": "577460490752241059"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2
• 최초 발생: 2026-07-29 07:04 KST
• 최근 발생: 2026-07-29 07:01 KST
• HTTP 상태: 204 (성공) — 에러 없음, 순수 latency 이슈
• 비즈니스 영향: 콜백 발신 측 (pano vectorize agent) 의 타임아웃 정책에 따라 재시도가 트리거될 위험. 재시도가 발생하면 analysis_state_processing? guard (captures_controller.rb:128-130) 때문에 ARG10001 InvalidState 로 실패한다.

Root Cause Summary#

analysis_done_callback 엔드포인트가 요청 스레드에서 동기적으로 무거운 작업을 실행하기 때문에 다운스트림 latency 가 요청 응답 시간에 그대로 누적된다. 구체적으로 capture.done_analysis_state! 는 Analyzable concern 의 after_transition from: any, to: :done 훅을 트리거하고, 그 안에서 run_si_lite_sync → CaptureInvoker#create_si_lite_sync → CreateSiLiteSyncJob.create! → run → AWS SQS send_message → queued_si_lite_state 상태 전이가 모두 인라인으로 수행된다. capture 744140 의 로그를 보면 요청 시작 이후 (1) job 생성까지 5초, (2) SQS send_message 로그까지 4초, (3) 응답까지 2초가 각각 소비되었다. 동일 시각 (07:04:08 KST) 에 처리된 capture 743234 는 초 이하로 완료되었으므로, 코드 자체의 성능 문제가 아닌 SQS 호출 또는 DB round-trip 의 일시적 지연이 요청 응답 시간에 노출된 케이스다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/captures_controller.rb:116
• 상태 전이: app/controllers/api/v1/captures_controller.rb:132 (capture.done_analysis_state!)
• 상태 전이 후 동기 훅: app/models/concerns/analyzable.rb:49-55
• SI Lite 동기 처리: app/models/concerns/si_lite_sync.rb:45-49
• Job AR 레코드 생성 + SQS 전송: app/invokers/capture_invoker.rb:157-180 → app/jobs/create_si_lite_sync_job.rb:27-38 → app/models/job.rb:61-134

Controller — find_by → HMAC 검증 → 상태 체크 → done_analysis_state! → 로그 → 렌더 순서로 모두 동기 실행:

def analysis_done_callback
  capture = ::Capture.find_by(id: params[:id])
  raise Cupix::Errors::NotFound.new(code: 'ARG10002', reason: 'Capture not found') if capture.blank?

  token = params[:token].to_s
  expected_token = OpenSSL::HMAC.hexdigest('SHA256', Rails.application.secret_key_base, "analysis_done:#{capture.id}")

  unless ActiveSupport::SecurityUtils.secure_compare(token, expected_token)
    Cupix::Logger.error("CapturesController::analysis_done_callback | invalid token on #{capture.id}", class: self.class.name, function: __method__)
    raise Cupix::Errors::Unauthorized.new(code: 'AUTH10001', reason: 'Invalid callback token')
  end

  unless capture.analysis_state_processing?
    raise Cupix::Errors::InvalidState.new(code: 'ARG10001', reason: "Invalid analysis_state: #{capture.analysis_state}")
  end

  capture.done_analysis_state!
  Cupix::Logger.info("CapturesController::analysis_done_callback | done on #{capture.id}", class: self.class.name, function: __method__)

  render_api
end

Analyzable concern 의 after_transition ... to: :done hook 은 SI Lite 조건을 만족할 때 run_si_lite_sync 를 요청 스레드에서 그대로 실행한다:

after_transition from: any, to: :done do |model, transition|
  model.log_trace_event('pano_vectorize_finished') if model.respond_to?(:log_trace_event) && model.respond_to?(:cupix_trace_id)
end

after_transition from: any, to: :done do |model, transition|
  model.run_si_lite_sync if model.respond_to?(:run_si_lite_sync?) && model.run_si_lite_sync?
end

run_si_lite_sync 는 CaptureInvoker#create_si_lite_sync 를 호출해 AR 레코드를 만든다. CreateSiLiteSyncJob.create! 는 run_on_create? == true (create_si_lite_sync_job.rb:23-25) 이므로 저장 콜백에서 즉시 run 이 호출되어 SQS 로 메시지를 전송한다:

def run_si_lite_sync
  capture_invoker = CaptureInvoker.new(model: self, current_user: self.user, current_team: self.team)
  job = capture_invoker.create_si_lite_sync
  Cupix::Logger.info("'create_si_lite_sync' job(#{job.id}) run for capture #{self.id}", class: self.class.name, function: __method__)
end

def run_on_create?
  true
end

def run
  send_message
  self.jobable.queued_si_lite_state
rescue => e
  false
else
  true
end

Job#send_message 는 최종적으로 AWS SDK sqs_client.send_message 를 요청 스레드에서 호출한다:

Cupix::Logger.info("Sending message to #{_queue_url}: #{message_body}", class: self.class.name, function: __method__)

begin
  sqs_params = { queue_url: _queue_url, message_body: message_body.to_json }
  sqs_params.merge!(_fifo_params) if _fifo_params.present?
  sqs_client.send_message(sqs_params)
rescue => e
  Cupix::Logger.error(
    "Failed to send SQS message - queue_url: #{_queue_url}, job_id: #{id}, jobable_type: #{jobable_type}, jobable_id: #{jobable_id}, error: #{e.class.name}: #{e.message}",
    ...

기대 동작 vs 실제 동작

• 기대: webhook 콜백은 analysis_state 만 flip 하고 즉시 204 응답. SI Lite 등 후속 작업은 background worker 로 위임 → 응답 시간 ≪ 1초.
• 실제: SI Lite job 생성 + SQS 전송 + 두 번째 상태 전이 (queued_si_lite_state) 가 모두 요청 스레드에서 실행되어 SQS/DB 지연이 그대로 응답 시간에 반영됨 → 11초.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api "744140"

시간 범위 2026-07-28T22:04:00Z ~ 2026-07-28T22:04:25Z, 결과 6건 (KST 로 표기):

07:04:13 KST  INFO  CaptureInvoker.create_si_lite_sync  "SI Lite sync job is created for capture 744140. job_id: 1233554"
07:04:13 KST  INFO  Capture.run_si_lite_sync            "'create_si_lite_sync' job(1233554) run for capture 744140"
07:04:17 KST  INFO  CreateSiLiteSyncJob.send_message    "Sending message to https://sqs.us-west-2.amazonaws.com/002596530511/cupix-si-lite-agent-production: {:id=>744140, :job=>{:id=>1233554}, :session=>{:id=>11726370, :token=>\"7fs5jjsi8c2b\"}, :cupix_trace_id=>\"d175873e-4567-4bf8-b034-0520b9886d1c\", :cpu_architecture=>nil, :launch_mode=>\"CUPIXWORKS\"}"
07:04:17 KST  INFO  (state_machine)                     "si_lite_state has transitioned from none to queued on Capture 744140"
07:04:19 KST  INFO  Api::V1::CapturesController#analysis_done_callback  "CapturesController::analysis_done_callback | done on 744140"
07:04:19 KST  INFO  (rack)                              "[204] POST /api/v1/captures/744140/callbacks/analysis_done"

동일 시각의 정상 case (capture 743234) — sub-second 응답:

07:04:08 KST  INFO  CaptureInvoker.create_si_lite_sync  "SI Lite sync job is created for capture 743234. job_id: 1233553"
07:04:08 KST  INFO  Capture.run_si_lite_sync            "'create_si_lite_sync' job(1233553) run for capture 743234"
07:04:08 KST  INFO  CreateSiLiteSyncJob.send_message    "Sending message to https://sqs.us-west-2.amazonaws.com/002596530511/cupix-si-lite-agent-production: {:id=>743234, :job=>{:id=>1233553}, ...}"
07:04:08 KST  INFO  (state_machine)                     "si_lite_state has transitioned from none to queued on Capture 743234"
07:04:08 KST  INFO  Api::V1::CapturesController#analysis_done_callback  "CapturesController::analysis_done_callback | done on 743234"
07:04:08 KST  INFO  (rack)                              "[204] POST /api/v1/captures/743234/callbacks/analysis_done"

동일 window 에서 warn/error 조회:

service:cupixworks-api status:warn  (2026-07-28T22:00:00Z ~ 22:10:00Z) → 0건
service:cupixworks-api @http.status_code:500  (2026-07-28T22:00:00Z ~ 22:10:00Z) → 0건

status board 조회: svc:cupixworks-api::unknown scope, active null. 최근 5-7일간 동일 scope 에서 4건의 resolved 인시던트가 있었으나 별개 클러스터.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

없음. 500 에러가 아닌 순수 latency 이슈이고 발생 빈도 (2건) 가 낮다. 콜백 발신 측 (pano vectorize agent) 의 timeout 설정이 15초 이상인지 확인만 권장 — 만약 timeout 이 10초 이하라면 재시도 → ARG10001 InvalidState 로 이어질 수 있으므로 timeout 조정이 우선.

단기 개선 (1주 이내)#

• analysis_done_callback 을 얇게 유지: app/controllers/api/v1/captures_controller.rb:116-136 에서 capture.done_analysis_state! 만 실행하고 204 를 반환하도록 하고, 후속 SI Lite job 생성 / SQS 전송은 Sidekiq worker 로 위임하는 방향 검토.
• Analyzable concern 의 after_transition ... to: :done hook (app/models/concerns/analyzable.rb:53-55) 을 async 로 전환: 현재 run_si_lite_sync 가 요청 스레드에서 실행되지만, AnalyzePanoWorker.perform_async (line 63) 처럼 background 위임하면 콜백 응답 시간이 SQS latency 와 분리된다.
• 대안: CreateSiLiteSyncJob 의 run_on_create? (app/jobs/create_si_lite_sync_job.rb:23-25) 를 false 로 두고, run 은 별도 Sidekiq worker 에서 호출하도록 재설계.

장기 개선 (재발 방지)#

• Webhook 성 엔드포인트 전체에 대해 "receive → persist state → enqueue background job → respond" 패턴을 강제하는 컨벤션 도입. 특히 after_transition ... to: :done 훅에서 외부 API 호출 (SQS/HTTP) 을 금지하고 별도 worker 로 위임.
• APM 상 analysis_done_callback resource 에 대한 p95 latency SLO 정의 (예: p95 < 1s). 위반 시 알람.

Monitoring#

Datadog trace latency (p95) — analysis_done_callback 응답 시간 추이:

avg:trace.rack.request.duration.by.resource_service.95p{service:cupixworks-api,resource_name:api::v1::capturescontroller#analysis_done_callback} by {env}

분당 slow request 카운트 (>1s) — 문제 재발 감지용:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::capturescontroller#analysis_done_callback,duration:>1s}.as_count()

SQS send_message 로그 빈도 (CreateSiLiteSyncJob) — SQS 지연 상관 관계 확인:

logs("service:cupixworks-api @class:CreateSiLiteSyncJob @function:send_message").index("*").rollup("count").by("@queue_url").last("1h")

AWS SQS SendMessage P95 latency (us-west-2) — 외부 원인 확인용:

avg:aws.sqs.approximate_age_of_oldest_message.p95{queuename:cupix-si-lite-agent-production,region:us-west-2}

Alert 권장: analysis_done_callback p95 latency > 3s for 5min → warning, > 10s for 5min → critical.

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard (분리 자체는 표준적인 배경 처리 리팩토링이지만, state machine after_transition 훅을 async 로 전환할 때 기존 재시도 / 실패 처리 시나리오 회귀 테스트 필요)
• 사용자 영향: 낮음 (콜백 발신자만 관찰). 재발 빈도가 늘어나면 재시도 폭주 위험 존재.