RCA: IntegrationsController#access_token Latency (1710ms)

Overview#

What Happened#

2026-05-26 09:40에 ap-southeast-2 리전의 cupixworks-api 서비스에서 Api::V1::IntegrationsController#access_token 요청이 1710ms 소요되었다. BIM360 integration(297)의 OAuth 토큰이 4시간 이상 만료된 상태에서 동기적 토큰 갱신 + 사용자 그룹 프로비저닝이 동시에 발생하여 latency spike가 발생했다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-05-26 05:33:26 UTC — BIM360 integration(297) 토큰 만료
2. 2026-05-26 09:40:39.433Z — 사용자(Daniel Lancashire) 요청 시작, UserFactory가 그룹 프로비저닝 수행
3. 2026-05-26 09:40:39.434Z — 만료된 토큰 감지, BIM360 OAuth 토큰 갱신 시작
4. 2026-05-26 09:40:41.435Z — BIM360 토큰 갱신 완료 (expired_at: 10:45:38 UTC)
5. 2026-05-26 09:40:39.944Z — HTTP 200 응답 반환 (총 1709ms)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::IntegrationsController#access_token",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1710,
  "max_ms": 1710,
  "sample_trace_id": "3100981153382337738"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-05-26T09:40:37.818Z
• 최근 발생: 2026-05-26T09:40:37.818Z

Root Cause Summary#

BIM360 integration(297)의 OAuth access token이 4시간 이상 만료된 상태에서 access_token 요청이 들어왔다. IntegrationRepository#refresh_token이 BIM360 OAuth 서버에 동기적으로 HTTP POST 요청을 보내 토큰을 갱신했으며, 이 외부 호출이 약 1576ms 소요되었다. 추가로 같은 요청 내에서 UserFactory#update_user_groups!가 사용자 그룹 프로비저닝을 수행하여 DB 시간(133ms)도 평소(~23ms) 대비 높았다. 두 요인이 결합되어 총 1710ms latency가 발생했다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/integrations_controller.rb:35
• Token 만료 확인: app/repositories/integration_repository.rb:93
• Token 갱신 시작: app/repositories/integration_repository.rb:103
• 외부 HTTP 호출: app/operations/bim360_operation.rb → lib/cupix/http_client.rb
• Failure point: 외부 API 응답 지연 (BIM360 OAuth 서버)

def access_token
  token = repository_instance.access_token
  render_json 200, token
end

repository_instance.access_token이 모든 로직을 담당하며, 동기적으로 완료될 때까지 요청이 블로킹된다.

# Existing logic for other providers (BIM360, Procore, etc.)
if @model.expired_at < 10.minutes.since
  refresh_token
else
  {
    provider: @model.provider,
    access_token: @model.access_token,
    token_type: @model.token_type,
    expired_at: @model.expired_at,
    region: @model.region
  }
end

토큰이 만료 시간 + 10분 이내이면 refresh_token을 호출한다. integration(297)의 토큰은 05:33 UTC에 이미 만료되어 이 조건에 해당했다.

def refresh_token
  # Redis lock to prevent concurrent refresh
  lock_key = "#{cache_key}::Lock::Key"
  lock_acquired = Rails.cache.redis_instance.setnx(lock_key, true)
  Rails.cache.redis_instance.expire(lock_key, 5)

  # ... provider-specific refresh logic
  # BIM360: Bim360Operation.refresh_token() -> HTTP POST to Autodesk OAuth
  # Updates @model with new tokens and saves
  @model.save!
end

refresh_token은 Redis lock 획득 후 Bim360Operation.refresh_token()을 호출하여 Autodesk OAuth 서버에 HTTP POST를 보낸다. 이 외부 호출이 ~1576ms 소요되었다.

RETRIABLE_STATUS_CODES = [429, 502, 503, 504].freeze
MAX_RETRIES = 3
# Exponential backoff: sleep((2**(attempt - 1)) + rand(0.0..0.5))

HTTP client에 명시적 timeout 설정이 없으며, RestClient 기본값(60초)에 의존한다. 재시도 시 최대 7.5초까지 추가 지연 가능.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api resource_name:"Api::V1::IntegrationsController#access_token" @duration:>500ms env:production

service:cupixworks-api trace_id:3100981153382337738

핵심 로그 항목:

[2026-05-26 09:40:39.434Z] [info] [Integration] refresh token for bim360 integration(297) - state: active, expired_at: 2026-05-26 05:33:26 UTC

[2026-05-26 09:40:41.435Z] [info] [Integration] Successfully refreshed token for bim360 integration(297) - state: active, expired_at: 2026-05-26 10:45:38 UTC

토큰 갱신에 약 2초(09:40:39 → 09:40:41) 소요. 이 시간이 요청의 대부분을 차지한다.

사용자 그룹 프로비저닝 로그:

[2026-05-26 09:40:39.433Z] [info] Custom groups found for user 1721
[2026-05-26 09:40:39.434Z] [info] User 1721 added to group ea792a62... #952
[2026-05-26 09:40:39.434Z] [info] User 1721 added to group d422658f... #953
[2026-05-26 09:40:39.434Z] [info] Provisioned user 1721 to groups

같은 날 다른 slow 요청들과 비교:

09:24:51Z - 533ms - bim360/access_token (www821) - DB: 24ms
09:11:53Z - 662ms - procore/access_token (z96drp) - DB: 26ms
06:27:45Z - 503ms - bim360/access_token (19f44g) - DB: 22ms

다른 요청들은 500-660ms 수준인데, 이 요청만 1710ms로 약 3배 높다. 차이는 (1) 토큰이 4시간 이상 만료되어 OAuth 서버 세션 갱신이 느렸을 가능성, (2) 동시에 UserFactory 그룹 프로비저닝이 발생한 점이다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 이 건은 단발성 latency spike (1회)로 즉각적 수정이 필요한 수준은 아님.
• 단, lib/cupix/http_client.rb에 명시적 connection/read timeout을 설정하여 외부 API 호출의 최대 대기 시간을 제한하는 것을 권장 (예: connection_timeout 5초, read_timeout 10초).

단기 개선 (1주 이내)#

• IntegrationRepository#refresh_token에서 토큰 갱신 소요 시간을 로깅하여 외부 API 응답 시간을 모니터링할 수 있도록 한다.
• 토큰이 만료 임박(10분)이 아닌, 만료 30분 전에 백그라운드로 갱신하는 proactive refresh를 고려한다. 이를 통해 사용자 요청 시점에 동기적 외부 호출을 피할 수 있다.

장기 개선 (재발 방지)#

• 토큰 갱신을 비동기 작업(Sidekiq job)으로 분리하여 사용자 요청의 latency에서 외부 API 의존성을 제거한다.
• Integration별 토큰 만료 시간을 추적하여, 장기간 미사용 integration의 토큰을 주기적으로 갱신하는 cron job을 도입한다.
• Circuit breaker 패턴을 적용하여 외부 OAuth 서버 장애 시 빠르게 실패하도록 한다.

Monitoring#

• Integration 토큰 갱신 latency 추적:

service:cupixworks-api "refresh token for" @duration:>1000ms

• access_token 엔드포인트 P95/P99 latency 알림 설정 (threshold: 2000ms)
• 토큰 만료 후 미갱신 시간이 1시간을 초과하는 integration 모니터링

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial
• 단발성 이벤트(1회 발생)이며, HTTP 200 정상 응답을 반환했다. 기능적 오류는 아니고 성능 이상이므로 위험도는 낮다. 단, timeout 미설정은 잠재적 장애 포인트이므로 개선이 바람직하다.