RCA: Api::V1::VideosController#create latency 10104ms (Faraday timeout on Elasticsearch)

Overview#

What Happened#

2026-06-25 14:31 KST에 ap-southeast-2 리전의 cupixworks-api에서 POST /api/v1/videos 요청 1건이 10,104 ms 동안 대기한 뒤 500으로 종료되었다. 응답을 끊은 직접 원인은 Faraday::TimeoutError: Operation timed out after 10002 milliseconds with 0 bytes received로, Elasticsearch 클라이언트에 설정된 request.timeout: 10초 한도에 정확히 걸렸다. 동시간대 같은 인스턴스/리전에서 다른 500이 관측되지 않아, 1회성 Elasticsearch slow response/네트워크 이슈로 판단된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-25 14:31:40 KST — APM에서 Api::V1::VideosController#create span 시작 (cluster first_seen).
2. 2026-06-25 14:31:42 KST — request_id d9a86d08-a08a-42df-b1a5-1113011a5e17로 요청 처리 시작 (500 응답 timestamp − duration 10087.91ms 역산).
3. 2026-06-25 14:31:52 KST — Faraday가 10,002 ms에서 timeout 발생, controller가 500 반환. db: 12.9 ms, duration: 10087.91 ms.
4. 2026-06-25 14:31:55 KST — 동일 endpoint에 다른 요청이 200으로 성공 (3초 뒤). 이후 14:32:05, 14:32:13 등에서도 정상 응답 확인.
5. 2026-06-25 14:32:00 KST 이후 — 동일 시간대, 동일 인스턴스에서 추가 500 미관측.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::VideosController#create",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10104,
  "max_ms": 10104,
  "sample_trace_id": "4184651080064739471"
}

Impact#

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

직접 사용자 영향은 1건의 video 생성 실패 (HTTP 500). 사용자는 동일 capture에 대해 재시도 시 정상 작동했을 가능성이 매우 높다 (3초 뒤 같은 endpoint가 200으로 성공). 데이터 손상이나 부분 저장 위험은 낮음 — BaseFactory#create!는 ActiveRecord save! 이후 after-commit 단계에서 Elasticsearch 인덱싱이 일어나므로, Postgres에는 video row가 commit되었을 수 있지만 ES 인덱싱은 실패. (단, controller가 500을 반환했기 때문에 사용자 측 client는 재시도를 트리거할 수 있고, 그 결과 Postgres에 중복 row가 만들어졌을 가능성은 있음 — 검증 필요.)

Root Cause Summary#

Api::V1::VideosController#create는 ActiveRecord Video#save! 이후 Searchable / EntityIndexable concern의 after_commit 훅에서 동기적으로 Elasticsearch에 문서를 인덱싱한다. Elasticsearch HTTP 클라이언트는 config/initializers/elasticsearch.rb에서 transport_options.request.timeout: 10(초)로 설정되어 있다. 이 단일 요청 처리 중 Elasticsearch 응답이 10초 안에 돌아오지 않아 Faraday가 Faraday::TimeoutError를 raise했고, 측정된 timeout 값(10002ms)과 controller duration(10087.91ms)이 설정과 정확히 일치한다. 동시간대 같은 서비스/host에서 다른 500이나 ES 관련 에러가 관측되지 않아 1회성 Elasticsearch slow response 또는 전송 경로 stall로 판단되며, 만성적 버그라기보다는 노이즈 cluster에 가깝다. 다만 단일 사용자 요청이 ES 일시 지연만으로 10초 응답 + 500을 받게 되는 동기 인덱싱 의존도가 잠재적 약점이다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/videos_controller.rb:35

def create
  @model = factory_instance.create!(params)

  super
end

VideoFactory가 capture를 로드하고 BaseFactory#create!에 위임:

def create!(params = {})
  self.model = ::Video.new

  if params[:capture_id].present?
    self.parent = CaptureRepository.new(current_user: self.current_user).show(params[:capture_id])
  elsif params[:capture].present?
    self.parent = CaptureRepository.new(current_user: self.current_user).show(params[:capture])
  else
    raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'capture_id is required')
  end
  # ...
  self.model.capture = self.parent
  set_camera_params(params)
  super
end

BaseFactory#create!가 save!로 Postgres에 저장 → after-commit 트리거:

begin
  self.model.save!
  self.model
rescue Elasticsearch::Transport::Transport::Errors::BadRequest => e
  raise e
rescue NoMethodError => e
  raise Cupix::Errors::System.new(code: 'SYS10003', reason: e.message)
rescue ActiveRecord::RecordInvalid => e
  raise Cupix::Errors::Entity.new(code: 'ENT10005', reason: e.message)
rescue StandardError => e
  raise e if e.is_a?(Cupix::Errors::BaseError)

  raise Cupix::Errors::System.new(code: 'SYS50000', reason: e.message)
end

Video 모델은 Searchable::Video + EntityIndexable를 include하므로 after_commit on: :create에서 ES 인덱싱이 실행됨:

after_commit on: [:create] do
  _index_document
end
# ...
def _index_document
  return if @skip_index_document == true

  indexed_json = __elasticsearch__.as_indexed_json
  base_request = {
    id: __elasticsearch__.id,
    body: indexed_json
  }

  results = __elasticsearch__.client.index(base_request.merge(index: __elasticsearch__.index_name))
  Cupix::Logger.debug(results.to_json, class: self.class.name, function: __method__)

  if (tmp_index = self.class.fetch_tmp_index_name)
    __elasticsearch__.client.index(base_request.merge(index: tmp_index))
  end
rescue StandardError => e
  Cupix::Logger.error("Index error - #{e.message}", class: self.class.name, function: __method__)
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')
end

Failure point: Elasticsearch 클라이언트의 transport timeout이 정확히 10초:

Elasticsearch::Model.client = ConnectionPool::Wrapper.new(size: 10, timeout: 7) {
  Elasticsearch::Client.new(
    host: ENV.fetch('RAILS_ES_HOST') { 'localhost' },
    port: ENV.fetch('RAILS_ES_PORT') { DEFAULT_RAILS_ES_PORT },
    user: ENV['RAILS_ES_USER'],
    password: ENV['RAILS_ES_PASSWORD'],
    transport_options: {
      request: {
        timeout: 10
      }
    }
  ) do |faraday|
    if Rails.env.development?
      faraday.response :logger, Logger.new($stdout, level: :info)
    end
  end
}

기대 동작: ES 인덱스 호출이 수십~수백 ms 안에 완료되어야 함. 실제 동작: 단일 요청에서 ES write가 10초간 응답하지 않아 Faraday가 Faraday::TimeoutError를 raise. _index_document의 rescue StandardError가 잡아 BulkIndexWorker.perform_async로 폴백할 것으로 기대되지만, Datadog에는 해당 "Index error - ..." 로그가 관측되지 않았다 (@class:Video "Index error" 쿼리 결과 0건 — uncertain: 로그가 누락된 것인지, 다른 ES 경로(_entity_index_document)에서 raise가 새어나간 것인지, 또는 Cupix::Logger가 Datadog로 라우팅되지 않는 경로인지 확인 필요).

EntityIndexable._entity_index_document도 동일한 ES client를 사용하며 별도의 rescue StandardError를 갖지만, transport-level 호출이라 동일한 timeout 영향을 받는다:

def _entity_index_document
  return if @skip_index_document == true

  Elasticsearch::Model.client.index(
    index: self.class.entity_index_name,
    id: entity_document_id,
    body: as_entity_indexed_json
  )
rescue StandardError => e
  Cupix::Logger.error("Entity index error - #{e.message}", class: self.class.name, function: __method__)
end

Log Evidence#

Datadog query (request 단위 추적):

service:cupixworks-api @request_id:d9a86d08-a08a-42df-b1a5-1113011a5e17

결과: 1건의 request summary log만 존재 (해당 controller 내부에서 추가 로그 없음).

500 응답 raw 로그 (요점만):

{
  "timestamp": "2026-06-25T05:31:52.280Z",
  "message": "[500] POST /api/v1/videos (Api::V1::VideosController#create)",
  "error": [
    "Faraday::TimeoutError",
    "Operation timed out after 10002 milliseconds with 0 bytes received"
  ],
  "duration": 10087.91,
  "db": 12.9,
  "controller": "Api::V1::VideosController",
  "action": "create",
  "http": { "status_code": 500, "method": "POST", "url_details": { "path": "/api/v1/videos" } },
  "params": {
    "name": "VID_20260625_172428_00_215.insv",
    "capture_id": 78513,
    "uuid": "144ef4a2-a08a-4b57-8acd-2a95fb7d01c1"
  },
  "user": { "id": 6221, "email": "mitch.ottley@naylorlove.co.nz", "team": { "id": 22 } },
  "tenant": "cupix",
  "host": { "name": "ip-10-1-16-114.ap-southeast-2.compute.internal" },
  "tags": [
    "region:ap-southeast-2",
    "version:production-ap-southeast-2-20260625t0505z0-24b9962e-cupixworks"
  ]
}

핵심 수치 비교 — duration: 10087.91 ms vs db: 12.9 ms → 약 99.9%의 시간이 Postgres 외부(=ES Faraday 호출 대기)에서 소모되었다. Faraday::TimeoutError after 10002 milliseconds는 config/initializers/elasticsearch.rb:25의 request.timeout: 10초 설정과 정확히 일치한다.

주변 요청 비교 (동일 controller#create):

service:cupixworks-api @http.url_details.path:*videos* status:info
(2026-06-25T05:31:00Z ~ 2026-06-25T05:33:00Z)

같은 host(ip-10-1-16-114)와 전체 서비스에서 같은 15분 윈도우 동안 다른 500은 관측되지 않았다:

service:cupixworks-api @http.status_code:500
(2026-06-25T05:25:00Z ~ 2026-06-25T05:40:00Z)
→ 1 log

상태 보드도 svc:cupixworks-api::unknown 스코프에 동시 진행 중인 incident 없음(active: null) 확인. 직전 24시간에 동일 스코프의 incident가 2건 resolved 상태로 있었으나 (2026-06-24-svc-cupixworks-api--unknown-1/2) 본 cluster와의 직접 인과 증거는 없다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

본 cluster는 1회성 latency 이벤트이고 광범위한 영향 없음 — 즉시 코드 수정은 불필요. 모니터링과 사용자 데이터 정합성 확인이 우선.

• Postgres에 capture_id=78513, name VID_20260625_172428_00_215.insv, user_id 6221의 video row가 commit되었는지 확인 (DB 검증). after_commit에서 timeout이 발생한 경우 Postgres에는 row가 이미 존재할 수 있음. 사용자가 재시도했다면 중복 row 가능성 검사.
• 해당 row가 ES에 색인되었는지 확인. 누락 시 BulkIndexWorker가 fallback으로 색인했는지, 또는 수동 재색인 필요한지 결정.

단기 개선 (1주 이내)#

• Searchable._index_document / EntityIndexable._entity_index_document의 rescue 경로가 실제로 BulkIndexWorker로 폴백하는지 — 그리고 그 fallback 자체가 controller 응답을 5xx로 보내지 않는지 — 검증. 본 케이스는 응답이 500으로 나왔으므로, after-commit 안에서 raise된 예외가 controller까지 전파되는 경로가 있을 가능성이 있음 (Cupix::Errors::System 래핑 또는 Searchable 외부에서의 ES 호출). 코드 경로 보강: app/models/concerns/searchable.rb:43,48 및 app/models/concerns/entity_indexable.rb:163-167의 rescue가 모든 Faraday/Elasticsearch transport 예외를 잡는지 (예: Elasticsearch::Transport::Transport::Errors::*는 StandardError 하위가 아닐 수 있음) 확인.
• ES 단일 호출 timeout(request.timeout: 10)이 web 요청 SLA 대비 너무 크다. p99 응답이 100ms 미만일 ES write에 대해 10초 대기는 사용자 경험을 망친다. 단축(예: 1.5–2초) + retry 1회 정책을 검토. 위치: config/initializers/elasticsearch.rb:25.

장기 개선 (재발 방지)#

• after-commit 동기 ES 인덱싱을 기본 비동기로 전환. 즉, write path에서 항상 BulkIndexWorker.perform_async로 enqueue하고 controller는 ES 응답을 기다리지 않게 한다. 현재 구조는 ES 한 호출의 latency가 그대로 API p99에 누적된다.
• Datadog에 Elasticsearch transport 단위 메트릭/트레이스 추가 (현재는 controller-level duration만 있음). Datadog::Tracing.active_span&.set_tag('elasticsearch.duration', ...)는 search 응답 한정 (elasticsearch.rb:48); index/update path에도 동일 태그 노출.

Monitoring#

추가/검토 권장 Datadog timeseries (release dashboard 위젯용):

• 분 단위 Faraday timeout 발생 건수 (cupixworks-api):

  textCopy

  sum:trace.rack.request.errors\{service:cupixworks-api,error_type:Faraday::TimeoutError\}.as_count()
  

• VideosController#create 500 응답 카운트:

  textCopy

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

• VideosController#create p95/p99 latency:

  textCopy

  p95:trace.rack.request\{service:cupixworks-api,resource_name:Api::V1::VideosController#create\}
  

  textCopy

  p99:trace.rack.request\{service:cupixworks-api,resource_name:Api::V1::VideosController#create\}
  

• Elasticsearch client request duration (가능한 경우):

  textCopy

  avg:trace.elasticsearch.query\{service:cupixworks-api\}
  

알림 권장: 동일 endpoint에서 10초 근처 latency가 5분 내 ≥3건 발생 시 알림 (다중 발생 시에만 — 단일 1회 이벤트는 노이즈).

Risk Assessment#

• Risk level: low (1회성, 단일 사용자, 동일 endpoint 즉시 회복)
• 예상 복잡도: trivial (코드 변경 불필요. DB/ES 정합성 확인 + 모니터링 추가 정도)