Api::V1::UsersController#create_ispring_account (avg 1731ms, max 1953ms)

RCA: Api::V1::UsersController#create_ispring_account Latency

Overview#

What Happened#

2026-05-27 07:25-07:26 UTC에 cupixworks-api 서비스의 create_ispring_account 엔드포인트에서 평균 1731ms, 최대 1953ms의 높은 응답 시간이 감지되었다. ap-northeast-1 리전의 jp-di 팀 사용자 2명이 iSpring 계정 생성을 요청했으며, 모든 요청은 HTTP 200으로 성공했지만 외부 iSpring API 호출로 인해 latency가 높았다.

Quick Facts#

Field	Value
resource_name	`Api::V1::UsersController#create_ispring_account`
top_frame	`app/operations/ispring_operation.rb:38`
env	production, ap-northeast-1
avg_duration	1731ms
max_duration	1953ms

Timeline#

2026-05-27T07:25:53Z — user 266 (a.makiuchi@ntt.com) iSpring 계정 생성 요청, 1951ms 소요
2026-05-27T07:26:35Z — user 166 (yuusuke_myouken@jpower.co.jp) iSpring 계정 생성 요청, 1509ms 소요
2026-05-27T07:26:37Z — 두 번째 요청 완료, latency 클러스터 감지

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::UsersController#create_ispring_account",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 1731,
  "max_ms": 1953,
  "sample_trace_id": "1274203608749349071"
}

Impact#

Service: cupixworks-api
발생 횟수: 2
최초 발생: 2026-05-27T07:25:51.763Z
최근 발생: 2026-05-27T07:26:35.166Z
영향: jp-di 팀 사용자 2명의 iSpring 계정 생성 시 1.5~2초 대기. 기능적 실패는 없으나 UX 저하.

Root Cause Summary#

create_ispring_account 요청 시 외부 iSpring API에 대해 두 번의 순차적 동기 HTTP 호출(OAuth token 발급 + 사용자 생성)이 발생하며, access token 캐싱이 없어 매 요청마다 token을 새로 발급받는다. iSpring API 자체의 응답 시간이 총 1.5~~1.9초를 차지하며, 내부 DB 처리(17~~22ms)는 무시할 수준이다. 이는 외부 API의 정상적인 응답 속도에 의한 구조적 latency이다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/users_controller.rb:96
Repository layer: app/repositories/user_repository.rb:271
Service layer: app/services/cupix/ispring_service.rb:14
HTTP call 1 (token): app/operations/ispring_operation.rb:141 → https://api-learn.ispringlearn.com/api/v3/token
HTTP call 2 (create user): app/operations/ispring_operation.rb:38 → https://api-learn.ispringlearn.com/user
DB write: app/services/cupix/ispring_service.rb:24 → user.create_ispring_user!

app/controllers/api/v1/users_controller.rb:96-100ruby

def create_ispring_account
  @model = repository_instance.create_ispring_account

  show
end

app/operations/ispring_operation.rb:141-169ruby

def get_access_token
  client_id = ENV['ISPRING_CLIENT_ID']
  client_secret = ENV['ISPRING_CLIENT_SECRET']

  data = {
    client_id: client_id,
    client_secret: client_secret,
    grant_type: 'client_credentials'
  }

  headers = {
    'Content-Type': 'application/x-www-form-urlencoded',
    'Accept': 'application/json'
  }

  begin
    url = 'https://api-learn.ispringlearn.com/api/v3/token'
    response = Cupix::HttpClient.post(url, data, headers)
  rescue StandardError => e
    Cupix::Logger.error("iSpring Authentication failed: #{e.message}", class: self.name, function: __method__)
    raise Cupix::Errors::BadGateway.new(
      code: 'BG10001',
      reason: "iSpring Authentication failed: #{e.message}",
      message: e.message
    )
  end

  JSON.parse(response.body)['access_token']
end

매 요청마다 get_access_token이 호출되어 OAuth token을 새로 발급받는다. client_credentials grant type의 token은 일정 시간 유효하므로, 캐싱 없이 매번 발급하는 것은 불필요한 latency를 추가한다.

app/operations/ispring_operation.rb:30-38ruby

begin
  url = 'https://api-learn.ispringlearn.com/user'
  response = Cupix::HttpClient.post(url, request_body.to_json, headers)
rescue RestClient::Exception => e
  error_body = e.response&.body || ''
  Cupix::Logger.error("iSpring create user failed: #{e.message}", class: self.name, function: __method__, response: error_body, request_body: request_body)
  raise Cupix::Errors::BadGateway.new(
    code: 'BG10001',
    reason: "iSpring create user failed: #{e.message}",
    message: e.message
  )
end

Cupix::HttpClient는 timeout 설정 없이 RestClient를 사용하며, retry는 [429, 502, 503, 504]에 대해 최대 3회 수행한다. 별도의 connection/read timeout이 지정되지 않아 RestClient 기본값(무제한)이 적용된다.

lib/cupix/http_client.rb:17-28ruby

def self.post(url, payload, headers = {}, retries: MAX_RETRIES)
  attempt = 0
  begin
    RestClient.post(url, payload, headers)
  rescue RestClient::Exception => e
    if RETRIABLE_STATUS_CODES.include?(e.http_code) && attempt < retries
      attempt += 1
      sleep((2**(attempt - 1)) + rand(0.0..0.5))
      retry
    end
    raise
  end
end

Log Evidence#

Datadog에서 조회한 두 요청의 duration 분석:

text

service:cupixworks-api @http.url_details.path:*create_ispring_account* env:production

json

{
  "request_1": {
    "timestamp": "2026-05-27T07:25:55.086Z",
    "user_email": "a.makiuchi@ntt.com",
    "user_id": 266,
    "duration_ms": 1951.26,
    "db_ms": 22.2,
    "view_ms": 0.14,
    "external_call_ms": 1929,
    "status": 200,
    "team": "jp-di",
    "request_id": "2eeea2c7-6b10-4ec3-abd4-19da3d1ce57f"
  },
  "request_2": {
    "timestamp": "2026-05-27T07:26:37.099Z",
    "user_email": "yuusuke_myouken@jpower.co.jp",
    "user_id": 166,
    "duration_ms": 1508.88,
    "db_ms": 17.31,
    "view_ms": 0.07,
    "external_call_ms": 1492,
    "status": 200,
    "team": "jp-di",
    "request_id": "58cd092b-6c24-440a-a280-9ae5c75746fe"
  }
}

Application-level 로그:

text

2026-05-27T07:25:53.913Z [INFO] Cupix::IspringService#create_user_account - "creating ispring account for user: a.makiuchi@ntt.com"
2026-05-27T07:25:53.913Z [INFO] Cupix::IspringService#create_user_account - "iSpring account created successfully - user_id: 266"
2026-05-27T07:26:35.922Z [INFO] Cupix::IspringService#create_user_account - "creating ispring account for user: yuusuke_myouken@jpower.co.jp"
2026-05-27T07:26:37.923Z [INFO] Cupix::IspringService#create_user_account - "iSpring account created successfully - user_id: 166"

Duration 분석 결과, 전체 latency의 98%+ (1492~~1929ms)가 외부 iSpring API 호출에 소요됨. DB (17~~22ms) 및 view rendering (<1ms)은 무시할 수준.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	외부 iSpring API 응답 속도가 느려 전체 latency를 지배	Duration 분석: 총 1951ms 중 DB 22ms, view 0.14ms → 외부 호출 ~1929ms. 두 요청 모두 동일 패턴.	—	Confirmed
H2	DB 쿼리 또는 N+1 문제로 인한 latency	—	DB time이 17~22ms로 전체의 1%에 불과. 단순 조회 1회 + insert 1회 구조.	Rejected
H3	Retry 로직에 의한 추가 latency (iSpring API가 429/5xx 반환 후 재시도)	—	HTTP 200 성공, error 로그 없음. Retry가 발생했다면 error 로그가 남았을 것.	Rejected
H4	Access token 캐싱 부재로 인한 추가 HTTP 호출 (latency 기여)	코드에서 `get_access_token`이 매 요청마다 호출됨 (`ispring_operation.rb:141`). 캐싱 로직 없음.	token 발급 자체의 latency를 개별적으로 측정할 수 없음 (로그 분리 없음)	Confirmed (contributing factor)

Fix Recommendation#

즉시 조치 (Critical)#

Access token 캐싱 구현: app/operations/ispring_operation.rb:141의 get_access_token 메서드에 Rails.cache 또는 class variable 기반 캐싱 추가. client_credentials token은 보통 1시간 유효하므로, 만료 시간 기반으로 캐싱하면 매 요청에서 token 발급 HTTP 호출 1회를 제거할 수 있다.
HTTP timeout 설정: lib/cupix/http_client.rb에 RestClient의 open_timeout(5초), read_timeout(10초) 설정 추가. 현재 timeout 미설정으로 iSpring API가 응답하지 않을 경우 무한 대기 가능.

단기 개선 (1주 이내)#

비동기 처리 검토: iSpring 계정 생성을 Sidekiq worker로 이관하여 사용자 요청을 즉시 응답 가능하게 변경. 이미 IspringAddAdminWorker 패턴이 존재하므로 동일 구조 활용 가능.
External API latency 메트릭 추가: token 발급과 user 생성 각각의 소요 시간을 StatsD/Datadog APM custom span으로 분리 계측.

장기 개선 (재발 방지)#

외부 API 호출을 포함하는 모든 동기 엔드포인트에 대해 timeout + circuit breaker 패턴 적용 검토.
iSpring API 호출에 대한 SLO 정의 (예: p99 < 3초) 및 위반 시 알림.

Monitoring#

iSpring API 호출 latency 추적:

text

service:cupixworks-api resource_name:"Api::V1::UsersController#create_ispring_account" @duration:>1000ms

Token 발급 실패 모니터링:

text

service:cupixworks-api "iSpring Authentication failed" status:error

Risk Assessment#

Risk level: low
예상 복잡도: standard
현재 기능적 실패는 없으며 UX 지연만 발생. 단, timeout 미설정으로 인해 iSpring API 장애 시 thread 고갈 위험 존재.