RCA: Api::V1::AuthenticatesController#create latency (11.4s)

Overview#

What Happened#

2026-07-03 17:31 KST, cupixworks-api (us-west-2)에서 POST /api/v1/authenticate 요청 한 건이 11382 ms 만에 완료됐다. 응답은 HTTP 200이지만 duration은 정상 트래픽(50 ms ~ 400 ms) 대비 20배 ~ 200배 늦다. 같은 window에서 Api::V1::AuthenticatesController#create 다른 요청도 5921 ms, 3436 ms, 3171 ms, 2483 ms 등 다수가 초 단위로 지연되었고, 서비스 status board에는 동일 시간대에 svc:cupixworks-api::unknown 활성 인시던트가 열려 있다. 즉 인증 로직 자체의 버그가 아니라 cupixworks-api production 노드의 광범위한 성능 저하 시기에 편입된 요청이다.

Quick Facts#

Affected Teams#

같은 window에 authenticate 엔드포인트 slow request 8건 이상 관측(11382, 5921, 3436, 3171, 2483, 1495, 1401, 1288 ms). 클러스터가 latency 클러스터이므로 실패는 아니지만 사용자 체감 로그인은 크게 저하됐다.

Timeline#

1. 2026-07-03 17:08 KST — status board가 2026-07-03-svc-cupixworks-api--unknown-1 인시던트 개시, 초기 클러스터 b3c83033-a17f-4bd3-9ab6-8fa1d910e772 등록
2. 2026-07-03 17:31 KST — 본 cluster (bb3f2774)의 첫/마지막 발생. AuthenticatesController#create가 11382 ms 소요, HTTP 200
3. 2026-07-03 17:32 KST — 동일 host (ip-10-1-144-228)에서 refresh_token 요청도 5921 ms 지연
4. 2026-07-03 18:45 KST — 서비스 degradation 인시던트 마지막 이벤트 관측 (116ab21f), 이 시점까지 인시던트는 open 상태

Error Log#

Datadog Logs

{
  "duration": 11382.05,
  "db": 1249.21,
  "view": 0.98,
  "controller": "Api::V1::AuthenticatesController",
  "action": "create",
  "cupix_auth_method": "COGNITO",
  "params": { "grant_type": "access_code" },
  "http": { "status_code": 200, "method": "POST", "url_details": { "path": "/api/v1/authenticate" } },
  "host": { "name": "ip-10-1-144-228.us-west-2.compute.internal" },
  "request_id": "fb0d80bd-7346-4f93-a73d-f653f271c260",
  "@timestamp": "2026-07-03T08:31:51.124Z"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (cluster 기준), 동 window slow siblings 다수
• 최초 발생: 2026-07-03 17:31 KST
• 최근 발생: 2026-07-03 17:31 KST

Root Cause Summary#

사용자별 요청 자체는 정상 경로(signin_with_access_code)를 성공적으로 완료했지만, request가 처리된 시점에 cupixworks-api production node (ip-10-1-144-228.us-west-2)가 광범위한 latency 저하 상태였다. duration 11382 ms 중 DB에 1249 ms, view rendering에 0.98 ms만 사용됐고 나머지 10132 ms(약 89 %)는 Ruby/외부 호출/GC/thread 대기 등 어플리케이션 영역에서 소모됐다. 동일 window에서 다른 authenticate 요청 다수가 초 단위 지연을 보였고, status board는 같은 시각에 svc:cupixworks-api::unknown 인시던트가 open이었음을 확인해준다. 즉 이 cluster는 auth 로직의 버그가 아니라 진행 중인 서비스 degradation의 한 증상이다.

Technical Analysis#

Code Path#

Entry point는 Api::V1::AuthenticatesController#create로, grant_type=access_code이므로 signin_with_access_code로 분기한다.

def create
  grant_type = params[:grant_type] || 'email'

  case grant_type
  # ...
  when 'access_code'
    raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'access_code is required') if params[:access_code].nil?

    access_code = params[:access_code]
    signin_with_access_code(access_code)
  # ...
  end

def signin_with_access_code(access_code)
  begin
    decoded_access_code = Cupix::Auth::AccessCode.decode(access_code)[0]
  # ...
  end

  user = UserRepository.show(decoded_access_code['user_id'])

  # validate access_code
  begin
    decoded_access_code = Cupix::Auth::AccessCode.decode(access_code, user.api_token)[0]
  # ...
  end

  team = TeamRepository.find_by_id(decoded_access_code['team_id'])
  @session = SessionFactory.new(current_user: user, current_team: team).create!(grant_type: 'access_code')
  token = TokenFactory.create!(@session)
  render_json 200, TokenSerializer.new(token).serializable_hash[:data][:attributes]
end

AccessCode.decode는 in-memory JWT 처리로 네트워크 호출이 없다.

class AccessCode
  class << self
    def decode(code, secret = nil)
      JWT.decode code, secret, secret.present?
    end

기대 동작: DB 조회 2회(UserRepository.show, TeamRepository.find_by_id) + JWT decode 2회 + SessionFactory.create! (DB insert) + TokenFactory.create! (JWT 서명). 정상 트래픽에서 관측되는 duration 50 ms ~ 100 ms 범위와 일치.

실제 동작: duration 11382 ms, db 1249 ms (정상보다 5배 ~ 20배), view 0.98 ms. DB만으로는 지연을 설명할 수 없고, 초과 약 10 s는 application 영역에서 발생.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api AuthenticatesController

시간 범위 2026-07-03T08:31:00Z ~ 2026-07-03T08:32:30Z 내에서 관측된 AuthenticatesController#create request duration 분포(원본 로그의 attributes.duration, ms):

62.32
238.87
5921.35   ← same host, grant_type=refresh_token
361.81
386.10
3171.12
3436.78
65.02
60.22
45.17
84.96
74.66
59.17
59.63
54.55
51.68
2483.61
52.01
208.02
56.02
1495.39
341.49
299.57
11382.05  ← 본 cluster의 대표 request (request_id fb0d80bd)
423.40
47.58
47.03
1288.79
95.91
1401.19

대상 요청 원문(요약):

{
  "@timestamp": "2026-07-03T08:31:51.124Z",
  "host": "ip-10-1-144-228.us-west-2.compute.internal",
  "controller": "Api::V1::AuthenticatesController",
  "action": "create",
  "params": { "grant_type": "access_code" },
  "duration": 11382.05,
  "db": 1249.21,
  "view": 0.98,
  "http": { "status_code": 200 }
}

같은 host에서 32초 후 refresh_token 요청도 지연:

{
  "@timestamp": "2026-07-03T08:32:27.176Z",
  "host": "ip-10-1-144-228.us-west-2.compute.internal",
  "params": { "grant_type": "refresh_token" },
  "duration": 5921.35,
  "db": 1153.20,
  "view": 0.93,
  "http": { "status_code": 200 }
}

Status board (cli/incident-board.ts for-cluster bb3f2774-...) 결과:

scope: svc:cupixworks-api::unknown
active incident: 2026-07-03-svc-cupixworks-api--unknown-1
  started_at: 2026-07-03T08:08:35.753Z (17:08 KST)
  last_event_at: 2026-07-03T09:45:16.160Z (18:45 KST)
  cluster_ids: 8 clusters clustered under this incident

본 cluster의 first_seen (08:31:38Z)이 인시던트 open window(08:08:35Z ~ 09:45:16Z) 안에 포함된다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 별도의 코드 변경은 필요하지 않다. 본 cluster는 상위 서비스 인시던트 2026-07-03-svc-cupixworks-api--unknown-1의 파생 증상이므로 상위 인시던트의 근본 원인(GC, thread contention, upstream dep, DB pool 등) 조사가 우선이다.
• 상위 인시던트 조사 시 ip-10-1-144-228.us-west-2.compute.internal host의 08:00 ~ 09:00 UTC window에서 puma thread status, GC.stat, DB connection pool 대기 시간, 그리고 Cognito/외부 dep p99 latency를 확인하도록 권고.

단기 개선 (1주 이내)#

• AuthenticatesController#create 경로에 request-level fine timing (JWT decode / UserRepository.show / SessionFactory.create! / TokenFactory.create! 각 단계 duration)을 info 레벨로 남기면, 다음 지연 발생 시 어느 단계가 병목인지 로그만으로 특정 가능하다.
• 인증 요청에 대해 최대 5 s 응답 시간 SLO를 정의하고, p99 > 5 s가 5분 지속되면 별도 알림 발생.

장기 개선 (재발 방지)#

• cupixworks-api production 노드에 대한 상시 dashboard: puma queue depth, GC pause time, DB connection pool wait, upstream (Cognito) p99. 이번 인시던트처럼 status board svc:...::unknown scope로 분류된 반복적 degradation의 근본 원인을 좁히기 위한 관측성 강화.
• Auth 경로에 회로차단(circuit breaker) 도입 검토: Cognito 등 외부 dep 응답이 임계값을 초과하면 fail-fast하여 puma thread가 blocking되지 않도록.

Monitoring#

Datadog 쿼리(release dashboard timeseries widget용):

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::authenticatescontroller#create,env:production}

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::authenticatescontroller#create,env:production}.as_rate()

avg:trace.rack.request.duration.by.http_status_code{service:cupixworks-api,resource_name:api::v1::authenticatescontroller#create,http.status_code:200,env:production}

같은 window에서 host-level 지표 병행 관측:

avg:system.load.norm.1{service:cupixworks-api,region:us-west-2}

avg:ruby.gc.time{service:cupixworks-api,env:production}

Risk Assessment#

• Risk level: medium — 개별 요청은 성공(HTTP 200)했지만 로그인 응답 지연은 사용자 이탈과 client timeout을 유발할 수 있다.
• 예상 복잡도: 본 cluster 단독으로는 trivial (코드 변경 불필요). 상위 서비스 degradation 인시던트 조사는 standard.