RCA: Api::V1::SitetracksController#create_sitetrack_upload_credentials 429s latency

Overview#

What Happened#

2026-07-17 16:13 KST 경 production cupixworks-api (us-west-2) 에서 POST /api/v1/sitetracks/21583/sitetrack_upload_credentials 요청 1건이 429,113 ms (약 7분 9초) 소요된 후 HTTP 200 으로 완료됨. 동일 시간대에 다른 요청들에서 MySQL LockWaitTimeout (captures/736633/check_voxels_uploading 502) 과 Elasticsearch 10 초 request timeout (Admin::CaptureRepository) 이 반복 관측되어, 인프라 수준의 정체가 요청 지연의 배경으로 확인됨. 요청 자체는 성공했지만 응답 시간이 정상값(수백 ms) 대비 세 자릿수 이상 벌어져 클라이언트 측 UX 및 재시도 정책에 영향을 줄 수 있음.

Quick Facts#

Affected Teams#

status-board 는 이 클러스터를 활성 인시던트 2026-07-17-svc-cupixworks-api--unknown-1 (started 2026-07-17T07:06:57Z) 에 포함시켜 그룹으로 관리 중.

Timeline#

1. 2026-07-17 16:04 KST — UserRecipeGenerator 관련 service_jwt NoMethodError 다수 발생 (별개 이슈, 배경 노이즈).
2. 2026-07-17 16:10 KST — Uuidable::UuidValidator 가 ES 10 초 timeout 을 감지 ("Operation timed out after 10002 milliseconds with 0 bytes received"). ES 응답 지연 신호 시작.
3. 2026-07-17 16:13:58 KST — 문제의 slow trace 시작 (first_seen 을 KST 로 변환한 시각). Sitetrack 21583 대상 create_sitetrack_upload_credentials 진입.
4. 2026-07-17 16:14:57 KST — Sitetrack 21583 의 다른 처리 (Sitetrack.notify, Job 1205223 job_stopped_callback) 가 완료되어 다수 write / ES index 콜백이 동시 실행됨.
5. 2026-07-17 16:15:34 → 16:20:26 KST — PUT /api/v1/captures/736633/check_voxels_uploading 이 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 로 6 회 반복 실패 (502). DB row-lock 경합 확인.
6. 2026-07-17 16:20:38 → 16:20:42 KST — Admin::CaptureRepository 에서 ES 10 초 timeout 이 7 회 연속 발생.
7. 2026-07-17 16:27:39 KST — 문제의 요청이 최종적으로 HTTP 200 응답 (총 429,113 ms 소요).
8. 2026-07-17 16:33 KST — RCA 착수 (본 문서).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::SitetracksController#create_sitetrack_upload_credentials",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 429113,
  "max_ms": 429113,
  "sample_trace_id": "8677574539610561917"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-17 16:13 KST
• 최근 발생: 2026-07-17 16:13 KST
• 연관 인시던트: status-board 2026-07-17-svc-cupixworks-api--unknown-1 (cluster dc0e4dfd-3500-4645-9143-ceda3edf71e4 — BimsController#check_uploading 25 초 동일 창에서 발생)

Root Cause Summary#

SitetracksController#create_sitetrack_upload_credentials 는 SitetrackRepository#create_sitetrack_upload_credentials → Sitetrack#sitetrack_upload_credentials 를 호출한다. 이 메서드는 (1) self.uploading_sitetrack_state state_machine event 를 발화하여 sitetracks 레코드에 save! 를 수행하고, (2) STS get_federation_token 을 동기 호출한다. save! 의 after_commit 에서는 elasticsearch-model 의 _update_document 가 동기적으로 ES client.update 를 호출한다 (app/models/concerns/searchable.rb:16-17, 55-121). 사고 시각(16:15–16:20 KST) 에는 (a) MySQL row-lock 경합 (captures/736633 에서 반복 LockWaitTimeout), (b) ES 요청 stall (10 초 request timeout 다수 관측) 이 동시에 진행 중이었다. 이 상황에서 sitetrack 저장/ES 인덱싱 경로가 정상 응답 대비 매우 느려졌고, after_commit 안에서 ES 예외가 Faraday::TimeoutError/Elasticsearch::Transport::Transport::Error 로 잡히기 전 여러 번 재시도되는 조합으로 요청이 429 초 동안 열려 있었다. 즉, 이 트레이스는 코드 결함이 아니라 공유 인프라(ES/DB) 정체가 sitetrack 업로드 자격증명 발급 경로에 흘러들어간 결과이며, 요청 경로 자체가 after_commit 에서 ES 콜을 인라인으로 수행하는 구조라 정체가 그대로 요청 지연으로 노출된다.

Technical Analysis#

Code Path#

• Entry: app/controllers/api/v1/sitetracks_controller.rb:43-47
• Repository: app/repositories/sitetrack_repository.rb:27-31
• Model: app/models/concerns/sitetrack_result/s3.rb:30-39
• State machine event (write path): app/models/concerns/statable/sitetrack.rb:89-128
• Elasticsearch sync callback: app/models/concerns/searchable.rb:16-17, app/models/concerns/searchable.rb:55-121
• Elasticsearch client config: config/initializers/elasticsearch.rb:17-34

def create_sitetrack_upload_credentials
  credentials = repository_instance.create_sitetrack_upload_credentials

  render_json 200, credentials
end

def create_sitetrack_upload_credentials
  raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied') unless @model.updatable_by?(self.current_user)

  @model.sitetrack_upload_credentials
end

def sitetrack_upload_credentials
  self.uploading_sitetrack_state          # state_machine event → save! → after_commit → ES sync update

  Cupix::StorageService.upload_credentials( # STS get_federation_token (동기)
    storage_option: storage_option,
    id: id,
    bucket_name: storage_option.s3_hosting_bucket_name,
    key: sitetrack_basepath(sitetrack_upload_revision)
  )
end

after_commit on: [:update] do
  _update_document
end

# ...

def _update_document
  # ...
  results = __elasticsearch__.client.update(request.merge({ index: __elasticsearch__.index_name }))
  # ...
rescue Faraday::TimeoutError => e
  Cupix::Logger.error("TimeoutError - #{e.message}", class: self.class.name, function: __method__)
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')
rescue Elasticsearch::Transport::Transport::Error => e
  Cupix::Logger.error("ElasticsearchError - #{e.message}", class: self.class.name, function: __method__)
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')
rescue StandardError => e
  Cupix::Logger.error("StandardError - #{e.message}", class: self.class.name, function: __method__)
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')
end

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|
    ...
  end
}

기대 동작 vs 실제 동작.

• 기대: 요청 전체가 수백 ms 안에 완료 (state 전이 DB write + STS get_federation_token 호출).
• 실제: 429 초 소요. after_commit 안 ES client.update 가 stall 상태의 ES 로 인해 10 초 timeout 을 여러 번 겪거나, 앞선 DB 트랜잭션이 다른 트랜잭션의 row-lock 을 기다리며 지연됨. ES stall 시 client.update 는 rescue 후 BulkIndexWorker.perform_async 로 fallback 하지만, 그 rescue 전 각 attempt 는 10 초를 소모하고 Faraday connection reuse 및 connection-pool checkout timeout(7 초) 이 추가로 누적된다.

Log Evidence#

Datadog 쿼리 (재현용):

service:cupixworks-api trace_id:8677574539610561917

service:cupixworks-api "create_sitetrack_upload_credentials"

service:cupixworks-api status:error

service:cupixworks-api "TimeoutError" OR "10002 milliseconds"

Slow 요청 자체는 성공 로그만 남김 (info 레벨):

{
  "timestamp": "2026-07-17 16:27:39 KST",
  "status": "info",
  "message": "[200] POST /api/v1/sitetracks/21583/sitetrack_upload_credentials (Api::V1::SitetracksController#create_sitetrack_upload_credentials)"
}

동일 창의 ES timeout:

{
  "timestamp": "2026-07-17 16:20:42 KST",
  "status": "error",
  "message": "Operation timed out after 10002 milliseconds with 0 bytes received",
  "class": "Admin::CaptureRepository"
}

동일 창의 MySQL lock-wait:

{
  "timestamp": "2026-07-17 16:20:26 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/captures/736633/check_voxels_uploading (Api::V1::CapturesController#check_voxels_uploading)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

Uuid 검증도 ES 응답 지연을 보고:

{
  "timestamp": "2026-07-17 16:11:20 KST",
  "status": "warn",
  "message": "ES timeout/connection failure during uuid validation. Rejecting request because uuid uniqueness could not be verified. reason: Operation timed out after 10002 milliseconds with 0 bytes received",
  "class": "Uuidable::UuidValidator",
  "function": "uuid_used_in_other_models?"
}

Sitetrack 21583 자체는 slow 요청 이전(16:14:57 KST)에 processing 완료 이벤트(Sitetrack.notify, Job 1205223 job_stopped_callback done) 를 발생시켰고, 같은 sitetrack 에 대한 다른 create_sitetrack_upload_credentials (16:14:40, 16:27:39 KST) 는 200 으로 정상 응답. slow 트레이스만 지연되어 남았다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 없음. 요청은 최종 200 으로 성공했고, 근본 원인은 애플리케이션 로직이 아니라 공유 ES/DB 정체다. status-board 인시던트 2026-07-17-svc-cupixworks-api--unknown-1 의 추적을 이어가고, 같은 창의 LockWaitTimeout 발생 리소스(captures/736633) 를 소유한 팀과 함께 원인(장기 트랜잭션 / hot row) 을 확인할 것.

단기 개선 (1주 이내)#

• sitetrack_upload_credentials 의 state 전이 필요성 재검토 — app/models/concerns/sitetrack_result/s3.rb:31 에서 자격증명 발급 시마다 uploading_sitetrack_state 를 강제 발화하고 있어 매 요청마다 DB write + ES sync 인덱싱이 동반된다. 이미 uploading 상태이거나 짧은 재발급인 경우 skip 하거나, 상태 전이를 STS 호출 이후로 옮겨 실패 시 부작용을 최소화하는 방향을 검토.
• Searchable#_update_document 를 비동기 기본으로 전환하는 실험 — 현재는 동기(__elasticsearch__.client.update) → 실패 시 BulkIndexWorker.perform_async fallback (app/models/concerns/searchable.rb:94, 112-120). 응답 시간에 민감한 컨트롤러(예: sitetrack 자격증명 발급) 경로에서는 인덱싱을 항상 async 로 위임하도록 옵션(skip_index_document! 유사) 을 명시 사용하는 것을 고려. 단, 다른 컨트롤러 동작(즉시 검색 반영 등) 과의 호환성을 반드시 확인.
• ES client 회로차단(circuit breaker) 도입 — 10 초 timeout 이 짧은 시간 안에 연속 발생하면 이후 호출을 즉시 fail-fast 로 전환하도록 랩. 현재 rescue 후 BulkIndexWorker.perform_async 로 fallback 은 있으나, 각 attempt 는 여전히 10 초를 소모.

장기 개선 (재발 방지)#

• Sitetrack write 경로에서 ES 인덱싱 완전 분리 — 인덱싱은 outbox / async worker 로 위임하여 API 응답 latency 를 ES 헬스에서 격리.
• APM 응답시간 SLO 및 자동 경보 — resource_name:api::v1::sitetrackscontroller#create_sitetrack_upload_credentials 에 대한 p95/p99 SLO 및 5 초 초과 경보 추가.
• DB row-lock 이슈(별건, captures/736633) 의 근본 원인 분리 조사 — 이 인시던트의 배경이자 반복 발생 가능성이 있으므로, capture voxel upload 상태 갱신 트랜잭션 범위 축소를 검토.

Monitoring#

• p95 응답시간 관측 (metric):

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::sitetrackscontroller#create_sitetrack_upload_credentials}

• 이 리소스의 slow 요청 수 (log search):

service:cupixworks-api "create_sitetrack_upload_credentials" @duration:>5000000000

• 동일 창에서 재현되는 ES timeout 카운트 (log search):

service:cupixworks-api status:error "Operation timed out after 10002 milliseconds"

• MySQL lock-wait 카운트 (log search):

service:cupixworks-api "Lock wait timeout exceeded"

Risk Assessment#

• Risk level: medium — 단발성 slow trace 이지만 status-board 상 같은 창에서 다른 리소스(BimsController#check_uploading) 지연이 함께 잡혔고, 원인이 특정 코드 결함이 아니라 공유 인프라 정체이므로 재발 가능성이 있음.
• 예상 복잡도: standard — 즉시 코드 수정은 불필요. 인덱싱 async 전환/서킷브레이커 도입은 다중 모델에 영향을 주므로 표준 규모의 변경.