RCA: Api::V1::ReviewsController#load latency (10529ms)

Overview#

What Happened#

2026-07-10 22:47 KST 경, cupixworks-api production 환경 (us-west-2) 에서 GET /api/v1/reviews/goj0cu/load 요청이 10529ms 걸린 뒤 500 으로 종료됐다. 근본 원인은 ReviewRepository#records 가 호출한 Elasticsearch (::Record.search) 쿼리가 Faraday HTTP client 의 10 초 request timeout (Faraday::TimeoutError) 에 걸린 것이며, 해당 예외는 fallback 대상이 아니라 그대로 상위로 재-raise 되어 500 이 반환됐다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-10 22:47:28 KST — 이전 동일 controller 요청 (k2dfc9/load) 은 200 정상 응답
2. 2026-07-10 22:47:33 KST (±) — goj0cu/load 진입, ReviewRepository#load 가 compute_load_info 경로로 들어가 _record_ids 를 호출 → records → ::Record.search 로 ES 요청 전송 (trace first_seen)
3. 2026-07-10 22:47:45 KST — Failed to get records - Operation timed out after 10002 milliseconds with 0 bytes received (status:error, class:ReviewRepository, function:records) 로그 기록
4. 2026-07-10 22:47:45 KST — 동일 시점에 [500] GET /api/v1/reviews/goj0cu/load 로그, error 배열 ["Faraday::TimeoutError", "Operation timed out after 10002 milliseconds with 0 bytes received"]
5. 2026-07-10 22:47:51 KST — 이후 동일 controller 의 다른 review (73538) 는 501.85ms 로 정상 처리 재개

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ReviewsController#load",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10529,
  "max_ms": 10529,
  "sample_trace_id": "3513346690022485002"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (trace 기준). 다만 동일 ES timeout 시그니처는 최근 7일 동안 20+ 회 다른 repository 에서 관측됨 (아래 Log Evidence 참고)
• 최초 발생: 2026-07-10 22:47 KST
• 최근 발생: 2026-07-10 22:47 KST
• 사용자 영향: Review 상세 화면 최초 로드 시 10초간 hang 후 500. cache miss (LIVE_FACILITY_INVALIDATED / LIVE_FRESH 경로) 인 첫 요청만 영향을 받으며, cache hit (CACHE 경로) 은 1~3ms 로 정상 응답 중

Root Cause Summary#

Api::V1::ReviewsController#load 는 ReviewRepository#load 를 호출하고, cache miss 시 compute_load_info → _record_ids / _level_ids 를 통해 AccessibleEntitiesRepository::Review#records / #levels 가 실행된다. 두 메서드는 ::Record.search(...).records 와 ::Level.search(...) 로 Elasticsearch 를 호출하는데, config/initializers/elasticsearch.rb 에서 Faraday transport 의 request.timeout 이 10 초로 고정되어 있다. 이 시점에 ES 응답이 10 초를 넘기면 Faraday::TimeoutError 가 던져진다. records / levels 는 rescue Faraday::ConnectionFailed 로 legacy DB fallback 을 하지만, TimeoutError 는 rescue => e 로 잡혀 Cupix::Logger.error("Failed to get records - #{e.message}") 만 남긴 뒤 그대로 raise e 한다. 그 결과 요청은 fallback 없이 10초 timeout 을 소모하고 500 으로 실패한다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/reviews_controller.rb:95-106

def load
  fresh = params[:fresh].present? && ActiveRecord::Type::Boolean.new.cast(params[:fresh])
  load_info = repository_instance.load(fresh: fresh)

  render_api Renderable.new({
    contents: @model,
    serializer: ReviewLoadSerializer,
    serializer_option: {
      params: { load_info: load_info }
    }
  })
end

Cache miss 분기에서 compute_load_info 실행:

else
  # Invalidate and recompute if facility cache is invalid
  Rails.cache.delete(review_cache_key)
  compute_start = Time.current
  computed_result = compute_load_info
  ...
end

compute_load_info 는 _record_ids / _level_ids 로 여러 exists? 쿼리를 만든다:

def compute_load_info
  level_ids = _level_ids
  record_ids = _record_ids
  facility_id = @model.facility_id

  {
    assets: ::Asset.where(assetable_type: 'Review', assetable_id: @model.id, cycle_state: 'created').exists?,
    ...
    spacetimes: @model.spacetimes.where(level_id: level_ids, record_id: record_ids).exists?,
    ...
  }
end

_record_ids / _level_ids 는 Rails.cache miss 시 records / levels 를 호출:

def _record_ids(from_at: nil, to_at: nil, visibility: Cyclable.visibility[:UNTRASHED])
  _cache_key = cache_key('record_ids').merge!({ from_at: from_at, to_at: to_at, visibility: visibility })
  Rails.cache.fetch(_cache_key, expires_in: DEFAULT_PERMISSION_CACHE_EXPIRES_IN) do
    Cupix::Logger.info("Flushing record_ids on review #{model.key}", ...)

    record_ids(from_at: from_at, to_at: to_at, visibility: visibility)
  end
end

Failure point: app/repositories/concerns/accessible_entities_repository/review.rb:10-18 — Faraday::TimeoutError 가 Faraday::ConnectionFailed fallback 을 우회한 뒤 그대로 re-raise 된다.

def records(from_at: nil, to_at: nil, visibility: Cyclable.visibility[:UNTRASHED])
  accessible_records(from_at: from_at, to_at: to_at, visibility: visibility)
rescue Faraday::ConnectionFailed
  Cupix::Logger.warn('Failed to get records from ES. Try to get records from legacy.', class: self.class.name, function: __method__)
  accessible_records_legacy(from_at: from_at, to_at: to_at, visibility: visibility)
rescue => e
  Cupix::Logger.error("Failed to get records - #{e.message}", class: self.class.name, function: __method__)
  raise e
end

ES client 의 10초 request timeout 설정:

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
      }
    }
  )

기대 동작: ES 가 느리면 Faraday::ConnectionFailed 와 유사하게 legacy DB fallback (accessible_records_legacy) 이 동작해 사용자에게는 200 이 반환되어야 한다.

실제 동작: Faraday::TimeoutError 는 별도 rescue 절이 없어 rescue => e 로 잡히고 재-raise 되어, controller 최상단까지 올라가 500 응답이 된다. 소요 시간은 정확히 timeout 값 (10002ms ≈ 10529ms trace 총합) 이다.

Log Evidence#

사용한 Datadog 쿼리 (재현 가능):

service:cupixworks-api "ReviewsController#load"
  from: 2026-07-10T13:47:20Z to 2026-07-10T13:47:50Z

정확 시각의 500 응답 로그:

{
  "timestamp": "2026-07-10 22:47:45 KST",
  "status": "info",
  "message": "[500] GET /api/v1/reviews/goj0cu/load (Api::V1::ReviewsController#load)",
  "error": [
    "Faraday::TimeoutError",
    "Operation timed out after 10002 milliseconds with 0 bytes received"
  ]
}

같은 시각 repository 레벨 error 로그 (review.rb:16 의 Cupix::Logger.error 출력):

{
  "timestamp": "2026-07-10 22:47:45 KST",
  "status": "error",
  "message": "Failed to get records - Operation timed out after 10002 milliseconds with 0 bytes received",
  "class": "ReviewRepository",
  "function": "records"
}

주변 정상 요청 (대조군, cache hit 은 13ms, cache miss 는 801300ms 로 완료됨):

2026-07-10 22:47:28 KST | ReviewRepository#load | review_id=72383 | cache_source=LIVE_FACILITY_INVALIDATED | compute_time=112.7ms
2026-07-10 22:47:51 KST | ReviewRepository#load | review_id=73538 | cache_source=LIVE_FACILITY_INVALIDATED | compute_time=501.85ms

동일 timeout 시그니처 (Operation timed out after 10002 milliseconds) 가 최근 7일 동안 여러 repository 에서 반복됨:

service:cupixworks-api "Operation timed out"  (now-7d, 30+ hits)
2026-07-10 22:47:45 | ReviewRepository#records
2026-07-10 21:59:14 | EditingEntityRepository
2026-07-10 20:27:10 | EditingEntityRepository
2026-07-10 20:27:07 | Admin::PointcloudRepository
2026-07-10 18:08:35 | PanoRepository
2026-07-10 15:57:25 | RecordRepository
2026-07-10 15:57:19 | Admin::CaptureRepository (x2)
2026-07-10 15:57:08 | Admin::CaptureRepository
2026-07-10 11:21:49 | WorkareaRepository
2026-07-10 11:21:46 | WorkareaRepository
2026-07-10 11:21:45 | AssetRepository
2026-07-10 05:14:28 | ReviewRepository#captures  ← 동일 concern, captures 경로
2026-07-10 04:24:44 | ClusterRepository
2026-07-10 03:40:13 | VideoRepository
2026-07-10 00:21:xx | Pano#_update_document (x12)

특정 code path 만의 문제라면 이렇게 다양한 클래스에서 동시에 나타나지 않는다 — Elasticsearch cluster 응답성 저하 (인덱스 refresh, hot shard, 리소스 포화 등) 가 상위 원인일 가능성이 크다. 다만 이 RCA 는 cluster-측 원인 특정을 위한 ES metric 을 직접 조회하지 않았다 — uncertain -- needs verification (ES cluster health, _cat/indices, slow log).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/concerns/accessible_entities_repository/review.rb 의 records, levels, captures, annotation_layers, bims, floorplans 각각의 rescue Faraday::ConnectionFailed 절에 Faraday::TimeoutError (또는 상위 Faraday::Error 중 timeout/connection 계열) 를 함께 포함시켜 legacy DB fallback 이 timeout 상황에서도 동작하게 한다. 이때 fallback 은 최소 warn 레벨로 기록해 자주 fallback 되는 상황을 감지할 수 있게 한다. 단, Elasticsearch::Transport::Transport::Errors::* 계열 (5xx, 4xx application error) 은 fallback 대상이 아닐 수 있으므로 예외 클래스 목록을 명시적으로 선정한다.
• 위 concern 이 EditingEntityRepository, PanoRepository, CaptureRepository, WorkareaRepository, RecordRepository, AssetRepository, ClusterRepository, VideoRepository, Admin::*Repository 에도 동일 패턴으로 존재하는지 확인이 필요하다. 로그상 이들 클래스에서도 동일 timeout 을 재-raise 하고 있어, 광범위한 rescue 절 재검토가 필요함 (uncertain -- needs verification: 이 RCA 에서는 AccessibleEntitiesRepository::Review 만 확인).

단기 개선 (1주 이내)#

• Faraday request.timeout 을 사용자가 눈에 띄는 지연을 겪지 않을 값 (e.g. 3–5 초) 으로 낮추고, fallback 이 확실히 동작하는지 부하 테스트로 검증. 현재 10 초는 사용자가 명확히 hang 을 인지하는 값.
• ReviewRepository#compute_load_info (review_repository.rb:558-585) 의 14 개 exists? 쿼리를 aggregate 형태로 묶거나 Elasticsearch 의존성을 줄여 첫 캐시 miss 지연을 낮춘다 (현재 정상 경로도 80–1319ms). 사용자가 처음 review 를 열 때마다 10 개+ 의 exists? 를 순차 실행하는 구조는 근본적으로 SLO 취약.
• ES cluster health (JVM heap, GC, hot shard, index refresh interval) 를 확인해 상위 원인이 cluster 측인지 특정 index/query 측인지 규명. service:cupixworks-api "Operation timed out" 이 다수 repository 에 걸쳐 있는 점은 cluster-측 원인일 가능성을 시사.

장기 개선 (재발 방지)#

• ES 를 호출하는 모든 repository concern 에 대해 공통 fallback strategy (연결 실패 · timeout · 5xx) 를 helper 로 추출하고, "ES 는 optional, DB 는 truth" 라는 계약을 코드로 명시.
• SLO 기반 모니터링: Api::V1::ReviewsController#load 의 p95/p99 latency 와 500 rate 를 Datadog SLO 로 정의. 10 초에 근접하는 요청은 사실상 실패로 간주.
• ES 헬스 이상 조기 감지: Faraday::TimeoutError 발생 시 곧바로 인시던트 채널에 알림, ES cluster health API 결과와 상관 확인.

Monitoring#

• ES timeout 발생 추이:

service:cupixworks-api "Operation timed out after"

• Review load 500 응답:

service:cupixworks-api "ReviewsController#load" "[500]"

• Review load p95 latency (APM trace 기준):

p95:trace.rack.request{service:cupixworks-api,resource_name:api::v1::reviewscontroller#load}

• Faraday timeout 시그니처 전반:

service:cupixworks-api "Faraday::TimeoutError"

Risk Assessment#

• Risk level: medium (사용자 개별 500 은 낮은 빈도이지만, 동일 timeout 시그니처가 여러 repository 에 걸쳐 반복되고 있어 systemic 신호. Review 상세 최초 진입 실패는 이탈로 이어지기 쉬움.)
• 예상 복잡도: standard — 즉시 조치는 rescue 절에 예외 클래스 하나 추가하는 수준. 다만 (a) 동일 패턴을 다른 concern/repository 까지 확산 적용, (b) fallback 후 legacy 경로의 신뢰성 검증, (c) ES cluster 측 원인 규명은 별도 트랙으로 진행 필요.