RCA: GET 400 (avg 35601ms, max 35601ms)

Overview#

What Happened#

2026-07-23 02:57 KST 경 eu-central-1 리전의 cupixworks-api(Elastic Beanstalk 환경 tesla-eu-prod) 에서 GET /api/v1/admin/revision_requests 요청 한 건이 400 응답을 내면서 35.6초 동안 지연되었다. 같은 시각 근처에 동일 리전의 Api::V1::Admin::RevisionRequestsController#index (평균 509s, 최대 563s) 와 Api::V1::MeController#show (208s) 요청도 극단적으로 느려졌으며, 세 클러스터는 status-board 상 동일 svc-level incident 2026-07-22-svc-cupixworks-api--unknown-1 로 묶여 있다. 원인은 특정 컨트롤러 코드가 아니라 eu-central-1 데이터 계층(Redis / MySQL) 이 짧은 시간 동안 심각하게 지연된 인프라 이벤트다.

Quick Facts#

Affected Teams#

Trace-level 증거만 확보 가능하고 다른 리전(us-east-1, ap-northeast-2 등) 은 같은 시각 정상. tenant:cupix 만 태그되어 있어 다른 테넌트 영향은 미확인.

Timeline#

1. 2026-07-23 02:55 KST — RevisionRequestsController#index 지연 시작 (sibling cluster 3e41f969 first_seen).
2. 2026-07-23 02:57 KST — 본 클러스터 발생: GET /api/v1/admin/revision_requests 요청 접수 (span start 2026-07-22T17:57:05.329Z).
3. 2026-07-23 02:57:11 KST — rails.cache GET 시작, 이후 19.8s 동안 Redis 응답 지연.
4. 2026-07-23 02:57:40 KST — 응답 400 반환, 총 35.6s 소요.
5. 2026-07-23 03:01 KST — MeController#show 208s 지연 사건 (a58229f6) 발생, svc-incident 마지막 이벤트.
6. 2026-07-23 03:01 KST — status-board 가 2026-07-22-svc-cupixworks-api--unknown-1 을 resolved 로 마감. 이후 정상.

Error Log#

Datadog Logs

{
  "resource_name": "GET 400",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 35601,
  "max_ms": 35601,
  "sample_trace_id": "1235335099960433629"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-23 02:57 KST
• 최근 발생: 2026-07-23 02:57 KST

Root Cause Summary#

GET /api/v1/admin/revision_requests?fields&page&per_page&order_by&sort&state 요청은 파라미터가 모두 비어 있어 결과적으로 400 Bad Request 로 응답되었지만, 응답이 반환되기까지 35.6s 가 걸렸다. 이 지연의 대부분(약 19.8s + 하위 Redis 명령 누적 약 11s)은 요청 처리 초기 단계의 rails.cache GET 및 이어지는 Redis GET/DEL 명령에 소비되었다. 같은 리전·같은 시각에 발생한 sibling trace(Api::V1::Admin::RevisionRequestsController#index, 466s)에서는 MySQL SELECT teams WHERE domain = ? 18.1s, SELECT sessions ... 21.8s, 심지어 커넥션 초기화용 SET NAMES utf8mb4 ... 가 8.5s 걸리는 등 Redis 와 MySQL 양쪽 모두 심각한 지연 이 관측된다. 따라서 이 400 응답의 35.6s 지연은 컨트롤러 로직 결함이 아니라, eu-central-1 데이터 계층(ElastiCache Redis 및 RDS MySQL) 의 일시적 성능 저하가 rack.request 초기 파이프라인(캐시 조회 → 세션 조회 → 파라미터 검증)을 블로킹한 결과다.

Technical Analysis#

Code Path#

컨트롤러 자체는 표준적인 index 액션으로, 문제 시점의 코드 경로 자체에는 결함 신호가 없다.

# GET /api/v1/admin/revision_requests
def index
  query_option = Cupix::QueryOption::RevisionRequest.new(
    get_query_option(enable_current_team: false), params
  )
  revision_requests = repository_instance.search(query_option)

  render_api Renderable.new({
    search_result: revision_requests,
    is_collection: true,
    serializer_option: @serializer_option
  })
end

Admin 계열은 아래처럼 authenticate! 를 확장하여 admin team 검증을 하지만, 400 응답으로 종료된 이번 요청은 컨트롤러 액션까지 도달하지 못했다(child 스팬에 rails.action_controller 스팬이 없음).

class Api::V1::Admin::ApiController < Api::V1::ApiController
  def authenticate!
    super

    raise ActionController::RoutingError, 'Not Found' if @current_team != TeamRepository.admin_team
  end
end

• Entry point: rack.request → Api::V1::Admin::RevisionRequestsController (before authenticate! 단계로 추정)
• Failure point: 코드가 아니라 하위 인프라(rails.cache/Redis, MySQL 세션·팀 조회) 지연
• 기대 동작: 파라미터 검증 실패 시 즉시 400 응답 (일반적으로 수십 ms)
• 실제 동작: rack.request 시작 이후 rails.cache GET 이 19.8s, 하위 redis 명령 누적 11s+ 소요되어 400 응답까지 35.6s

Log Evidence#

트레이스(span) 검색을 통해 확보한 증거. Datadog 로그(status:error/warn) 에는 이 시간대 관련 항목이 없었으며(아래 쿼리 참고), 성능 문제는 APM span 에서만 확인된다.

트레이스 span 조회에 사용한 API 쿼리:

POST /api/v2/spans/events/search
filter.query: service:cupixworks-api trace_id:1235335099960433629
filter.from:  2026-07-22T17:50:00Z
filter.to:    2026-07-22T18:10:00Z

문제 트레이스의 span 트리 (본 클러스터, 총 6개 span):

rack.request   | GET 400                        | 35,601 ms | start 17:57:05.329Z parent=0
├─ rails.cache | GET                            | 19,835 ms | start 17:57:11.494Z
│  ├─ redis.command GET   | 3,510 ms | start 17:57:15.863Z
│  ├─ rails.cache DELETE  | 3,885 ms | start 17:57:19.637Z
│  ├─ redis.command DEL   | 1,246 ms | start 17:57:23.522Z
│  └─ redis.command GET   | 2,400 ms | start 17:57:26.682Z

동일 리전·동일 시간대 sibling trace (Api::V1::Admin::RevisionRequestsController#index, trace_id 2562980848986214478, 466.7s) 에서 관측된 초장 지연 쿼리(발췌):

rack.request | Api::V1::Admin::RevisionRequestsController#index | 466,747 ms
mysql2.query | SELECT teams.* FROM teams WHERE teams.domain = ? LIMIT ?         | 18,149 ms
mysql2.query | SELECT teams.* FROM teams WHERE teams.domain = ? LIMIT ?         | 15,458 ms
mysql2.query | SELECT sessions.* FROM sessions WHERE user_id=? AND state=? ...  | 21,779 ms
mysql2.query | SELECT sessions.* FROM sessions WHERE user_id=? AND state=? ...  | 21,842 ms
mysql2.query | SELECT users LEFT OUTER JOIN teams ... WHERE domain=? AND email=?| 9,520 ms
mysql2.query | SET NAMES utf8mb4 COLLATE utf8mb4_unicode_ci ...                 | 8,529 ms
rails.cache  | GET                                                              | 11,624 ms
redis.command| GET                                                              | 3,730 ms

SET NAMES utf8mb4 ... 는 매 연결(session) 설정 시 실행되는 세션 파라미터 명령이다. 이 명령이 8.5s 걸린다는 것은 MySQL 서버/연결 계층 자체가 매우 지연되고 있었다는 강한 신호다.

Status-board 결과 (동일 svc-scope 로 묶임):

scope: svc:cupixworks-api::unknown
active: null
recent[0].id: 2026-07-22-svc-cupixworks-api--unknown-1
recent[0].started_at:  2026-07-22T17:57:05.329Z
recent[0].resolved_at: 2026-07-22T18:01:26.593Z
recent[0].cluster_ids:
  - 3db35b39-7c60-4672-9f63-393c0dcf9216  (본 클러스터, GET 400 35.6s)
  - 3e41f969-317a-4ffa-9767-097c0656318c  (RevisionRequestsController#index 509s avg)
  - a58229f6-f8fa-400c-b6bc-36ac7f6fb293  (MeController#show 208s)

Datadog 로그 재현 쿼리 (관련 error/warn 로그 없음을 확인):

service:cupixworks-api env:production status:error
  from 2026-07-22T17:50:00Z to 2026-07-22T18:05:00Z → 0 hits

service:cupixworks-api @http.status_code:400 env:production
  from 2026-07-22T17:56:30Z to 2026-07-22T17:57:30Z → 0 hits

로그가 0건인 것 자체가 증거다. 정상적이라면 400 응답은 Rails info 로그([400] GET /api/v1/admin/revision_requests ...)를 남긴다. 이 시각 window 에 해당 로그가 없다는 것은 요청이 로깅 시점(rails.action_controller 이후) 이전에 stall 되어 로그가 유실되었거나, 요청 자체가 컨트롤러 도달 전에 400 을 반환하고 로거 flush 가 지연된 것으로 해석된다. 어느 쪽이든 rack.request span 이 35.6s 를 소비한 사실은 span 데이터로 확정된다.

Hypotheses Considered#

Fix Recommendation#

이 클러스터의 근본 원인이 애플리케이션 코드가 아니라 리전 데이터 계층의 일시적 성능 저하이므로 코드 수정은 최우선 조치가 아니다. 인프라·관측 개선이 핵심이다.

즉시 조치 (Critical)#

• 인프라 확인 (DevOps 협조 필요, 자동 code-fix 대상 아님): eu-central-1 ElastiCache Redis 클러스터와 RDS MySQL 인스턴스의 2026-07-22 17:55Z~18:02Z 구간 CPU, 커넥션 수, replication lag, slow query log, ElastiCache EngineCPUUtilization, CurrConnections, NetworkBytesIn/Out 을 확인. SET NAMES 가 8.5s 걸리는 것은 연결 풀 고갈 또는 DB 서버 CPU 포화의 강한 지표.
• 범위 재확인: 같은 시간대 다른 admin/일반 엔드포인트의 p99 latency 스파이크 여부를 리전 단위로 재점검. status-board 가 이미 3개 클러스터를 하나의 svc-incident 로 묶었으나, spans 검색으로 tenant 별 영향을 별도 집계 필요.

단기 개선 (1주 이내)#

• cache/DB 호출에 timeout 을 두어 요청이 30s+ 매달리지 않도록: 현재 rack.request 가 35.6s 를 온전히 소비하고 응답을 늦게 반환. Rails 캐시(store level) 및 mysql2 어댑터에 read timeout 을 짧게(예: 3~5s) 설정해 dependency degradation 을 fast-fail 로 표면화. 관련 위치는 config/environments/production.rb 의 config.cache_store 및 config/database.yml connect/read timeout.
• Rack-level slow request warn 로깅: 5s 이상 걸린 rack.request 는 warn 레벨 로그를 남기도록 미들웨어 추가. 이번 사건에서 status:error/warn 로그 0건이 원인 파악을 늦춤. 400 응답조차 로그로 남지 않은 점이 문제.
• 관리자 계열 엔드포인트에 대한 별도 SLO/alert: Api::V1::Admin::* 는 사용 빈도는 낮지만 CS/운영에 직접 영향. p95 3s 를 넘으면 즉시 알림하도록 monitor 신설.

장기 개선 (재발 방지)#

• eu-central-1 데이터 계층 capacity/failover 재검토: ElastiCache/RDS 인스턴스 크기, Multi-AZ, connection pool 크기(PgBouncer/ProxySQL 유무) 를 리전간 일관되게 검토. SET NAMES 지연 = 신규 연결 자체가 느림 = 커넥션 풀 exhaustion 가능성.
• Regional dependency circuit breaker: 특정 리전의 캐시/DB latency 가 급증할 때 admin 계열처럼 latency-sensitive 하지 않은 엔드포인트도 자동으로 degrade(캐시 스킵, 조회 폴백 등) 하도록 구조화.
• Trace-level SLO board: rack.request duration 을 리전·엔드포인트 별로 시계열로 상시 노출해 오늘처럼 4분간 국지적 스파이크를 즉시 감지.

Monitoring#

writing-datadog-monitoring-queries 규칙에 따라 dashboard timeseries widget 에 그대로 사용 가능한 metric 쿼리로 작성.

• eu-central-1 API rack.request p95 지연 (분단위)

p95:trace.rack.request.duration{service:cupixworks-api,env:production,region:eu-central-1}

• 리전별 cupixworks-api 5s 이상 rack.request 발생 건수 (분단위 rate)

sum:trace.rack.request.hits{service:cupixworks-api,env:production,duration:>5s} by {region}.as_rate()

• rails.cache GET p95 지연 (Redis dependency 계측)

p95:trace.rails.cache.duration{service:cupixworks-api,env:production,region:eu-central-1,resource_name:GET}

• mysql2 쿼리 p95 지연 by region (SET NAMES / SELECT teams 등 커넥션 초기화 이상 조기 감지)

p95:trace.mysql2.query.duration{service:cupixworks-api,env:production} by {region}

• 400 응답 rack.request 중 duration 5s 초과 건수 (본 클러스터 유형 재발 감지)

sum:trace.rack.request.hits{service:cupixworks-api,env:production,http.status_code:400,duration:>5s} by {region}.as_rate()

Risk Assessment#

• Risk level: medium (사용자 트래픽 영향은 4분간 국지적, admin 계열 위주. 그러나 sibling trace 에서 세션 조회 21s / users 조인 9.5s 는 일반 사용자 요청에도 광범위 영향을 미쳤을 가능성. 재발 시 서비스 전반 latency 문제로 확대 가능).
• 예상 복잡도: standard (앱 코드 수정보다는 인프라/관측 개선이 핵심. 코드 수정은 timeout·slow-request warn 로깅 위주로 소규모).