RCA: Api::V1::JobsController#complete_action latency spike (22.3s)

Overview#

What Happened#

2026-06-25 02:40 KST(UTC 17:40:27)에 cupixworks-api의 PUT /api/v1/jobs/1149719/actions/postprocessor/complete 요청이 22.3초 만에 응답되었다(정상 평균은 1~2초). 응답 자체는 200이었지만, postprocessor complete_action 처리 과정에서 동기적으로 실행되는 JobCallbackWorker.perform_inline(stopping → stopped 콜백) 두 단계가 요청 스레드에서 함께 수행되며 latency가 누적되었다. 동일 시간대 같은 서비스에서 발생한 7개의 unknown root cause 클러스터(인시던트 2026-06-24-svc-cupixworks-api--unknown-2)와 함께 묶여 있다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-25 02:33:13 KST — Capture#run_postprocessor_agent invoked for capture 721071, job 1149719 (postprocessor 실행 시작)
2. 2026-06-25 02:34:01 KST — PUT /api/v1/jobs/1149719/actions/postprocessor/running 200 OK (running 전이)
3. 2026-06-25 02:40:27 KST — PUT /api/v1/jobs/1149719/actions/postprocessor/complete 요청 도착 (first_seen)
4. 2026-06-25 02:40:30 KST — [Job] state changed from running to stopping on Job 1149719
5. 2026-06-25 02:40:32 KST — JobCallbackWorker#perform job_stopping_callback 시작 (inline)
6. 2026-06-25 02:40:42 KST — [Job] state changed from stopping to stopped + job_stopped_callback 시작 (inline)
7. 2026-06-25 02:40:46 KST — job_stopping_callback done, job_stopped_callback done
8. 2026-06-25 02:40:50 KST — HTTP 200 응답 — 총 22343.71 ms

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::JobsController#complete_action",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 22357,
  "max_ms": 22357,
  "sample_trace_id": "4072316262835173070"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-25 02:40 KST
• 최근 발생: 2026-06-25 02:40 KST

본 클러스터는 인시던트 2026-06-24-svc-cupixworks-api--unknown-2(2026-06-25 01:45 ~ 02:59 KST, 약 75분, 7개 클러스터)에 속한다. 같은 시간대 service 전반에 걸친 latency 상승이 관측되었다.

Root Cause Summary#

Api::V1::JobsController#complete_action은 postprocessor command의 _finish 훅에서 Capture job을 stopping_state! → stopped_state!로 두 번 전이시킨다. 두 transition 모두 after_transition에서 JobCallbackWorker.perform_inline(...)(Sidekiq inline 실행)을 호출하여, 콜백 워커가 HTTP 요청 스레드 안에서 동기 실행된다. 콜백 내부에서는 Capture/Pano 등 다수 모델의 _update_document(Elasticsearch update API) 호출이 일어나며, Elasticsearch 응답이 느려지면 complete_action 응답 시간이 그대로 늘어난다. 사고 시점 로그에 동일 윈도우(KST 02:40~03:00) 동안 Pano#_update_document/EditingEntity#_update_document/Record#_update_document에서 NotFound - attributes_in_database warn이 다량 발생했고, db 시간은 1.5초에 불과한데 총 latency는 22.3초였다 — 즉 latency의 ~93%는 RDB 외부 (대부분 Elasticsearch + 콜백 체인) 에서 발생했다.

이는 코드 결함이라기보다 동기 콜백 + 외부 의존성(Elasticsearch) 지연이 결합된 구조적 latency 위험이다. 같은 인시던트의 다른 6개 클러스터와 동일한 잠복 원인을 공유한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/actionable_controller.rb:4 — complete_action 액션
• Repository hop: app/repositories/concerns/actionable_repository.rb:4 — @model.complete_action!(action_name) 위임
• State 전이: app/models/concerns/actionable.rb:56-63 — action을 찾고 action.completed_state! 호출
• State machine after_transition: app/models/concerns/statable/action.rb:44-46 — actionable.run_completed_state_callbacks(action) 실행
• Command finish: app/models/concerns/actionable.rb:24-34 → current_action.command.finish(actionable) → app/models/concerns/command_proxy.rb:9-11 → Commands::Job::Postprocessor#_finish
• Postprocessor finish: app/models/concerns/commands/job/postprocessor.rb:18-27 — super 후 Capture 인 경우 job.stopping_state!
• Failure point: app/models/concerns/statable/job.rb:95-98 — after_transition any => :stopping에서 JobCallbackWorker.perform_inline (블로킹)
• Stopping → Stopped: Jobable::Callbacks#after_job_stopping_callback(app/models/concerns/jobable/callbacks.rb:44-46)이 model.stopping_running_state!를 호출하여 추가 transition을 일으키고, 이어 stopped_state!까지 도달 → app/models/concerns/statable/job.rb:86-93에서 job_stopped_callback도 inline 실행

module ActionableController
  extend ActiveSupport::Concern

  def complete_action
    repository_instance.complete_action!(params[:action_name])

    render_api Renderable.new({
      contents: @model
    })
  end

def complete_action!(action_name)
  action = actions.completable.eager_load(:command).find_by(commands: { name: action_name })

  raise Cupix::Errors::Parameter.new(code: "Action not found with `#{action_name}`") if action.blank?

  action.completed_state!
  action
end

def _finish(job = nil)
  super

  case job.jobable_type
  when 'Capture'
    job.stopping_state!
  when 'Deviation', 'Sitetrack'
    job.stopped_state!
  end
end

after_transition any => :stopped do |job, transition|
  job.aws_tasks.each do |task|
    PullTaskWorker.perform_in(20.second, task.id)
  end

  jid = JobCallbackWorker.perform_inline(job.id, 'job_stopped_callback')
  Cupix::Logger.info("invoke job_stopped_callback with jid: #{jid} for job #{job.id}")
end

after_transition any => :stopping do |job, transition|
  jid = JobCallbackWorker.perform_inline(job.id, 'job_stopping_callback')
  Cupix::Logger.info("invoke job_stopping_callback with jid: #{jid} for job #{job.id}")
end

class JobCallbackWorker
  include Sidekiq::Worker
  sidekiq_options queue: :default, retry: 3

  def perform(id, callback_name)
    Cupix::Logger.info("job #{id}, run #{callback_name}", class: self.class.name, function: __method__, job: { id: id, callback: callback_name })
    job = ::Job.find_by_id(id)
    return if job.nil?

    job.jobable.send(callback_name, job)
    ...
  end
end

perform_inline은 Sidekiq 큐에 넣지 않고 호출 스레드에서 즉시 실행한다. 따라서 Capture#job_stopping_callback → Capture#job_stopped_callback 안에서 호출되는 모든 _update_document(Elasticsearch update, app/models/concerns/searchable.rb:55)와 그 외 인덱싱 부수효과가 HTTP 응답 시간에 직접 합산된다.

기대 동작 vs 실제 동작:

• 기대: postprocessor complete 요청은 action 상태만 변경하고 무거운 콜백은 비동기 워커로 위임 (~1초)
• 실제: stopping/stopped 두 transition 모두 inline 실행되어 ES 인덱싱이 끝날 때까지 응답이 보류됨 (22.3초)

Log Evidence#

Datadog 쿼리(latency spike — 본 트레이스):

service:cupixworks-api "complete_action" @duration:>10000

해당 trace 의 raw 요청 로그(요약):

{
  "@timestamp": "2026-06-24T17:40:50.841Z",
  "controller": "Api::V1::JobsController",
  "action": "complete_action",
  "params": { "id": "1149719" },
  "http": {
    "url_details": { "path": "/api/v1/jobs/1149719/actions/postprocessor/complete" },
    "status_code": 200,
    "method": "PUT"
  },
  "duration": 22343.71,
  "db": 1519.89,
  "team": { "domain": "burkecgi", "id": 965 },
  "user": { "id": 41211, "email": "hseavey@burkecgi.com" }
}

Job 1149719 의 trace 로그(KST):

2026-06-25 02:33:13  postprocessor agent is invoked for capture 721071 job id: 1149719
2026-06-25 02:34:01  [200] PUT /api/v1/jobs/1149719/actions/postprocessor/running
2026-06-25 02:40:27  PUT /api/v1/jobs/1149719/actions/postprocessor/complete  (요청 시작)
2026-06-25 02:40:30  [Job] state changed from running to stopping on Job 1149719
2026-06-25 02:40:32  job 1149719, run job_stopping_callback   (JobCallbackWorker#perform)
2026-06-25 02:40:42  [Job] state changed from stopping to stopped on Job 1149719
2026-06-25 02:40:42  job 1149719, run job_stopped_callback    (JobCallbackWorker#perform)
2026-06-25 02:40:46  job 1149719 job_stopping_callback done
2026-06-25 02:40:46  job 1149719 job_stopped_callback done
2026-06-25 02:40:50  [200] PUT /api/v1/jobs/1149719/actions/postprocessor/complete  (응답 완료, 22.3s)

같은 시간대(02:40~03:00 KST) cupixworks-api 의 다발성 warn — Elasticsearch 인덱스 정합성 신호:

service:cupixworks-api status:warn
→ "NotFound - attributes_in_database" (Pano#_update_document, EditingEntity#_update_document, Record#_update_document) 다수

searchable.rb:108의 분기 — attributes_in_database가 비어 있을 때 _index_document로 fallback 하면서 추가 ES 호출이 일어나는 구조이며, _update_document 자체가 inline 콜백 안에서 호출된다.

상태 보드 결과(증거):

{
  "scope": "svc:cupixworks-api::unknown",
  "active": null,
  "recent": [{
    "id": "2026-06-24-svc-cupixworks-api--unknown-2",
    "started_at": "2026-06-24T16:45:41.172Z",
    "resolved_at": "2026-06-24T17:59:31.677Z",
    "cluster_ids": ["bd35bc1d...", "13c20707-2776-42a4-984f-bc090734484e", "..."]
  }]
}

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 즉각적인 코드 변경 없이도 영향이 단발성(1건)이며 인시던트는 이미 자동으로 resolved 상태(2026-06-24-svc-cupixworks-api--unknown-2). 같은 인시던트의 7개 클러스터를 묶어 단일 액션으로 처리할 것 — 본 클러스터만 단독 fix 불필요.
• Elasticsearch 클러스터 헬스(cluster_health, indexing_pressure)와 Pano/Record/EditingEntity 인덱스 평균 응답 시간을 사고 시점(02:40~03:00 KST) 기준으로 점검. _update_document 다발 warn은 documents lookup miss이므로 reindex 큐 누적 여부와 함께 확인.

단기 개선 (1주 이내)#

• app/models/concerns/statable/job.rb:91, 96 에서 사용 중인 JobCallbackWorker.perform_inline을 비동기 큐 호출로 전환 검토:
  • 옵션 A: perform_async(혹은 perform_in(0)) — 응답을 빠르게 돌려보내고 콜백을 백그라운드에서 처리
  • 옵션 B: 인라인 유지 시 콜백 내부의 ES 인덱싱(_update_document) 만이라도 BulkIndexWorker.perform_async로 일괄 위임
• complete_action 트레이스에 콜백 실행 단계별 span(예: job_stopping_callback, job_stopped_callback) 을 추가해 latency 분해를 가능하게 한다.

장기 개선 (재발 방지)#

• 동기 inline 콜백 패턴(perform_inline)을 controller 응답 경로에서 사용하지 않는다는 표준 수립. CI lint/grep 룰로 perform_inline 추가를 차단.
• Elasticsearch 의존성을 controller 경로에서 제거하고 indexing 은 always-async (after_commit + Sidekiq) 로 통일.
• p95/p99 latency SLO 와 alarm 을 controller resource 단위로 도입 (Api::V1::JobsController#complete_action 자체).

Monitoring#

추가/유지할 Datadog 쿼리(timeseries widget — pipe/stats 문법 미사용):

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::JobsController#complete_action} by {env}

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::JobsController#complete_action} by {env}

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:Api::V1::JobsController#complete_action}.as_count()

Job 콜백 인덱싱 부담 추정용:

sum:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::JobsController#complete_action,@http.method:PUT}

알림 조건(예시): p95 complete_action duration > 5s for 5m — 별도 monitor 로 등록.

Risk Assessment#

• Risk level: medium — 단일 발생이지만 동일 시간대 6개 추가 클러스터와 함께 발생. inline 콜백 + ES 결합 구조는 ES latency 가 튈 때마다 재현 가능.
• 예상 복잡도: standard — perform_inline → perform_async 전환은 콜백 사이드이펙트가 후속 transition 에 의존하지 않는지(after_job_stopping_callback이 stopping_running_state!를 트리거) 확인이 필요하므로 단순 치환은 위험. callback chain reordering 이 따른다.