RCA: Api::V1::ClustersController#index Latency (avg 1075ms)

Overview#

What Happened#

2026-05-26 03:50~05:17 UTC 동안 cupixworks-api의 Api::V1::ClustersController#index 엔드포인트에서 평균 1075ms, 최대 1147ms의 응답 지연이 ap-southeast-2 및 ap-southeast-1 리전에서 6건 감지되었다. DB 시간은 평균 23ms로 매우 낮았으나, 전체 응답 시간의 대부분(~1000ms)이 Rails가 계측하지 않는 인증 단계에서 소모되었다.

Quick Facts#

Timeline#

1. 2026-05-26T03:50:39Z — 최초 slow trace 감지 (1146ms, ap-southeast-2)
2. 2026-05-26T05:17:16Z — 마지막 slow trace (1085ms, ap-southeast-2)
3. 2026-05-26T05:17Z — error-sweeper 클러스터 생성

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ClustersController#index",
  "service": "cupixworks-api",
  "occurrences": 6,
  "avg_ms": 1075,
  "max_ms": 1147,
  "sample_trace_id": "5304669806875010812"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 6 (threshold 초과 건수; 같은 시간대 전체 slow request는 43건)
• 최초 발생: 2026-05-26T03:50:39.113Z
• 최근 발생: 2026-05-26T05:17:16.337Z

Root Cause Summary#

ClustersController#index 요청의 인증 단계에서 Cognito get_user API 호출(Cupix::Aws::Cognito.get_user_by_access_token)이 cache miss 시 외부 AWS Cognito 서비스에 동기적으로 HTTP 요청을 보낸다. APAC 리전(ap-southeast-2, ap-southeast-1)에서 Cognito 엔드포인트까지의 네트워크 지연이 ~1000ms에 달하며, 이것이 Rails가 계측하는 DB/View/Serialization 이외의 "설명되지 않는 overhead"로 나타난다. DB 시간은 평균 23ms로 정상이고, 실제 쿼리 로직에는 문제가 없다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/verification_controller.rb:15 (authenticate!)
• Auth verification: lib/cupix/auth/verification.rb:20 (verify_authenticated_request!)
• JWT verification (cached max 300s): lib/cupix/auth/verification.rb:209 (verify_jwt_access_token!)
• JWKS fetch (cached 1 day): lib/cupix/aws/cognito/jwt.rb:28 (jwks)
• Failure point — Cognito get_user (cached 1 hour): lib/cupix/aws/cognito.rb:206 (get_user_by_access_token)
• Controller action: app/controllers/api/v1/clusters_controller.rb:12 (index)

인증 흐름에서 두 개의 외부 HTTP 호출이 존재한다:

1. JWKS Fetch (1일 캐시)

def jwks
  Rails.cache.fetch('cupix:aws:cognito:jwks', expires_in: 1.day) do
    refresh_jwks
  end
end

JWKS 캐시는 1일이므로 대부분의 요청에서 cache hit. 그러나 서버 재시작이나 캐시 만료 직후에는 외부 호출 발생.

2. Cognito get_user API (1시간 캐시) — 주요 병목

def get_user_by_access_token(access_token: nil, sub: nil)
  sub ||= ::JWT.decode(access_token, nil, false).first['sub']

  Rails.cache.fetch(user_cache_key(sub), expires_in: 1.hour) do
    Cupix::Logger.info("Fetching an user from Cognito: #{sub}", function: __method__, module: 'Cupix::Aws', class: 'Cognito')

    response = client.get_user(access_token: access_token)
  rescue ::Aws::CognitoIdentityProvider::Errors::NotAuthorizedException
    raise Cupix::Errors::Unauthorized.new(code: 'AUTH20013', reason: 'Invalid access token')
  else
    Cupix::Aws::Cognito::UserResponse.new(
      user_response_hash(response)
    )
  end
end

이 메서드는 verify_authenticated_request! 내부에서 JWT 검증 이후 매번 호출된다(line 81):

verified_access_token = self.class.verify_jwt_access_token!(access_token: @access_token)
# ... decoded token validation (lines 63-79) ...
user_response = Cupix::Aws::Cognito.get_user_by_access_token(access_token: access_token, sub: sub)

verify_jwt_access_token!는 결과를 캐시하지만(max 300s), 그 이후의 get_user_by_access_token 호출은 별도의 1시간 캐시를 사용한다. 사용자 캐시가 만료되면 매 요청마다 Cognito API를 호출한다.

3. HTTP Client — 타임아웃 미설정

def self.get(url, headers = {}, retries: MAX_RETRIES)
  attempt = 0
  begin
    RestClient.get(url, headers)
  rescue RestClient::Exception => e
    if RETRIABLE_STATUS_CODES.include?(e.http_code) && attempt < retries
      attempt += 1
      sleep((2**(attempt - 1)) + rand(0.0..0.5))
      retry
    end
    raise
  end
end

RestClient.get에 timeout 파라미터가 없어 기본값(무제한)을 사용. 네트워크 지연이 길어져도 요청이 무한 대기할 수 있다.

Log Evidence#

Datadog에서 trace ID로 조회한 결과, 모든 slow request에서 동일한 패턴이 확인됨:

service:cupixworks-api trace_id:5304669806875010812

{
  "trace_id": "5304669806875010812",
  "duration_ms": 1084.78,
  "db_ms": 82.01,
  "view_ms": 0.05,
  "serialization_ms": 1,
  "overhead_ms": 1001,
  "host": "ip-10-1-145-251.ap-southeast-2.compute.internal",
  "auth_method": "COGNITO",
  "params": { "capture_id": "72967", "fields": ["id", "cluster_type", "meta", "capture"] },
  "total_entries": 1,
  "per_page": 30
}

service:cupixworks-api trace_id:3765563761474654223

{
  "trace_id": "3765563761474654223",
  "duration_ms": 1124.52,
  "db_ms": 20.72,
  "view_ms": 0.07,
  "serialization_ms": 0,
  "overhead_ms": 1103,
  "host": "ip-10-1-147-122.ap-southeast-1.compute.internal",
  "auth_method": "COGNITO",
  "params": { "capture_id": "2329", "fields": ["id"], "per_page": 100 },
  "total_entries": 3
}

동일 시간대에 43건의 slow request(>500ms) 확인. 평균 overhead 786.8ms, DB 평균 22.9ms. 리전별 분포: ap-southeast-2 (53%), ap-southeast-1 (26%), eu-central-1 (12%), us-west-2 (9%).

핵심 관찰:

• 결과 건수 1~7건으로 매우 적음 → DB가 병목이 아님
• 모든 요청이 COGNITO auth 사용
• Overhead는 항상 500~1400ms 범위이며, DB/View/Serialization 시간과 무관

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• lib/cupix/aws/cognito.rb:206 — get_user_by_access_token의 캐시 TTL을 1시간에서 Cognito access token 만료 시간(보통 1시간)과 동기화하되, 별도의 background refresh 메커니즘을 도입하여 사용자 요청 경로에서 외부 호출을 제거
• lib/cupix/http_client.rb:15 — RestClient.get에 timeout: 5, open_timeout: 3 파라미터를 추가하여 외부 호출이 무한 대기하지 않도록 방어

단기 개선 (1주 이내)#

• verify_authenticated_request! 흐름을 리팩터링하여 get_user_by_access_token 결과를 JWT verification cache에 포함시키거나, 이미 검증된 JWT의 sub claim을 기반으로 로컬 DB에서 사용자를 조회하는 방식으로 변경 (Cognito API 호출을 최초 로그인 시에만 수행)
• JWKS를 앱 시작 시 preload하고 background job으로 주기적 refresh

장기 개선 (재발 방지)#

• APAC 리전 서버에서 Cognito 호출을 제거하는 아키텍처 변경: JWT claim만으로 인증을 완료하고, 사용자 정보는 로컬 DB에서 조회
• 인증 단계의 외부 호출 지연을 APM에서 별도 span으로 계측하여 가시성 확보
• Circuit breaker 패턴 적용으로 Cognito 장애 시 graceful degradation

Monitoring#

• Cognito get_user 호출 빈도 및 지연 추적:

service:cupixworks-api "Fetching an user from Cognito" | stats avg(duration) by host

• ClustersController#index P95 latency 알림 (임계값: 500ms)

avg(last_5m):trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::clusterscontroller#index} > 500000000

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard — 캐시 전략 변경과 timeout 추가는 비교적 안전하지만, 인증 흐름 변경은 신중한 테스트 필요