RCA: Api::V1::JobsController#running_action latency outlier (17.7s)

Overview#

What Happened#

2026-06-25 06:50 KST 경 cupixworks-api (us-west-2)에서 PUT /api/v1/jobs/:id/actions/:action_name/running 한 건이 17.7초 걸린 latency outlier로 감지되었다. 동일 endpoint 의 같은 시간대(06:48-06:55 KST) 다른 요청들은 모두 HTTP 200 정상 응답이고, 동시 시간 구간의 JobCallbackWorker.perform 로그도 1-4초 내에 완료되어, 단일 trace 의 일시적 outlier 이며 systemic regression 은 아니다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-25 06:50:32 KST — 문제 trace 발생 (sample_trace_id=3650352366366419804, 17.7s).
2. 2026-06-25 06:50:32 KST 전후 — 같은 endpoint 의 다른 호출들은 정상 200 응답(예: 06:50:32 job 1150634, 06:50:24 job 1150617 등 모두 info 레벨 200).
3. 2026-06-25 06:54:54 KST — 동일 service 에서 무관한 ClusterRepository "Operation timed out after 10002 milliseconds" 에러 1건 발생(아래 "Hypotheses Considered" 참조).
4. 2026-06-24 21:50:32 UTC — error-sweeper collector 가 latency 클러스터로 등록 (first_seen == last_seen, occurrence 1).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::JobsController#running_action",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 17733,
  "max_ms": 17733,
  "sample_trace_id": "3650352366366419804"
}

Impact#

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

단일 outlier 이므로 즉시 사용자 영향은 제한적이지만, 호출 측이 짧은 timeout (예: 10s) 으로 설정된 경우 client-side timeout 실패 가능성이 있다. 이 endpoint 는 agent (preprocessor / skat-master / postprocessor) 가 자신의 상태를 running 으로 보고하는 경로이므로 지연이 누적되면 agent 의 다음 처리 시작이 늦어질 수 있다.

Root Cause Summary#

Api::V1::JobsController#running_action 은 thin controller (app/controllers/api/v1/jobs_controller.rb) 로 ActionableController#running_action (app/controllers/concerns/actionable_controller.rb:12-18) 을 통해 repository.running_action! 을 호출한다. 이 경로는 Action state machine 의 after_transition from: any, to: :running 콜백 (app/models/concerns/statable/action.rb:39-42) 을 거쳐 actionable.run_running_state_callbacks → Actionable::Job#after_action_running (app/models/concerns/actionable/job.rb:11-19) 으로 이어지고, command 가 preprocessor 인 경우 추가로 Job 자체의 running_state! state machine 이벤트가 발생하면서 JobCallbackWorker.perform_inline(job.id, 'job_running_callback') (app/models/concerns/statable/job.rb:81-84) 이 request thread 안에서 동기적으로 실행된다. 즉 단일 HTTP PUT 호출이 (1) Action state 업데이트, (2) Action.run_at 업데이트, (3) Job state 업데이트 + Event 레코드 생성, (4) Sidekiq worker 의 inline 실행(jobable 의 callback 체인) 까지 모두 처리한다.

해당 1건의 17.7s outlier 는 위 동기 체인 중 하나(가장 가능성 높은 후보: JobCallbackWorker.perform_inline 내 job.jobable.send(callback_name, job) 호출 — Capture/Bim 등 jobable 의 검색 인덱싱/event 생성 등 중량 작업 포함) 가 일시적으로 느려진 것으로 추정된다. 동시 시간대의 다른 running_action 호출과 JobCallbackWorker 로그가 모두 수 초 내에 완료된 점, 동일 endpoint 의 systemic 에러/지연이 보이지 않는 점이 이를 뒷받침한다 — 즉 systemic regression 이 아닌 synchronous fan-out 경로의 tail-latency outlier 이다.

Technical Analysis#

Code Path#

Entry point 는 ActionableController#running_action 이고, fan-out 의 끝은 JobCallbackWorker#perform 의 inline 실행이다.

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

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

def running_action!(action_name)
  @model.running_action!(action_name)
end

def running_action!(action_name)
  action = actions.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.running_state!
  action
end

action.running_state! 는 Statable::Action state machine 의 running event 를 발화시키고, after-transition 에서 update(run_at: ...) 와 actionable.run_running_state_callbacks(action) 를 모두 request thread 안에서 실행한다.

after_transition from: any, to: :running do |action, transition|
  action.update(run_at: DateTime.now)
  action.actionable.run_running_state_callbacks(action)
end

after_transition from: any, to: :completed do |action, transition|
  action.actionable.run_completed_state_callbacks(action)
end

Actionable::Job#after_action_running 은 command 가 preprocessor 인 경우 Job 의 running_state! 까지 호출하여 Job state machine 의 running 전이를 추가로 발화시킨다. 이 시점에 stat 업데이트(update_processing_stat) 와 log_cupix_trace 가 동기적으로 실행된다.

def after_action_running
  Cupix::Logger.debug("[after_action_running] job: #{id}, current_action.command.name: #{current_action.command.name rescue nil}")

  update_processing_stat('running', self.current_action.command.name) if self.current_action.present?
  if self.current_action.present? && self.current_action.command.name == 'preprocessor'
    running_state!
    self.current_action = nil
  end
end

Failure point (가장 비용이 높은 sync fan-out): Job state machine 의 after_transition to: :running 이 JobCallbackWorker.perform_inline 으로 워커 코드를 request 컨텍스트에서 동기 실행한다. Sidekiq queue 를 거치지 않으므로 retry/throttling 도 없다.

after_transition to: :running do |job, transition|
  jid = JobCallbackWorker.perform_inline(job.id, 'job_running_callback')
  Cupix::Logger.info("invoke job_running_callback with jid: #{jid} for job #{job.id}")
end

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)

  Cupix::Logger.info("job #{id} #{callback_name} done", class: self.class.name, function: __method__, job: { id: id, callback: callback_name })
rescue StandardError => e
  Cupix::Logger.error("job #{id} #{callback_name} error - #{e.class}: #{e.message}\n#{e.backtrace.join("\n")}", class: self.class.name, function: __method__, job: { id: id, callback: callback_name })
end

여기서 job.jobable.send('job_running_callback', job) 은 jobable 모델(Capture, Bim, Deviation, Sitetrack)의 :job_running_callback ActiveSupport callback chain 을 실행한다. Capture 의 경우 search index 갱신, event 생성 등 다수의 부수효과가 단일 HTTP request 내에서 동기 처리된다.

추가로 Job 의 running_state 전이 자체가 매번 Eventable::Events::Update.create_event(self) 를 호출하여 DB 의 events 테이블에 INSERT 를 일으킨다.

def create_running_state_changed_event(transition)
  if IOS_NOTIFICATION_SEND_TRANSITIONS.include?(transition.to_name)
    _send_ios_notification = true
  end

  if self.respond_to?(:build_event)
    self.set_current_user(self.user)
    self.build_event({
      action: 'update',
      reason: "running_state_#{transition.to}",
      send_ios_notification: _send_ios_notification
    })
    self.append_event_extra({
      error_code: self.try(:error_code),
      processing_status: self.try(:processing_status)
    })
    ::Eventable::Events::Update.create_event(self)
  end
end

기대 동작: 상태 전이 보고는 가벼운 ACK + 비동기 fan-out 이어야 한다. 실제 동작: 전이 보고가 (Action state, Job state, Event row, jobable callback chain) 4단계의 동기 작업을 모두 책임지며, 그 중 하나가 느려지면 client 가 수십 초 대기한다.

Log Evidence#

Datadog query (재현용):

service:cupixworks-api "running_action"

service:cupixworks-api 3650352366366419804

원본 trace_id 로 직접 조회한 결과는 비어 있다 — APM trace 만 존재하고 application log 에는 trace_id 가 따로 인덱싱되지 않은 것으로 보인다(uncertain — 추가 확인 필요).

Searching: service:cupixworks-api 3650352366366419804
Time range: 2026-06-24T21:00:00Z to 2026-06-24T22:30:00Z
Limit: 50

Found 0 logs:

같은 시간대(±5분) 의 정상 호출들은 모두 200 (info) 으로 마무리된다. 즉 endpoint 자체가 망가진 것이 아니라 단일 trace 의 outlier 다.

{ "timestamp": "2026-06-25 06:50:32", "status": "info",
  "message": "[200] PUT /api/v1/jobs/1150634/actions/postprocessor/running (Api::V1::JobsController#running_action)" }
{ "timestamp": "2026-06-25 06:50:24", "status": "info",
  "message": "[200] PUT /api/v1/jobs/1150617/actions/postprocessor/running (Api::V1::JobsController#running_action)" }
{ "timestamp": "2026-06-25 06:50:22", "status": "info",
  "message": "[200] PUT /api/v1/jobs/1150623/actions/postprocessor/running (Api::V1::JobsController#running_action)" }

JobCallbackWorker.perform 의 inline 실행 로그도 같은 시간대에 모두 1-4초 내 완료된다.

{ "timestamp": "2026-06-25 06:51:56", "message": "job 1150808, run job_running_callback", "class": "JobCallbackWorker" }
{ "timestamp": "2026-06-25 06:52:00", "message": "job 1150808 job_running_callback done", "class": "JobCallbackWorker" }
{ "timestamp": "2026-06-25 06:51:07", "message": "job 1150806, run job_running_callback", "class": "JobCallbackWorker" }
{ "timestamp": "2026-06-25 06:51:10", "message": "job 1150806 job_running_callback done", "class": "JobCallbackWorker" }

같은 1시간 윈도우에서 cupixworks-api 의 error 로그는 5건뿐이고, 그중 본 cluster 와 시간적으로 가장 가까운 것은 ClusterRepository "Operation timed out after 10002 milliseconds" (06:54:54 KST, +4분) 이다. 이는 Elasticsearch HTTP 클라이언트 타임아웃으로 본 endpoint 와는 직접 관련이 없다.

{ "timestamp": "2026-06-25 06:54:54", "status": "error",
  "message": "Operation timed out after 10002 milliseconds with 0 bytes received",
  "class": "ClusterRepository" }

cupixworks-api service 에 대해 같은 24h 동안 status-board 가 보고한 svc:* 인시던트는 06:45-07:59 KST 의 cupixworks-api service degraded (root_cause_types: [unknown], 7개 cluster) 가 있으나, 본 cluster 는 그 인시던트의 시작 직전 (06:50:32) 의 단일 latency outlier 로 동일 인시던트에 묶이지는 않았다. 즉 인시던트 직전 service 가 약간 흔들리던 정황은 있지만, 본 cluster 1건만으로는 그 일부라고 단정할 수 없다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

없음. 1건짜리 outlier 이고 immediate user-facing breakage 가 아니다. 다만 재발 시 정확한 구간을 알 수 있도록 관측성을 우선 보강한다.

• app/workers/job_callback_worker.rb:5-15 의 시작/종료 로그에 elapsed time 을 함께 기록하도록 한다 (이미 시작/종료 두 줄이 있으므로 종료 줄에서 차이를 찍거나 별도 timing 로그를 추가하는 방향).
• Api::V1::JobsController#running_action 호출 trace 에 jobable type, command name 을 APM tag 로 추가하면 다음 outlier 발생 시 어떤 jobable 의 어떤 callback 이 느린지 즉시 식별 가능하다.

단기 개선 (1주 이내)#

• app/models/concerns/statable/job.rb:81-84 의 JobCallbackWorker.perform_inline 사용을 검토한다. running 전이는 agent 가 자기 상태를 보고하는 빈번한 hot-path 이므로, jobable callback chain 중 정말 동기로 실행되어야 하는 부분(예: 즉시 응답에 반영되어야 하는 state)과 비동기로 옮길 수 있는 부분(search index 갱신, 알림 fan-out 등)을 분리한다. 분리 후 후자는 일반 Sidekiq enqueue (perform_async) 로 전환한다.
• Action state machine 의 after_transition (app/models/concerns/statable/action.rb:39-42) 에서 update(run_at: DateTime.now) 와 run_running_state_callbacks 가 같은 트랜잭션에 묶이는지 확인. 같이 묶여 있다면 트랜잭션을 짧게 분리하여 Action row 락 점유 시간을 줄인다 (uncertain — 트랜잭션 경계 추가 검증 필요).

장기 개선 (재발 방지)#

• agent 상태 보고 endpoint (running_action / complete_action / error_action) 는 본질적으로 status webhook 성격이다. 이 패턴에서는 (1) lightweight DB write + (2) async fan-out 이 표준이다. callback chain 을 비동기화하는 방향으로 controller-level 응답시간 SLO 를 정의 (예: p99 < 1s).
• jobable callback chain 의 각 단계별 비용을 메트릭으로 분리해 측정한다 (tag:callback_step:<name> 등).

Monitoring#

추가 또는 대시보드화할 Datadog 쿼리:

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::jobscontroller#running_action}

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::jobscontroller#running_action}

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::jobscontroller#running_action}.as_count()

위 쿼리에서 resource_name tag 가 Datadog APM 에 인덱싱되어야 한다. 본 RCA 작성 시점에 timeseries 가 비어 있어 tag 인덱싱 여부를 별도로 확인해야 한다(uncertain — needs verification).

ClusterRepository 타임아웃과의 상관 관찰용:

sum:logs.hits{service:cupixworks-api,@class:ClusterRepository,status:error}.as_count()

Risk Assessment#

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

단발성 outlier 이며 단독 user impact 는 작다. 다만 running_action endpoint 의 동기 fan-out 구조는 systemic 성능 부담의 잠재 원인이므로, 반복 발생 시 단기 개선(callback 비동기화) 우선순위를 올린다.