RCA: Api::V1::UsersController#check_ispring_connection latency (52138ms)

Overview#

What Happened#

2026-07-03 17:51 KST 경, cupixworks-api 의 GET /api/v1/users/:id/check_ispring_connection 엔드포인트에서 응답에 52.1초가 걸린 latency trace 1건이 감지되었다. 같은 시간대(08:08–09:45 UTC)에 cupixworks-api 의 서로 무관한 엔드포인트 7개에서도 10s ~ 13s 범위의 latency spike 가 동시에 발생했고, status-board incident 2026-07-03-svc-cupixworks-api--unknown-1 로 묶여 있다. 즉 이 클러스터는 endpoint 로직 결함이 아니라 서비스 전반의 일시적 latency spike 이벤트의 한 조각이며, 동시에 52초라는 가장 큰 spike 를 만든 outlier 이기도 하다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-03 17:08 KST — status-board incident 2026-07-03-svc-cupixworks-api--unknown-1 시작 (첫 sibling latency 클러스터 b3c83033)
2. 2026-07-03 17:19 KST — 두 번째 sibling 25b7ab18
3. 2026-07-03 17:51 KST — 본 클러스터 최초/최종 발생 (check_ispring_connection, 52138ms). 같은 시각까지 다른 check_ispring_connection 요청들은 모두 정상 200 응답 (Datadog 로그 기준 subsecond)
4. 2026-07-03 17:59–18:45 KST — sibling 클러스터 5건 추가 발생 (Meshes#index, Clusters#create_resource, Admin::add_reviewer 등)
5. 2026-07-03 이후 — 같은 엔드포인트의 인접 요청은 정상 200 으로 복귀. incident 는 여전히 open 상태 (resolved_at: null) 이나 error/warn 신호는 이 창 이후 감소

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::UsersController#check_ispring_connection",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 52138,
  "max_ms": 52138,
  "sample_trace_id": "2250649252354417794"
}

동일 엔드포인트의 정상 응답 (같은 시간대):

2026-07-03T08:52:49.271Z  [200] GET /api/v1/users/6015/check_ispring_connection
2026-07-03T08:52:48.325Z  [200] GET /api/v1/users/49827/check_ispring_connection
2026-07-03T08:52:24.284Z  [200] GET /api/v1/users/24807/check_ispring_connection
2026-07-03T08:51:49.836Z  [200] GET /api/v1/users/62/check_ispring_connection
2026-07-03T08:51:31.377Z  [200] GET /api/v1/users/24807/check_ispring_connection
2026-07-03T08:51:09.347Z  [200] GET /api/v1/users/24807/check_ispring_connection
2026-07-03T08:51:09.345Z  [200] GET /api/v1/users/24807/check_ispring_connection
2026-07-03T08:51:00.153Z  [200] GET /api/v1/users/776/check_ispring_connection
2026-07-03T08:50:55.329Z  [200] GET /api/v1/users/776/check_ispring_connection
2026-07-03T08:50:50.142Z  [200] GET /api/v1/users/49827/check_ispring_connection
2026-07-03T08:50:43.308Z  [200] GET /api/v1/users/49827/check_ispring_connection

Sibling latency clusters in the same svc-level incident:

b3c83033  08:08:35 UTC  (unknown resource)
25b7ab18  08:19:40 UTC  (unknown resource)
e2c1903c  08:51:10 UTC  Api::V1::UsersController#check_ispring_connection   52138 ms  ← this cluster
970f41f2  08:59:54 UTC  Api::V1::MeshesController#index                     12189 ms
9203687e  09:01:24 UTC  Api::V1::ClustersController#create_resource         10798 ms
60fe7289  09:02:03 UTC  (unknown resource)
3caa3b99  09:02:32 UTC  Api::V1::Admin::EditingsController#add_reviewer     12878 ms
116ab21f  09:45:16 UTC  (unknown resource)

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-03 17:51 KST
• 최근 발생: 2026-07-03 17:51 KST
• 직접 영향: 특정 사용자 1명의 iSpring 연결 상태 조회가 52초 지연. 응답이 200 이었는지 client-side timeout 으로 abort 됐는지 로그로 재현되지 않음 — 이 trace 에 대응하는 완료 로그가 Datadog info stream 에서 관찰되지 않음 (uncertain — needs APM span 확인).
• 간접 영향: 이 52초 동안 Puma worker 슬롯 1개가 점유되었을 개연성이 매우 높고, 뒤이어 08:59–09:02 UTC 에 4개 이종 엔드포인트에서 동시 10s+ latency 가 발생 — Puma worker 굶주림(queueing) 이 sibling cluster 를 일으켰다는 가설의 대표 증거다.

Root Cause Summary#

이 엔드포인트의 repository 로직(User.joins(:ispring_user).where(email: @model.email).first) 자체는 외부 iSpring 호출을 하지 않고 단순한 DB inner join 1건이므로 정상 경로에서는 subsecond 로 끝나야 한다. 실제로 같은 시각 인접한 다른 check_ispring_connection 요청은 전부 200 정상이었다. 따라서 52초 지연은 (a) endpoint 코드 결함이 아니며, (b) svc-level latency incident 2026-07-03-svc-cupixworks-api--unknown-1 의 대표 파편이자 (c) 이 slow 요청이 Puma worker 를 52초 동안 붙잡아 8분 뒤 시작된 sibling latency spike 를 유발/증폭한 primary contributor 로 보인다. 단일 클러스터로는 52초 동안 어디서 대기했는지(요청 큐잉 / DB connection checkout / permission_joins slow plan / 외부 인증 middleware) 를 확정할 수 없어 세부 원인은 uncertain — needs verification. 병목 후보 중 가장 유력한 것은 before_action :set_user 가 호출하는 UserRepository.permission_joins 의 heavy multi-LEFT-JOIN SQL (grouped_users 조인 포함) 이 특정 사용자 데이터에서 slow plan 을 만들었을 가능성이다.

Technical Analysis#

Code Path#

Entry point 및 controller 흐름:

class Api::V1::UsersController < Api::V1::ApiController
  include ParameterRequired
  include CyclableController
  include MfaController

  before_action :set_user, except: %i[create index request_reset_password reset_password untrash purge find_user_by_email mock provision]
  skip_before_action :authenticate!, only: %i[request_reset_password reset_password provision]

check_ispring_connection 은 except 목록에 없으므로 set_user before_action 이 실행된다.

Action 본체:

def check_ispring_connection
  connected = repository_instance.check_ispring_connection

  render_json 200, { connected: connected }
end

Repository 메서드 (실질 로직):

def check_ispring_connection
  existing_user = ::User.joins(:ispring_user).where(email: @model.email).first
  existing_user.present?
end

User has_one :ispring_user 는 IspringUser belongs_to :user 단순 관계이며 outer HTTP 호출이 전혀 없다. check_ispring_connection 자체는 subsecond 로 끝나야 하는 단일 DB 쿼리다.

Before_action set_user 가 호출하는 heavy SQL:

def show(id, **kwargs)
  self.model = UserRepository.permission_joins(::User, current_user).find_by(id: id)

  raise Cupix::Errors::NotFound.new(code: 'ARG10002', reason: 'User not found') if self.model.nil?

  unless self.model.readable_by?(self.current_user)
    raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied')
  end

  self.model
end

permission_joins 는 3개의 correlated LEFT JOIN subquery + GROUP BY 로 구성된 무거운 SQL 로, grouped_users 테이블의 특정 사용자 매핑이 크면 plan 이 급격히 나빠질 수 있다:

def self.permission_joins(record, current_user, select: nil, **kwargs)
  # ... SELECT with MAX(GREATEST(...)) AS applied_permission
  sanitized_user_id = ApplicationRecord.sanitize_sql(current_user.id) rescue -1

  record.joins("
    LEFT JOIN ( ... team_permissions accessor_type = 'User' ... ) AS team_user_permissions
    LEFT JOIN ( ... team_permissions accessor_type = 'Group' JOIN grouped_users ... ) AS team_group_permissions
    LEFT JOIN ( ... team_permissions accessor_type = 'Group' AND team_id IS NULL ... ) AS team_system_group_permissions
  ").group('id').select(_select).where("
    GREATEST(
      IFNULL(team_user_permissions.permission, 0),
      IFNULL(team_group_permissions.permission, 0),
      IFNULL(team_system_group_permissions.permission, 0)
    ) > 0
  ")
end

Failure point: endpoint 코드에는 없음. 지연은 (1) 요청이 Puma worker 에 도달하기 전 큐잉, (2) DB connection pool checkout 대기, (3) permission_joins 의 slow plan 중 하나에서 발생했을 개연성이 크다. 52초 지연은 endpoint 로직만으로는 재현되지 않으며 APM span 트리 (trace_id 2250649252354417794) 확인이 필요하다. uncertain — needs verification.

Log Evidence#

Datadog 쿼리 (재현 가능):

service:cupixworks-api "check_ispring_connection"
from: 2026-07-03T08:50:00Z  to: 2026-07-03T08:53:00Z

같은 시간대의 다른 check_ispring_connection 요청은 모두 200 정상 (앞의 Error Log 섹션 참고). 특히 08:51:09.345 / 08:51:09.347 UTC 에 user_id 24807 로 3건이 2ms 이내에 동시 도달했고, 이 시각 직후인 08:51:10.905 UTC 에 본 slow trace 가 시작되었다 — 프론트가 병렬로 fan-out 하는 패턴이 확인된다.

Slow trace 자체의 완료 info 로그는 관측되지 않음 (Datadog info stream 에서 trace_id 2250649252354417794 미포착):

Found 0 logs

Service-wide errors/warns 는 이 endpoint 와 무관 (같은 창의 warn 은 모두 Elasticsearch reindex 관련 NotFound - attributes_in_database):

2026-07-03T09:14:57Z  WARN  NotFound - attributes_in_database  class=ElementTrace  function=_update_document
2026-07-03T09:14:48Z  WARN  NotFound - attributes_in_database  class=Record        function=_update_document
2026-07-03T09:14:42Z  WARN  NotFound - attributes_in_database  class=Pointcloud    function=_update_document
... (동일 warn 반복)

check_ispring_connection 경로에서 발생 가능한 유일한 iSpring 관련 error(create_ispring_account 에서만 raise) 는 같은 창에 없다:

2026-07-03T08:52:27Z  [400] POST /api/v1/users/1820/create_ispring_account  code=ARG30002 "Cupix users cannot create iSpring account"
2026-07-03T08:42:28Z  [400] POST /api/v1/users/1820/create_ispring_account  code=ARG30002 (same)
...

Service max latency 시계열 (max:trace.rack.request.duration{service:cupixworks-api}, 24h) 에는 sibling RCA 에서도 인용된 spike 들이 명확히 관측되고, 그 중 52.137(단위 s 로 해석 시) 및 14867.9 ms 값은 본 클러스터/sibling 과 규모가 일치한다:

... 52.587, 14867.942962, 12.058832, 5966.5284, 353.42, 288.70 ...

RDS CPU 는 같은 창에서 5–13% 로 정상 (DB-wide 부하는 원인 아님):

... 11.35, 11.22, 11.34, 11.15, 11.32, 11.28, 11.35 ...

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 없음. 이 클러스터 단일 건에 대응하는 code fix 는 없다. Endpoint 코드는 정상이며 latency 는 svc-level incident 의 소산이다. errors/{cluster-id}.md 는 pipeline 이 관리하되, 사람이 개입할 곳은 svc-level incident 2026-07-03-svc-cupixworks-api--unknown-1 조사이다.

단기 개선 (1주 이내)#

• APM trace 분석: trace_id 2250649252354417794 의 flame graph 를 Datadog APM 에서 확인. 52초가 rack.queue_time 인지 db.query (permission_joins) 인지 authenticate! middleware 인지 분해. 같은 sibling 4992016731129222103(create_resource, 10.8s) 등과 span 시간 분포를 비교해 공통 병목 span 을 특정.
• permission_joins 의 slow plan 감사: app/repositories/user_repository.rb:210-264 의 3-LEFT-JOIN SQL 이 특정 user (예: system group 다수 매핑) 에서 slow plan 을 만드는지 pg query_stats / RDS Performance Insights 로 확인. grouped_users 인덱스 (user_id, group_id) 및 team_permissions 인덱스 (accessor_id, accessor_type, team_id) 존재 여부 재점검.
• Puma worker/thread 설정 검토: 요청 1건이 52초 걸릴 때 뒤 요청들이 큐잉되는 구조라면 (H5), 슬로우 요청을 격리(별도 Puma 그룹 또는 timeout 강제) 하거나 worker 수를 늘려 큐잉 영향 축소. puma.request.queue_time 계열 metric 을 대시보드에 상시 노출.
• 프론트엔드의 check_ispring_connection 호출 dedup: 로그상 같은 user_id 로 2ms 이내 3연속 호출(08:51:09.345/347) 이 관측됨. 동일 요청 in-flight dedup 이나 결과 캐시(짧은 TTL) 를 도입해 backend 부담을 줄인다.

장기 개선 (재발 방지)#

• Status-board classifier 를 확장해 svc:{service}::unknown 대신 dominant slow-span 종류(예: db_slow_permission_joins, puma_queue_saturation) 로 라벨링. 현재 8개 sibling 이 전부 unknown 이라 사람이 매번 재조사해야 한다.
• APM latency 임계값(예: >10s) 초과 트레이스에 대해 span 상세(외부 HTTP, DB, GC) 를 자동 캡처해 이후 RCA 에서 endpoint-specific vs 공유-리소스 병목을 자동 판별.
• iSpring 검사처럼 결과가 자주 바뀌지 않는 조회는 서버측 short-TTL 캐시 후보로 검토 (동일 사용자 대상 반복 호출 관측).

Monitoring#

• Service-wide p95/p99 latency 시계열 — 동일 형태 spike 조기 감지:

p95:trace.rack.request.duration{service:cupixworks-api}

p99:trace.rack.request.duration{service:cupixworks-api}

• 이 endpoint 의 p95 latency (같은 spike 재발 여부):

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::userscontroller#check_ispring_connection}

• 서비스 전반 10초 이상 요청 hit count (병목 재발 감지):

sum:trace.rack.request.hits{service:cupixworks-api,duration:>10s}.as_count()

• Puma queue time (요청이 워커에 도달하기 전 대기 시간; 태그명은 배포 환경에 맞게 조정):

avg:puma.request.queue_time{service:cupixworks-api}

• RDS CPU / query time (DB-wide 병목 배제용):

avg:aws.rds.cpuutilization{*}

avg:postgresql.query.time{service:cupixworks-api}

Risk Assessment#

• Risk level: medium — 이 요청 자체는 사용자 1명의 SSO 상태 조회로 데이터 무결성 영향은 없다. 그러나 52초 slow path 가 sibling 4개 endpoint 의 10s+ latency 를 유발했을 개연성이 커서, 재발 시 결제/업로드 등 시간 민감 요청에 파급될 위험이 있다.
• 예상 복잡도: standard — endpoint 코드 수정은 불필요. 병목 확정(APM span 분석) + permission_joins 인덱스/쿼리 감사 + Puma sizing 재검토 는 표준 성능 튜닝 범위.