RCA: Api::V1::MeController#show (avg 208755ms, max 208755ms)

Overview#

What Happened#

2026-07-23 03:01 KST경 eu-central-1 리전의 cupixworks-api (Elastic Beanstalk, host i-0f89558422bf291ff)에서 GET /api/v1/me 요청 한 건이 208.755초를 소비한 뒤 200 OK 로 응답했다. 트레이스 span 을 분해하면 rack.request 는 208.8s 를 소비했지만 실제 rails.action_controller 액션은 마지막 1.8s 만 실행되었다. 즉 요청은 컨트롤러 액션에 진입하기 전 middleware/authentication 단계에서 약 207 초 동안 stall 되었다. 이 클러스터는 status-board 상 sibling 클러스터 3db35b39 (GET 400 35.6s) 및 3e41f969 (RevisionRequestsController#index 509s avg) 와 동일한 svc-incident 2026-07-22-svc-cupixworks-api--unknown-1 에 묶여 있으며, sibling RCA 는 eu-central-1 Redis(ElastiCache) 및 MySQL(RDS) 데이터 계층의 일시적 성능 저하를 root cause 로 이미 확인했다.

Quick Facts#

Affected Teams#

tenant:cupix 만 태그되어 있어 다른 테넌트 영향 여부는 미확인. 다른 리전(us-east-1, ap-northeast-2 등)은 sibling RCA 조사에서 정상으로 확인됨.

Timeline#

1. 2026-07-23 02:57 KST — sibling cluster 3db35b39 발생 (GET 400 35.6s), svc-incident 시작.
2. 2026-07-23 02:57 KST — sibling cluster 3e41f969 발생 (RevisionRequestsController#index 509s avg).
3. 2026-07-23 03:01:26 KST — 본 클러스터 rack.request 시작 (2026-07-22T18:01:26.593Z).
4. 2026-07-23 03:04:52 KST — Cognito get_user_by_access_token 로그 기록 (요청 접수 후 약 3분 26초 경과).
5. 2026-07-23 03:04:53 KST — rails.action_controller 스팬 시작 (rack 진입 후 206.9s 만에 컨트롤러 액션 진입).
6. 2026-07-23 03:04:55 KST — rails.action_controller 종료, rack.request 종료. 응답 200 반환, 총 208.755s.
7. 2026-07-23 03:01 KST — status-board 2026-07-22-svc-cupixworks-api--unknown-1 resolved 처리. 이후 /me 요청 정상화 (03:06 KST 이후 다수의 200 OK /me 응답 확인).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::MeController#show",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 208755,
  "max_ms": 208755,
  "sample_trace_id": "1201168046855516580"
}

Impact#

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

Root Cause Summary#

GET /api/v1/me 요청은 최종적으로 200 OK 응답을 성공적으로 반환했으나, rack.request 시작부터 응답까지 208.755s 를 소비했다. 트레이스 span 분해 결과 rails.action_controller (컨트롤러 액션 자체) 는 요청 종료 직전 1.8s 만 실행되었고, 전체의 99% 이상인 약 206.9s 는 rack middleware 및 authentication 단계에서 stall 되었다. 이 stall 은 컨트롤러 코드의 결함이 아니라 authentication/session middleware 가 의존하는 인프라 계층(session store — MySQL sessions 테이블, Rails cache — ElastiCache Redis, Cognito access token 검증) 이 응답 지연 상태였기 때문이다. sibling cluster 3db35b39 RCA 에서 확인된 것처럼 같은 리전·같은 4분 window 에서 MySQL SELECT sessions 21.8s, SELECT teams WHERE domain=? 18.1s, SET NAMES utf8mb4 8.5s, rails.cache GET 19.8s 등 데이터 계층 전반이 심각한 지연을 보였다. 본 클러스터는 그 sibling 트레이스들과 동일한 svc-incident (2026-07-22-svc-cupixworks-api--unknown-1) 로 묶여 있으며, host / version / region / 시간 window 가 모두 일치한다.

Technical Analysis#

Code Path#

Api::V1::MeController#show 액션 자체는 매우 단순하다. 트레이스 상 실제 액션 실행 시간은 1.8s 로 문제 없다.

class Api::V1::MeController < Api::V1::ApiController
  include ParameterRequired

  before_action :set_user

  def show
    @model.show_api_token = true

    super
  end

Api::V1::ApiController (parent) 는 요청 처리 전에 authenticate! 를 호출하여 access token 을 검증하고 session 을 로드한다. 이 과정에서 (a) Cognito access token 검증, (b) Session 레코드 조회 (MySQL), (c) User / Team 로드 (MySQL + Rails cache) 가 순차적으로 발생한다.

• Entry point: rack.request (Rails middleware stack) → auth middleware → set_user before_action → Api::V1::MeController#show
• Failure point: 컨트롤러 액션 이전의 rack middleware 및 authentication 단계 (구체적 stall 위치는 span 데이터가 부족하여 특정 불가; 그러나 sibling 트레이스에서 SELECT sessions / SELECT teams / rails.cache GET 이 각각 수십 초 걸린 것으로 확인)
• 기대 동작: /me 응답은 통상 100~300ms (03:06 KST 이후 다수의 200 OK /me 응답이 초당 수건 처리됨)
• 실제 동작: rack.request 208.755s 중 206.9s 를 컨트롤러 진입 전 middleware/auth 에 소비, 실제 액션은 1.8s

Log Evidence#

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

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

본 트레이스의 주요 span (총 8 span 수집):

operation                    | resource                       | duration    | start (UTC)
rack.request                 | Api::V1::MeController#show     | 208,755.1ms | 2026-07-22T18:01:26.593Z
rails.action_controller      | Api::V1::MeController#show     |   1,805.9ms | 2026-07-22T18:04:53.542Z
active_record.instantiation  | User                           |       0.2ms | 2026-07-22T18:04:53.051Z
active_record.instantiation  | Session                        |       0.1ms | 2026-07-22T18:04:53.540Z
active_record.instantiation  | Team                           |       0.1ms | 2026-07-22T18:04:53.863Z
active_record.instantiation  | User                           |       0.1ms | 2026-07-22T18:04:54.921Z
active_record.instantiation  | Team                           |       0.1ms | 2026-07-22T18:04:55.163Z
active_record.instantiation  | Storage                        |       0.0ms | 2026-07-22T18:04:55.343Z

• rack.request start = 18:01:26.593Z, rails.action_controller start = 18:04:53.542Z → 206,949 ms 의 gap 이 middleware/auth 단계에서 발생.
• 첫 active_record.instantiation (User) 시각도 18:04:53.051Z 로, rack 시작 후 206.5s 지난 시점. 즉 authentication 단계의 첫 DB 조회 자체가 stall 되었다는 신호.
• 실제 컨트롤러 액션은 1.8s 로 정상 범위. 응답은 200 OK 로 성공.

Datadog 로그 검색 (동일 trace_id) — 정상 응답 로그와 Cognito 조회 로그만 존재:

service:cupixworks-api trace_id:1201168046855516580
  from 2026-07-22T17:55:00Z to 2026-07-22T18:10:00Z → 2 hits

2026-07-23 03:04:52 KST | info | Fetching an user from Cognito: 7615e7ab-eb01-4989-980f-12deedd772c7
                                 class=Cognito function=get_user_by_access_token
2026-07-23 03:04:56 KST | info | [200] GET /api/v1/me (Api::V1::MeController#show)

Cognito 로그 시각(03:04:52 KST)이 rack.request 시작(03:01:26 KST) 대비 약 3분 26초 뒤라는 사실이, session/token 검증 관련 middleware 가 이 시간 동안 blocking 되었음을 뒷받침한다.

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 — sibling)
  - 3e41f969-317a-4ffa-9767-097c0656318c  (RevisionRequestsController#index 509s avg — sibling)
  - a58229f6-f8fa-400c-b6bc-36ac7f6fb293  (본 클러스터, MeController#show 208s)

Sibling cluster 3db35b39 RCA 에서 확보된 데이터 계층 증거 (동일 리전·시간대, 인용):

mysql2.query | SELECT teams.* FROM teams WHERE teams.domain = ? LIMIT ?         | 18,149 ms
mysql2.query | SELECT sessions.* FROM sessions WHERE user_id=? AND state=? ...  | 21,779 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

Hypotheses Considered#

Fix Recommendation#

이 클러스터의 근본 원인은 sibling cluster 3db35b39 RCA 에서 이미 확인된 eu-central-1 데이터 계층 (ElastiCache Redis + RDS MySQL) 의 일시적 성능 저하다. 따라서 애플리케이션 코드 수정이 최우선이 아니며 인프라/관측 개선이 핵심이다. 아래 권장 사항은 sibling RCA 와 방향을 일치시키되, /me 엔드포인트의 특수성(authentication middleware 계층 stall)에 맞춰 보강한다.

즉시 조치 (Critical)#

• 인프라 확인 (DevOps 협조 필요, 자동 code-fix 대상 아님): eu-central-1 ElastiCache Redis 및 RDS MySQL 의 2026-07-22 17:55Z ~ 18:05Z 구간 CPU / connection count / replication lag / slow query log 확인. sibling RCA 에서 SET NAMES 8.5s 가 관측된 점은 신규 커넥션 생성 자체가 느렸다는 의미로, connection pool exhaustion 또는 DB 서버 CPU 포화 가능성이 높다. 세션 조회(SELECT sessions ...) 는 모든 authenticated 요청 경로에 개입하므로 /me 뿐 아니라 대부분의 API 요청이 영향을 받았을 것.
• 범위 재확인: 같은 시간대 /me, /me/firebase_token, /sessions 등 authentication middleware 를 공유하는 엔드포인트의 p95/p99 latency 를 리전 단위로 재점검. 3개 클러스터로만 묶인 svc-incident 지만 실제 영향 범위는 더 넓을 가능성.

단기 개선 (1주 이내)#

• Rack middleware / auth 계층 slow-path 로깅: 이번 사건에서 rack 진입 이후 컨트롤러 액션까지의 206.9s 구간이 어떤 middleware 에서 소비되었는지 로그로 특정할 수 없다. session store 조회, Rails cache 조회, Cognito 호출 각 단계에서 5s 이상 걸리면 warn 로그를 남기도록 계측 추가.
• session store / cache read timeout: config/environments/production.rb 의 config.cache_store (Redis) 및 session 조회 경로에 짧은 read timeout (예: 3~5s) 을 설정해 dependency degradation 시 fast-fail 로 표면화. 현재는 200s+ 매달림.
• /me 엔드포인트 별도 SLO/alert: /me 는 SPA 초기 로드 및 세션 유효성 확인 경로로, p95 500ms 를 초과하면 즉시 알림. 사용자 체감 timeout 을 조기 감지.

장기 개선 (재발 방지)#

• eu-central-1 데이터 계층 capacity/failover 재검토: sibling RCA 와 동일 — ElastiCache/RDS 인스턴스 사이즈, Multi-AZ, connection pool 크기(ProxySQL/RDS Proxy 유무) 를 리전간 일관성 있게 점검.
• Authentication middleware circuit breaker: session store / cache 응답 지연 시 조기 실패 후 재인증을 유도하는 회로 차단기. 사용자에게 208s 대기시키는 것보다 401/503 을 빠르게 반환하는 편이 UX·리소스 측면에서 유리.
• Trace-level SLO board: rack.request duration 을 리전·엔드포인트별 시계열로 상시 노출, 이번처럼 국지적 스파이크를 즉시 감지.

Monitoring#

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

• eu-central-1 /me rack.request p95 latency

p95:trace.rack.request.duration{service:cupixworks-api,env:production,region:eu-central-1,resource_name:Api::V1::MeController#show}

• 리전별 cupixworks-api rack.request p95 latency (인프라 계층 광역 감시)

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

• pre-controller stall 감지: rack.request 5s 이상 발생 건수 (리전별)

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} by {region}

• mysql2 쿼리 p95 지연 (session/team 조회 이상 조기 감지)

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

• /me 엔드포인트 5s 이상 응답 발생 건수 (재발 감지)

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

Risk Assessment#

• Risk level: medium — /me 는 SPA 초기 로드 및 세션 확인 경로로 authentication middleware 를 공유하는 모든 엔드포인트가 같은 시간대에 영향받았을 가능성이 높다. 4분 window 로 한정된 국지적 사건이었으나 재발 시 리전 전체 사용자 인증이 일시 마비될 수 있다.
• 예상 복잡도: standard — 앱 코드 수정보다 인프라/관측 개선이 핵심. 코드 변경은 timeout, slow-request warn 로깅, /me 별도 SLO 설정 수준으로 소규모.