RCA: Api::V1::SessionsController#show latency (avg 20550 ms, max 20897 ms)

Overview#

What Happened#

2026-06-25 02:37 ~ 02:38 KST 사이, cupixworks-api 의 Api::V1::SessionsController#show 가 2회 연속 약 20 s 응답시간으로 동작했다 (avg 20550 ms, max 20897 ms). 동일 시간대에 같은 호스트(ip-10-1-144-228.us-west-2) 에서 다수의 다른 컨트롤러(PanosController#create, PanosController#check_uploading, RecordsController#flush_geo_coordinate 등)도 5 ~ 8 s 의 비정상 응답을 기록했고, 같은 region 의 다른 호스트에서 Api::V1::ElementTracesController#refresh 가 duration=221786 ms, db=56758 ms 으로 실행 중이었다. 즉, Sessions 엔드포인트 자체의 신규 결함이 아니라 cupixworks-api production us-west-2 의 워커/DB 풀 saturation 으로 인한 광역 latency 의 한 단면이다.

Quick Facts#

Affected Teams#

/api/v1/sessions 는 클라이언트 부팅/포커스 복귀 시 호출되는 엔드포인트라 응답 지연이 길어지면 UI 진입 자체가 stall 한다.

Timeline#

1. 2026-06-24 17:37:53 UTC (2026-06-25 02:37 KST) — 같은 region 의 ip-10-1-80-134 호스트에서 Api::V1::PanosController#bulk 가 18.7 s, db=4696 ms 로 시작 (concurrent slow requests 다수).
2. 2026-06-25 02:38:17 KST — ip-10-1-144-228 에서 SessionsController#show 첫 번째 slow 요청 (duration=20883.72 ms, db=3002.27 ms, 사용자 gilbaneco).
3. 2026-06-25 02:38:37 KST — ip-10-1-80-134 에서 Api::V1::ElementTracesController#refresh 가 duration=221786 ms, db=56758 ms 로 진입 (단일 요청이 워커 1개를 56 s+ 점유).
4. 2026-06-25 02:38:41 KST — ip-10-1-144-228 에서 SessionsController#show 두 번째 slow 요청 (duration=20173.22 ms, db=1960.47 ms, 사용자 okland).
5. 2026-06-25 02:59 KST — status board 가 cluster 94ea15c2-... 를 마지막 이벤트로 svc 인시던트 2026-06-24-svc-cupixworks-api--unknown-2 를 resolved 처리.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::SessionsController#show",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 20550,
  "max_ms": 20897,
  "sample_trace_id": "2156428168216780945"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2
• 최초 발생: 2026-06-25 02:37 KST
• 최근 발생: 2026-06-25 02:38 KST
• 광역 영향: 같은 시간대(02:37 ~ 02:38 KST) 에 동일 region 에서 30+ 건의 5 s 초과 요청이 다양한 엔드포인트에 걸쳐 발생. status board 인시던트 2026-06-24-svc-cupixworks-api--unknown-2 의 7개 cluster 중 하나.

Root Cause Summary#

SessionsController#show 핸들러 자체는 사실상 빈 메서드(super)지만, 모든 Api::V1::* 요청이 공통으로 통과하는 before_action 체인 — set_auth_method → authenticate!(JWT 검증 + Cognito user fetch + User.eager_load(:team).find_by_email) → check_team_license → set_app_id 등 — 과 응답 직렬화 시점의 session.user.reload / session.team.reload 가 DB connection 을 요구한다. 사건 시점에 같은 region/호스트의 워커 풀이 Api::V1::ElementTracesController#refresh 의 56.7 s DB 쿼리와 Api::V1::PanosController#bulk 의 4 ~ 5 s DB 쿼리들로 포화되었고, 결과적으로 가벼운 Sessions 요청도 (1) DB connection 획득, (2) 직렬화 단계 reload 쿼리들이 같은 풀에서 차례를 기다리며 18 ~ 20 s 까지 누적되었다. 두 slow 요청 모두 view=0.07 ~ 0.11 ms, serialization.duration=0 으로 view/serializer 자체는 빠르므로, 지연은 DB/풀 wait + 인증 단계의 외부 호출 누적 에 집중된다.

Technical Analysis#

Code Path#

엔트리포인트는 매우 얇다.

class Api::V1::SessionsController < Api::V1::ApiController
  before_action :set_session

  def show
    super
  end

  def destroy
    SessionRepository.new(@session).delete
  rescue => e
    Cupix::Logger.error("Error occurred while destroying session - error: #{e.message}", class: self.class, function: __method__)
  else
    render_api
  end

  protected

  def set_session
    @model = @session
  end

super 는 Api::V1::ApiController#show 를 호출한다.

def show
  render_api Renderable.new({
    contents: @model,
    serializer_option: @serializer_option
  })
end

비용은 부모 컨트롤러가 include 하는 before_action 체인에서 나온다.

class Api::V1::ApiController < ApiController
  include VerificationController
  include SearchableController
  include RenderableController
  include StatusController
  include BillingController
  include MockableController
  include EntityParameterableController

  before_action :set_app_id

  include SetCurrentRequestDetails

  before_action :check_team_license
  before_action :check_access_token_scope, if: proc { |request| @scope_in_access_token.present? }
  before_action :check_session_scope, if: proc { |request| @scope_in_session.present? }
  before_action :check_scope_in_header
  before_action :set_updated_since
end

authenticate! 는 JWT 검증을 캐시한 뒤 Cognito API 와 DB 를 모두 거친다.

def authenticate!
  if @cupix_auth_method == 'COGNITO'
    begin
      verification = Cupix::Auth::Verification.new(request: request)
      response = verification.verify_authenticated_request!
    rescue Cupix::Errors::Unauthorized => e
      ...
    end

    @current_user = response.user
    @current_team = response.team
    @session = response.session
    Current.access_token = verification.access_token
  else
    legacy_authenticate!
  end
end

verify_authenticated_request! 본체에서 Cognito 외부 호출과 User.eager_load(:team).find_by_email 이 발생한다.

user_response = Cupix::Aws::Cognito.get_user_by_access_token(access_token: access_token, sub: sub)
...
user = ::User.eager_load(:team)
             .where(
               teams: {
                 domain: @current_team_domain
               }
             )
             .find_by_email(user_response.email)

응답 직렬화 시점에는 SessionSerializer 가 user/team 을 다시 reload 한다.

class SessionSerializer
  include CupixSerializer

  attribute :user do |session|
    SessionUserSerializer.new(session.user.reload, {
      params: { team: session.team }
    }).serializable_hash[:data]
  end

  attribute :team do |session|
    TeamSerializer.new(session.team.reload).serializable_hash[:data]
  end

  attributes :grant_type, :created_at, :updated_at, :expires_at

  attribute :session_id
end

기대 동작은 db ≈ 50 ms, view < 5 ms, total < 200 ms (정상 시 65 ms 의 sample 로그가 다수 관찰됨). 실제 동작은 db = 1960 ~ 3002 ms, total = 20173 ~ 20883 ms 으로, db 외에 약 17 ~ 18 s 가 컨트롤러 진입까지의 connection acquisition / 외부 호출 / Puma 큐 wait 로 소비되었다. 두 slow 요청 모두 serialization.duration = 0, view ≈ 0.1 ms 이므로 view 단계는 후보에서 배제된다.

Log Evidence#

Datadog 쿼리 (재현 가능):

service:cupixworks-api @http.url_details.path:"/api/v1/sessions" @duration:>10000

해당 시간 창에서 발견된 slow Sessions 요청 2건 전체:

{
  "@timestamp": "2026-06-24T17:38:41.703Z",
  "host": "ip-10-1-144-228.us-west-2.compute.internal",
  "controller": "Api::V1::SessionsController",
  "action": "show",
  "duration": 20173.22,
  "db": 1960.47,
  "view": 0.11,
  "serialization": {"duration": 0},
  "params": {"fields": ["user", "team"]},
  "team": {"domain": "okland", "id": 736},
  "user": {"id": 51635, "email": "jeff.stolzoff@okland.com"},
  "request_id": "808c26c8-d53d-41a0-a51b-2d145cb91884",
  "version": "production-us-west-2-20260624t0500z0-24b9962e-cupixworks"
}

{
  "@timestamp": "2026-06-24T17:38:17.650Z",
  "host": "ip-10-1-144-228.us-west-2.compute.internal",
  "controller": "Api::V1::SessionsController",
  "action": "show",
  "duration": 20883.72,
  "db": 3002.27,
  "view": 0.07,
  "serialization": {"duration": 0},
  "params": {"fields": ["user", "team"]},
  "team": {"domain": "gilbaneco", "id": 780}
}

같은 시점, 같은 region 에서 동시 발생한 slow 요청들 — 광역 saturation 의 직접 증거 (쿼리: service:cupixworks-api @duration:>5000 시간창 17:37:30 ~ 17:39:00 UTC):

2026-06-24T17:37:53.538Z ip-10-1-80-134  PanosController#bulk           dur=18739.29 db=4696.35
2026-06-24T17:38:17.650Z ip-10-1-144-228 SessionsController#show        dur=20883.72 db=3002.27
2026-06-24T17:38:23.663Z ip-10-1-144-228 PointcloudsController#create   dur=5111.94  db=993.04
2026-06-24T17:38:23.664Z ip-10-1-144-228 PanosController#check_uploading dur=5184.41 db=642.85
2026-06-24T17:38:27.674Z ip-10-1-144-228 Admin::EditingsController#update dur=8313.7 db=1939.31
2026-06-24T17:38:35.672Z ip-10-1-80-134  PanosController#bulk           dur=15810.85 db=4754.7
2026-06-24T17:38:37.683Z ip-10-1-80-134  ElementTracesController#refresh dur=221786.06 db=56758.99
2026-06-24T17:38:39.698Z ip-10-1-144-228 ElementTracesController#refresh dur=161141.64 db=1194.77
2026-06-24T17:38:41.703Z ip-10-1-144-228 SessionsController#show        dur=20173.22 db=1960.47
2026-06-24T17:38:43.707Z ip-10-1-144-228 RecordsController#flush_geo_coordinate dur=5677.41 db=1814.37

같은 시간 창에 service:cupixworks-api status:error 검색 결과는 0건. 즉, 5xx 폭증이 아니라 latency-only 사건이다. status:warn 결과는 NotFound - attributes_in_database (Pano/Record/EditingEntity 의 Elasticsearch _update_document) warn 이 다수였으나 SessionsController 와 직접 인과관계는 확인되지 않는다.

비교 baseline — 같은 시간 창의 정상 Sessions 요청 (쿼리: service:cupixworks-api @http.url_details.path:"/api/v1/sessions" status:info):

{
  "@timestamp": "2026-06-24T17:38:56.556Z",
  "host": "ip-10-1-19-190.us-west-2.compute.internal",
  "duration": 65.27,
  "db": 14.41,
  "view": 0.07,
  "serialization": {"duration": 0}
}

정상 응답은 duration=65 ms, db=14 ms 이므로 slow 요청의 18 ~ 20 s 는 endpoint 로직이 아니라 호스트/풀 상태에 종속된다.

Status board 컨텍스트 (스킬 출력 발췌):

{
  "scope": "svc:cupixworks-api::unknown",
  "active": null,
  "recent": [{
    "id": "2026-06-24-svc-cupixworks-api--unknown-2",
    "title": "cupixworks-api service degraded",
    "status": "resolved",
    "started_at": "2026-06-24T16:45:41.172Z",
    "resolved_at": "2026-06-24T17:59:31.677Z",
    "cluster_ids": [
      "bd35bc1d-...", "9e993945-...",
      "c387835e-3ff3-4300-8b16-1f9464275f5d",
      "13c20707-...", "cc83185a-...",
      "be873aea-...", "94ea15c2-..."
    ]
  }]
}

이 cluster 는 같은 인시던트의 7개 cluster 중 하나다. 같은 인시던트의 sibling cluster (be873aea AssetsController#index) RCA 는 serializer N+1 (heavy cover_urls/badges/annotations expand) 을 root cause 로 결론지었다. SessionsController 는 그와 별개의 controller body 결함이 아니라 같은 saturation 의 collateral damage 로 보인다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

이 cluster 자체의 코드 변경은 권장하지 않는다. 같은 인시던트(2026-06-24-svc-cupixworks-api--unknown-2) 의 saturation 원인 cluster 들을 우선 조치한다.

• 수정 대상 후보 (순서대로):
  1. Api::V1::ElementTracesController#refresh — 56.7 s DB 쿼리. 동일 호스트에서 3분 안에 2회 발생 (duration=221786, 161141 ms). 별도 cluster 로 발견되지 않았다면 신규 cluster 등록 후 RCA 필요.
  2. Api::V1::PanosController#bulk — 같은 시간 창에 8회 이상 5 ~ 18 s 응답. cluster cc83185a-... (PanosController#create) / bd35bc1d-... (PanosController#index) 와 동일 root cause 영역으로 추정.
  3. sibling cluster be873aea-... (AssetsController#index) 의 serializer N+1 fix. 이미 별도 RCA 와 actionability_score=44 가 부여됨.

근거: SessionsController 의 handler/serializer 자체는 baseline 65 ms 로 정상 동작하므로, Sessions 코드 수정은 false fix 다.

단기 개선 (1주 이내)#

• Api::V1::ApiController 진입 단계에 Rack::Runtime 또는 custom middleware 로 request queue time (Puma 가 worker 에 deliver 하기까지 wait) 측정값을 request 로그에 추가. 현재 duration 만으로는 controller body wait 와 queue wait 를 분리할 수 없어 saturation 사건의 RCA 가 어렵다.
• DB connection pool wait 메트릭 (activerecord.connection_pool.wait) 을 Datadog 로 노출하여 saturation 가시화.
• SessionSerializer 의 session.user.reload / session.team.reload 는 saturation 시점에 추가 connection 점유를 유발하므로 reload 의 필요성 재검토. 이미 authenticate! 에서 User.eager_load(:team) 로 fresh load 하므로 reload 없이도 충분할 수 있음. 단, 본 cluster 의 root cause 는 아니므로 우선순위는 낮음.

장기 개선 (재발 방지)#

• Long-running endpoint (ElementTracesController#refresh) 를 Puma worker 에서 분리 (Sidekiq async + polling status, 또는 별도 worker pool). 단일 endpoint 가 56 s+ 전용 connection 을 점유하면 동일 region 의 모든 가벼운 endpoint(SessionsController 포함) 가 collateral damage 를 입는다.
• Region 별 read replica 분리 또는 statement_timeout 강제 (SET LOCAL statement_timeout = '15s') 로 polluting query 가 풀을 점유하지 못하게 차단.
• Status board scope 가 svc:cupixworks-api::unknown 으로 떨어지지 않도록 root_cause_type 분류기 보강 — latency cluster 가 saturation 인지 endpoint 결함인지 자동 구분되어야 같은 collateral cluster 7개에 동일 RCA 노력이 중복되지 않는다.

Monitoring#

• Sessions endpoint p95 가 normal 65 ms 대비 1 s 이상 상승하면 인접 endpoint saturation 신호. Datadog timeseries:

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::SessionsController#show}.rollup(avg, 60)

• 같은 region 의 모든 endpoint 5 s 초과 요청 수 — saturation 의 1차 신호:

sum:trace.rack.request.hits{service:cupixworks-api,@duration:>5000} by {resource_name}.as_count()

• Long-running endpoint 점유 추적:

max:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::ElementTracesController#refresh}

• DB connection pool wait (가능 시):

avg:activerecord.connection_pool.wait{service:cupixworks-api} by {host}

Risk Assessment#

• Risk level: medium (사용자 세션 갱신 stall = UI 진입 stall 이지만 occurrence 2건, recovered)
• 예상 복잡도: critical (이 cluster 자체는 fix 불필요. 인접 cluster bd35bc1d/cc83185a/be873aea 와 가상 endpoint ElementTracesController#refresh 의 collateral 으로 묶어 처리해야 하므로 단일 PR 로 끝나지 않음)