RCA: Api::V1::VideosController#upload_url latency spike (10.3s)

Overview#

What Happened#

2026-07-30 08:13 KST 시점에 cupixworks-api 서비스의 POST /api/v1/videos/:id/upload_url 요청 하나가 10,333 ms(=10.3초) 소요되어 latency cluster 로 감지되었다. 응답 자체는 200 OK 로 성공했다(직후 access log 로 확인됨). 동일 endpoint 는 같은 클라이언트가 곧이어 보낸 후속 요청들에서는 정상 시간(1분 내 여러 건 200 OK)으로 응답했으므로, 지속적 latency degradation 이 아니라 단일 요청에서 발생한 tail-latency spike 이다.

Quick Facts#

Affected Teams#

단일 요청, 사용자 영향은 최소이며, 특정 팀 도메인을 특정할 수 있는 정보(request payload, user id)는 API 로그에 노출되지 않았다.

Timeline#

1. 2026-07-30 08:08 KST — status board 가 인접 latency cluster fde39d65 (AerialPhotosController#index, 33s) 를 감지하며 svc:cupixworks-api::unknown incident 를 open (started_at 2026-07-29T23:00:02Z).
2. 2026-07-30 08:13:17 KST — 이번 cluster 의 slow request(10.3s) 발생, last_event_at 갱신.
3. 2026-07-30 08:13:29 KST — 동일 endpoint 로 POST /api/v1/videos/703876/upload_url 이 200 OK 로 access log 에 기록 (Datadog service:cupixworks-api "VideosController#upload_url").
4. 2026-07-30 08:14:39 KST — POST /api/v1/videos/703877/upload_url 200 OK.
5. 2026-07-30 08:15:50 KST — POST /api/v1/videos/703878/upload_url 200 OK — 후속 요청 정상 latency 로 복귀.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::VideosController#upload_url",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10333,
  "max_ms": 10333,
  "sample_trace_id": "3188310188230743847"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-30 08:13 KST
• 최근 발생: 2026-07-30 08:13 KST

Root Cause Summary#

Api::V1::VideosController#upload_url 는 단순 state-machine transition endpoint 로, 정상 실행 경로는 (1) Capture.find, (2) capture state guard, (3) @model.resource_uploading state event 발행, (4) after_transition from: :created, to: :resource_uploading 콜백에서 video.update_capture_state 호출로 이어진다. 이 콜백은 capture.reload 로 DB 를 다시 조회한 뒤 조건이 맞으면 capture.uploading_state 를 실행하여 after_uploading_state :notify → PostCaptureStateChangeWorker.perform_async 로 Sidekiq enqueue 까지 수행한다. 즉 endpoint 한 번의 처리에 최소 두 번의 DB round-trip, state machine callback chain, 그리고 Sidekiq(Redis) enqueue 가 동기적으로 포함된다. 단일 slow 이벤트로 후속 요청이 즉시 정상화된 점, error/warn 로그가 없는 점, 동일 시각에 AerialPhotosController#index 도 33s latency cluster 로 함께 튄 점을 종합하면, 특정 코드 결함보다는 이 경로에 포함된 외부 리소스(PG / Redis / capture record lock) 중 하나의 순간적 blocking 이 원인일 가능성이 가장 높다. 로그·메트릭 상에서 stall 지점을 pinpoint 할 수 있는 tracing evidence 는 남아 있지 않아 정확한 sub-component 는 uncertain — needs verification.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/videos_controller.rb:54
• Repository: app/repositories/video_repository.rb:316
• State event: app/models/concerns/statable/video.rb:20-22
• After-transition callback: app/models/concerns/statable/video.rb:50-52 → app/models/concerns/capture_material.rb:7-12
• Capture-side state chain: app/models/concerns/statable/capture.rb:117-136 (before_transition DB 업데이트) + app/models/concerns/notifiable/capture.rb:11,19-45 (after_uploading_state :notify → PostCaptureStateChangeWorker.perform_async).

def upload_url
  video = repository_instance.upload_url
  render_api Renderable.new({
    contents: @model
  })
end

def upload_url(option = nil)
  capture = ::Capture.find(self.model.capture_id)

  unless %i[created initializing uploading upload_ready].include?(capture.state_name)
    raise Cupix::Errors::InvalidState.new(code: 'STAT20000', reason: "Capture state is not 'created': #{capture.state}")
  end

  if %i[created done resource_missing].include?(@model.state_name)
    @model.resource_uploading
  end

  @model
end

event :resource_uploading do
  transition %i[created resource_missing done] => :resource_uploading
end
...
after_transition from: :created, to: %i[resource_uploading resource_missing] do |video, transition|
  video.update_capture_state
end

def update_capture_state
  return if capture_id.blank?
  return unless %w[initializing upload_ready].include?(capture.reload.state)

  capture.uploading_state
end

after_uploading_state :notify
...
def notify
  case state
  when 'uploading'
    description = 'Uploading in progress'
    icon = ':arrow_up:'
  ...
  end

  message = "#{icon} [#{id}] ... #{description}"
  PostCaptureStateChangeWorker.perform_async(message)
end

기대 동작: 각 단계는 밀리초 수준으로 끝나고 endpoint 전체 응답은 통상 <1s. 실제 관측: 단일 요청이 10.3s 로 튀었으나 응답은 200 OK. state 전이 실패 시 발생하는 Cupix::Errors::InvalidState 도 로그에 없음. 즉 예외 경로가 아니라 정상 경로 안에서 대기가 발생. 정상 경로에서 blocking 가능성이 있는 지점은 다음 3 곳이다.

1. Capture.find(self.model.capture_id) (video_repository.rb:317)
2. capture.reload (capture_material.rb:9)
3. PostCaptureStateChangeWorker.perform_async — Sidekiq/Redis push (notifiable/capture.rb:44)

이 셋 중 어느 것이 stall 했는지는 span-level trace 없이는 확정할 수 없다. Datadog log 상에는 slow-query warning, connection timeout, Redis 관련 warn/error 가 이 창(23:00~23:20 UTC)에 없었다.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api "VideosController#upload_url"
from 2026-07-29T22:00:00Z to 2026-07-29T23:59:00Z

결과: 3 건, 모두 200 OK. 슬로우 트레이스가 발생한 시각 직후의 access log 도 포함.

2026-07-29T23:15:50.509Z info [200] POST /api/v1/videos/703878/upload_url (Api::V1::VideosController#upload_url)
2026-07-29T23:14:39.042Z info [200] POST /api/v1/videos/703877/upload_url (Api::V1::VideosController#upload_url)
2026-07-29T23:13:29.262Z info [200] POST /api/v1/videos/703876/upload_url (Api::V1::VideosController#upload_url)

Datadog 쿼리 (같은 서비스의 error / warn 로그):

service:cupixworks-api status:error
from 2026-07-29T23:00:00Z to 2026-07-29T23:30:00Z

결과: 1 건. 완전히 다른 subscriber 관련 에러(UserRecipeGenerator — private method 'service_jwt'), upload_url 흐름과 무관.

service:cupixworks-api status:warn
from 2026-07-29T23:00:00Z to 2026-07-29T23:20:00Z

결과: 30건, 모두 다른 도메인(Capture#set_default_timezone, Cupix::Salesforce::Case::CaseSender, [Permission] Duplicate permission detected). Slow-query warning 또는 Sidekiq / Redis 관련 warning 은 없음.

Trace 별 로그 조회:

service:cupixworks-api @dd.trace_id:3188310188230743847

결과: 0 건 — 이 trace 에 대한 log-trace 상관 log 가 남아 있지 않아 span-level 세부 정보로 stall 지점을 특정할 수 없음.

Status board:

{
  "scope": "svc:cupixworks-api::unknown",
  "active": {
    "id": "2026-07-29-svc-cupixworks-api--unknown-1",
    "title": "cupixworks-api service degraded",
    "status": "open",
    "started_at": "2026-07-29T23:00:02.575Z",
    "cluster_ids": [
      "fde39d65-d51d-466c-9c01-5a5a6245ce10",
      "018f6326-a687-4e1a-919e-cf0739f18a49"
    ]
  }
}

같은 시각에 AerialPhotosController#index (33s, cluster fde39d65) 도 함께 감지되어 auto-grouped incident 로 open 됨. 두 endpoint 는 코드 경로가 완전히 다르므로(index 검색 vs single-record state 전이), 공통 원인 후보는 endpoint 별 코드 결함이 아니라 공유 인프라(PG connection pool, EC2 host, Redis) 쪽이다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 별도 코드 fix 대상 아님. 단일 tail-latency spike 로 재현이 없고 응답은 성공했다. 이 cluster 만 놓고는 hotfix 를 만들 이유가 없다.
• Status board 의 sibling incident 2026-07-29-svc-cupixworks-api--unknown-1 (with cluster fde39d65 AerialPhotosController#index) 를 함께 모니터링하고 재발 여부 확인.

단기 개선 (1주 이내)#

• Api::V1::VideosController#upload_url 경로에 span/instrumentation 을 추가하여 (1) Capture.find, (2) capture.reload, (3) PostCaptureStateChangeWorker.perform_async 각 구간의 시간을 측정할 수 있게 한다. 다음 재발 시 stall 이 정확히 어디에서 발생했는지 확정 가능. (파일: app/repositories/video_repository.rb:316-328, app/models/concerns/capture_material.rb:7-12, app/models/concerns/notifiable/capture.rb:44.)
• Datadog APM 에서 이 endpoint 의 resource_name:Api::V1::VideosController#upload_url slow-query trace sampling 을 100% 로 올려 다음 발생 시 span-level breakdown 을 확보.

장기 개선 (재발 방지)#

• state-machine 콜백 체인에서 동기적으로 수행되는 PostCaptureStateChangeWorker.perform_async 등 Redis 의존 호출을 after_commit 또는 명시적 non-blocking 경로로 분리해, HTTP 응답이 Redis 지연에 얽매이지 않게 한다.
• capture.reload 처럼 write 흐름 안에서 재조회하는 경로를 audit 하고 필요 시 in-memory state 로 대체.
• Sidekiq/Redis 및 PG connection pool 의 tail-latency 를 별도 SLO 로 트래킹 (아래 monitoring 참조).

Monitoring#

• Api::V1::VideosController#upload_url p95 / max 응답 시간 timeseries:

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::videoscontroller#upload_url}.rollup(avg, 60)

• 서비스 전체 max latency (재발 여부 및 endpoint 간 상관 확인):

max:trace.rack.request.duration{service:cupixworks-api,env:production} by {resource_name}.rollup(max, 60)

• Sidekiq enqueue 대기 시간(공유 원인 후보):

avg:sidekiq.enqueue.duration{service:cupixworks-worker} by {queue}.rollup(avg, 60)

• Rails 에러율(회귀 감지 baseline):

sum:trace.rack.request.errors{service:cupixworks-api,env:production}.as_rate()

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial (관측/모니터링 개선), standard (콜백 async 화 리팩터링을 하는 경우)