RCA: Api::V1::CapturesController#trash 지연 (10.8s)

Overview#

What Happened#

2026-07-18 10:51 KST 시점에 cupixworks-api 의 PUT /api/v1/captures/710206/trash 요청 한 건이 정상 응답(204)을 반환했으나 처리 시간이 10,841ms 로 관측됐다. Datadog APM trace.rack.request.duration 메트릭 기준으로 동일 리소스(api::v1::capturescontroller_trash) 는 24시간 동안 단 2번 호출됐고 직전 호출은 0.56s 였다 — 즉 이 요청은 baseline 대비 약 19배 느린 이례적 spike 다. 사용자는 응답을 정상 수신했지만 앞단 UI/클라이언트에서 hang 처럼 느꼈을 가능성이 있다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-18 10:51:07 KST — Cupix::NotificationService#create_user_recipe "Recipe creation failed" 에러 3건 발생 (연관 여부는 미확인 — 아래 Hypotheses 참조)
2. 2026-07-18 10:51:35–37 KST 추정 — 클라이언트가 PUT /api/v1/captures/710206/trash 를 전송 (요청 완료 시점 - duration 기준 역산)
3. 2026-07-18 10:51:45 KST — Capture#flush_child_cycle_state_in_worker 콜백이 실행되어 FlushCycleStateChildrenWorker job 을 enqueue (info log)
4. 2026-07-18 10:51:48 KST — Rails 가 204 응답을 반환하며 10,841ms 로 요청 종료
5. 2026-07-18 10:51:36 UTC (first_seen) — error-sweeper collector 가 latency cluster 로 감지

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::CapturesController#trash",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10841,
  "max_ms": 10841,
  "sample_trace_id": "3946220051729744103"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-18 10:51 KST
• 최근 발생: 2026-07-18 10:51 KST

Root Cause Summary#

PUT /api/v1/captures/710206/trash 요청 한 건이 10.8초 걸린 latency spike 다. 코드 경로 자체는 짧고(CyclableController#trash → CyclableRepository#trash → Capture#trash!), 정상적으로 완료돼 204를 반환했으며 동일 시각대에 이 capture ID(710206) 를 대상으로 하는 slow query / error / lock 로그는 관찰되지 않는다. 반면 Datadog APM 메트릭 기준 이 endpoint 는 24시간에 2회만 호출되는 저빈도 경로이고 직전 호출은 0.56s 였다. 즉 재현 신호 없이 발생한 일회성 spike 로, root cause 는 request-body 코드가 아닌 request 처리 중 실행되는 부수 작업(state machine 전이에 따른 Elasticsearch reindex, event publish, callback chain) 중 하나가 외부 의존성(ES/Redis) 대기에 의해 blocking 됐을 가능성 이 가장 유력하다. 확정하려면 trace 3946220051729744103 의 span breakdown 확인이 필요하며 본 RCA 시점에는 span-level evidence 를 수집하지 못했다 — uncertain, needs verification via APM.

Technical Analysis#

Code Path#

Entry point: app/controllers/concerns/cyclable_controller.rb:6-9

def trash
  repository.new(model: @model, current_user: current_user).trash
  render_api
end

before_action :set_capture (app/controllers/api/v1/captures_controller.rb:17) 가 먼저 실행돼 CaptureRepository#show(params[:id]) 로 @model 을 로드한다.

Repository trash: app/repositories/concerns/cyclable_repository.rb:6-11

def trash
  check_deletable_permission

  @model.cycle_state_updated_by_id = current_user.id if @model.has_attribute?(:cycle_state_updated_by_id)
  @model.trash!
end

Model trash!: app/models/concerns/cyclable.rb:293-310

def trash!
  set_cycle_state

  if skip_trash?
    purge!
  else
    run_callbacks :trash do
      if self.class.untrashable?
        trashing_cycle_state!
      else
        deleting_cycle_state!
      end
    end
  end

  delete_cache if respond_to?(:delete_cache)
  flush_cached_permissions if respond_to?(:flush_cached_permissions)
end

Cyclable::Capture 는 untrashable? == true 를 반환(app/models/concerns/cyclable/capture.rb:13-15) 이므로 trashing_cycle_state! state machine 이벤트가 실행된다. 이 전이는:

1. before_validation :set_cycle_state 와 before_transition 콜백에서 cycle_state_updated_at 세팅
2. run_callbacks :trash 안에서 다음 after_trash 콜백 실행 (app/models/concerns/cyclable.rb:389-390, app/models/concerns/cyclable/jobs_base.rb:8)

after_trash :flush_child_cycle_state_in_worker, if: proc { self.class.cycle_state_children_flushable? }
after_untrash :flush_child_cycle_state_in_worker, if: proc { self.class.cycle_state_children_flushable? }

def flush_child_cycle_state_in_worker
  Cupix::Logger.info("Requested to flush children with #{cycle_state} cycle_state for #{self.class.name} ID: #{id}", class: self.class.name, function: 'flush_child_cycle_state', id: id)

  Rails.cache.write("flush_cycle_state_latest:#{self.class.name}:#{id}", cycle_state, expires_in: 10.minutes)
  FlushCycleStateChildrenWorker.perform_at(10.seconds.from_now, self.class.name, id, cycle_state)
end

after_trash :stop_children_running_jobs
after_purge :stop_children_running_jobs

def stop_children_running_jobs
  raise NotImplementedError
end

3. EntityIndexable (Capture include, app/models/capture.rb:3) 가 cycle_state 컬럼 변경을 Elasticsearch 로 동기 반영 (Pano 로그에서 관찰된 _update_document 와 동일 code path 로 추정 — Capture 문서에 대해서도 실행)
4. Eventable::Events::Delete.create_event(self) — event publish (Kafka/pubsub)

Failure point (추정): app/models/concerns/cyclable.rb:293-310 trash! 실행 도중 실행되는 위 부수 작업 중 한 지점에서 외부 의존성 응답 지연 발생. 코드 자체가 아닌 데이터/의존성 관련 spike.

기대 동작 vs 실제 동작: baseline 0.56s (직전 호출) → 실제 10.84s. 코드는 정상 완료(204) 했지만 응답 시간이 20배 증가.

Log Evidence#

Datadog 쿼리 (재현):

service:cupixworks-api "710206"

시간 범위 2026-07-18T01:00:00Z–02:30:00Z. 결과 2건:

2026-07-18 10:51:48  info  [204] PUT /api/v1/captures/710206/trash (Api::V1::CapturesController#trash)
2026-07-18 10:51:45  info  Requested to flush children with trashed cycle_state for Capture ID: 710206
                          class=Capture function=flush_child_cycle_state

두 로그의 간격은 3초. flush_child_cycle_state_in_worker 는 after_trash 콜백이므로 이 로그 이후에 남은 처리(ES 동기 반영, event publish, controller render_api) 만 실행돼 3초 안에 완료됐다는 뜻이다. 따라서 나머지 ~7.8초는 set_capture (@model 로드) 부터 run_callbacks :trash 진입 및 trashing_cycle_state! 전이 실행 사이에 소비된 것으로 추정된다.

APM latency 메트릭 (24h):

max:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::capturescontroller_trash}

2026-07-17T18:30:00Z  0.564 s
2026-07-18T01:50:00Z  10.841 s

동일 window 의 error/warn 로그:

service:cupixworks-api status:error   (2026-07-18T01:45:00Z–02:00:00Z)

에러 6건 — 모두 Cupix::NotificationService (Recipe creation failed / Forbidden) 및 Cupix::PubSub::Subscribers::UserRecipeGenerator (private method service_jwt) 관련. capture 710206 이나 trash flow 와 직접 연결되는 스택 없음:

2026-07-18 10:51:07  Cupix::NotificationService#create_user_recipe  "Recipe creation failed"
2026-07-18 10:51:09  Cupix::NotificationService#subscribe          "Forbidden"
2026-07-18 10:54:29  Cupix::PubSub::Subscribers::UserRecipeGenerator#created  "private method service_jwt"

trace_id 3946220051729744103 기반 로그 검색은 Datadog API 400 (input_validation_error) 반환 — trace_id 로 로그 직접 조회 실패. Span 레벨 breakdown 은 미확인 (uncertain — needs verification).

Hypotheses Considered#

Confirmed root cause: 없음 — 단일 spike 로 span-level 증거가 필요. H1 (ES sync)/H5 (row lock)/H6 (pubsub publish) 중 하나 또는 조합. 재발 시 APM span breakdown 으로 확정 필요.

Fix Recommendation#

즉시 조치 (Critical)#

없음. 단일 이벤트(occurrence_count=1) 이고 요청은 정상 완료(204) 됐으며 사용자 데이터 손실/불일치 근거 없음. 즉시 코드 변경으로 대응할 필요 없음.

• 후속 조사 필요: trace 3946220051729744103 를 Datadog APM UI 에서 열어 span breakdown 확인. 특히 elasticsearch.query, redis.command, postgres.query, sidekiq.push 스팬의 duration 분포를 보고 어느 dependency 가 blocking 했는지 특정.

단기 개선 (1주 이내)#

• Capture#trash 요청 스레드에서 실행되는 ES sync 를 async 화 검토 — app/models/capture.rb:3 의 EntityIndexable 가 after_commit 훅에서 ES _update_document 를 동기 실행하는지 확인. 만약 sync 라면 cycle_state 변경 같은 자주 있는 갱신은 after_commit :reindex_async 패턴으로 offload 하여 request latency 로부터 격리.
• P99 latency 알림 설정 — 저빈도 endpoint 는 평균 metric 만 보면 감지가 늦다. Api::V1::CapturesController#trash 개별 endpoint 에 p99 > 5s 알림을 걸어 재발 시 즉시 감지.

장기 개선 (재발 방지)#

• Cycle state 전이 → child flush 파이프라인의 요청-스레드 처리 최소화 — 이미 FlushCycleStateChildrenWorker 로 자식 flush 는 sidekiq 로 옮겼음. 부모(capture) 자체의 ES 인덱스 sync 도 동일하게 offload 하여 request 처리 시간을 상수화.
• APM 스팬 태깅 강화 — Rails 커스텀 라이브러리(Cupix::Logger, Eventable::Events::Delete.create_event) 에서 시간 소요가 큰 구간을 span 으로 감싸 blocking dependency 를 자동으로 pinpoint 할 수 있게.

Monitoring#

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

p99:trace.rails.action_controller.duration{service:cupixworks-api,resource_name:api::v1::capturescontroller_trash}

Elasticsearch 스팬 latency 트렌드:

p95:trace.elasticsearch.query.duration{service:cupixworks-api}

Redis 스팬 latency 트렌드:

p95:trace.redis.command.duration{service:cupixworks-api}

PostgreSQL 스팬 latency (cycle_state UPDATE 검증용):

p95:trace.postgres.query.duration{service:cupixworks-api}

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial (즉시 조치 없음; 후속 조사 및 monitoring 강화만 수행)
• 사용자 영향: 단일 요청 10.8s 지연, 정상 응답. Data 정합성 이슈 없음. 재발 시 다시 조사 필요.