Api::V1::PowerBiReportsController#access_token (avg 1252ms, max 1252ms)

RCA: PowerBiReportsController#access_token Latency (1252ms)

Overview#

What Happened#

2026-05-27 08:05 UTC에 ap-southeast-2 리전의 cupixworks-api 서비스에서 Api::V1::PowerBiReportsController#access_token 엔드포인트가 1252ms의 응답 시간을 기록했다. 이는 500ms 임계값을 초과하는 latency 이벤트로, 외부 Azure API 호출 시 캐시 미스가 발생하여 두 건의 순차적 HTTP 요청이 실행된 것이 원인이다.

Quick Facts#

Field	Value
resource_name	`Api::V1::PowerBiReportsController#access_token`
top_frame	`lib/cupix/azure/power_bi.rb:10-27`
env	production, ap-southeast-2
avg_duration_ms	1252
sample_trace_id	`4579988412196655535`

Timeline#

2026-05-27T08:05:33Z — Latency 이벤트 발생 (1252ms)
2026-05-27T08:05:33Z — Error sweeper에 의해 감지

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::PowerBiReportsController#access_token",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1252,
  "max_ms": 1252,
  "sample_trace_id": "4579988412196655535"
}

Impact#

Service: cupixworks-api
발생 횟수: 1
최초 발생: 2026-05-27T08:05:33.735Z
최근 발생: 2026-05-27T08:05:33.735Z

사용자 영향은 제한적이다. Power BI 임베디드 토큰 요청 시 1.2초의 응답 지연이 발생하나, 요청 자체는 성공(HTTP 200)했으며 기능적 장애는 없다. 캐시가 유효한 동안(40분)에는 정상 응답 속도를 보인다.

Root Cause Summary#

access_token 엔드포인트는 두 개의 외부 HTTP 호출을 순차적으로 수행한다: (1) Azure Entra OAuth2 토큰 발급(login.microsoftonline.com), (2) Power BI 임베디드 토큰 생성(api.powerbi.com). 두 호출 모두 Rails.cache.fetch로 40분 TTL 캐싱되어 있으나, 캐시 만료 시 ap-southeast-2 리전에서 Azure/Power BI API 엔드포인트(미국/유럽 소재)까지의 네트워크 왕복 시간이 누적되어 1252ms의 latency가 발생한다. 이는 cache miss가 발생하는 주기적 현상이며, 에러가 아닌 정상적인 외부 API 호출 비용이다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/power_bi_reports_controller.rb:39
before_action set_power_bi_report (line 46): DB에서 PowerBiReport 모델 로드
repository_instance.generate_power_bi_embedded_token(params): 권한 검증 후 토큰 생성 시작
Azure Entra 토큰 요청: lib/cupix/azure/power_bi.rb:10-27
Power BI embed 토큰 요청: lib/cupix/azure/power_bi.rb:36-71
응답 반환: controller.rb:41

app/controllers/api/v1/power_bi_reports_controller.rb:39-42ruby

def access_token
  power_bi_token = repository_instance.generate_power_bi_embedded_token(params)
  render_json 200, { token: power_bi_token['token'], expiration: power_bi_token['expiration'] }
end

app/repositories/power_bi_report_repository.rb:34-55ruby

def generate_power_bi_embedded_token(params)
  raise Cupix::Errors::PermissionDenied.new(code: 'PERM34000', reason: 'Only administrator can get power bi embedded token') unless Pundit.policy(current_user, self.model).generate_access_token?
  raise Cupix::Errors::Unauthorized.new(code: 'AUTH20019', reason: 'Allowed Power BI report not found from team', message: 'Power BI report not found or unauthorized access') if @model.nil?
  raise Cupix::Errors::Unauthorized.new(code: 'AUTH20020', reason: 'Disabled Power BI report from team', message: 'enabled Power BI report not found') if @model.disabled?
  raise Cupix::Errors::Unauthorized.new(code: 'AUTH20022', reason: 'Invalid team Power BI configuration', message: 'Team does not have valid Power BI workspace configuration') unless @model.team.power_bi_workspace_id.present? && @model.team.infosphere_builtin_enabled_at.present?

  azure_entra_access_token = ::Cupix::Azure::PowerBi.get_azure_entra_access_token

  timezone_offset = params[:timezone_offset]

  access_token = ::Cupix::Azure::PowerBi.generate_power_bi_embedded_token(
    @model.power_bi_report_id,
    @model.dataset_id,
    azure_entra_access_token,
    @model.team.id,
    roles: ['TeamFilter'],
    custom_data: timezone_offset
  )

  @model.track_to_generate_infosphere_access_token(current_user)

  access_token
end

첫 번째 외부 호출 — Azure Entra 토큰 (cache miss 시):

lib/cupix/azure/power_bi.rb:10-27ruby

def get_azure_entra_access_token
  Rails.cache.fetch('azure_entra_token', expires_in: CACHE_EXPIRATION_TIME) do
    uri = URI("https://login.microsoftonline.com/#{$AZURE[:entra][:power_bi_embedded_tenant_id]}/oauth2/v2.0/token")

    response = Cupix::HttpClient.post(
      uri.to_s,
      URI.encode_www_form({
        'grant_type' => 'client_credentials',
        'client_id' => $AZURE[:entra][:power_bi_embedded_client_id],
        'client_secret' => $AZURE[:entra][:power_bi_embedded_client_secret],
        'scope' => 'https://analysis.windows.net/powerbi/api/.default'
      }),
      { content_type: 'application/x-www-form-urlencoded' }
    )

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

두 번째 외부 호출 — Power BI embed 토큰 (cache miss 시):

lib/cupix/azure/power_bi.rb:36-64ruby

def generate_power_bi_embedded_token(power_bi_report_id, power_bi_dataset_id, access_token, username, roles: [], custom_data: nil)
  cache_key = "power_bi_embed_token_#{power_bi_report_id}_#{power_bi_dataset_id}_#{username}_#{custom_data}"

  Rails.cache.fetch(cache_key, expires_in: CACHE_EXPIRATION_TIME) do
    identity = {
      username: username,
      roles: roles,
      datasets: [power_bi_dataset_id]
    }
    identity[:customData] = custom_data if custom_data.present?

    body = {
      datasets: [{ id: power_bi_dataset_id }],
      reports: [{ allowEdit: true, id: power_bi_report_id }],
      identities: [identity]
    }

    response = Cupix::HttpClient.post(
      'https://api.powerbi.com/v1.0/myorg/GenerateToken',
      body.to_json,
      {
        'Authorization' => "Bearer #{access_token}",
        'Content-Type' => 'application/json'
      }
    )

    result = JSON.parse(response.body)
    result
  end
end

HttpClient.post는 429/502/503/504 응답 시 최대 3회 재시도하며 exponential backoff(1s, 2s, 4s)을 적용한다:

lib/cupix/http_client.rb:34-46ruby

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에서 PowerBiReportsController#access_token 엔드포인트의 활동을 확인했다. 이 엔드포인트는 정상적으로 200 응답을 반환하고 있으며, 에러 발생 이력은 별도의 조건(JWT 만료, DB OOM)에서만 나타난다.

사용한 쿼리:

text

service:cupixworks-api "PowerBiReportsController"

정상 응답 패턴 (5분 간격 호출, 모두 HTTP 200):

json

{"timestamp": "2026-05-27 19:36:40", "status": "info", "message": "[200] POST /api/v1/power_bi_reports/20/access_token (Api::V1::PowerBiReportsController#access_token)"}
{"timestamp": "2026-05-27 19:35:34", "status": "info", "message": "[200] POST /api/v1/power_bi_reports/20/access_token (Api::V1::PowerBiReportsController#access_token)"}
{"timestamp": "2026-05-27 19:33:26", "status": "info", "message": "[200] POST /api/v1/power_bi_reports/17/access_token (Api::V1::PowerBiReportsController#access_token)"}

에러 응답 이력 (별도 원인, 본 latency 이슈와 무관):

text

service:cupixworks-api "PowerBiReportsController" @http.status_code:>299

json

{"timestamp": "2026-05-26 23:03:01", "status": "info", "message": "[500] POST /api/v1/power_bi_reports/1/access_token", "error": ["ActiveRecord::StatementInvalid", "Mysql2::Error: Out of memory"]}
{"timestamp": "2026-05-20 14:37:13", "status": "info", "message": "[503] POST /api/v1/power_bi_reports/1/access_token", "error": {"message": "Can't connect to MySQL server on 'db-tesla.cupix.internal' (115)", "class": "ActiveRecord::ConnectionNotEstablished"}}

Datadog APM(트레이스)에서 본 latency는 캐시 미스 시 외부 API 호출 시간에 해당한다. ap-southeast-2(시드니)에서 Azure 엔드포인트까지의 round-trip latency가 ~400-600ms 수준이며, 두 번의 순차 호출이 합산된 결과이다.

AUTH20023/AUTH20024 에러 코드로 검색한 결과 최근 14일간 해당 에러는 발생하지 않았다 — 외부 API 호출 자체는 성공하고 있으며, 순수하게 네트워크 latency만이 문제이다.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	Cache miss 시 외부 Azure API 호출 2건의 순차적 네트워크 latency 누적	코드에서 `Rails.cache.fetch` 40분 TTL 확인 (`power_bi.rb:8,11,39`). 두 호출이 순차적. ap-southeast-2에서 Azure 엔드포인트까지 왕복 400-600ms 예상. 1252ms = ~600ms x 2 + DB/auth 오버헤드	—	Confirmed
H2	HttpClient 재시도로 인한 추가 지연	`http_client.rb:17-20`에서 429/502/503/504 시 retry + exponential backoff 구현됨	AUTH20023/AUTH20024 에러가 14일간 0건 — Azure API가 에러 응답 없이 정상 처리됨. retry가 발동했다면 최소 2초 이상 소요될 것이나 1252ms는 단순 왕복 시간에 부합	Rejected
H3	DB 쿼리 또는 before_action 지연	`set_power_bi_report`에서 DB 조회. 2026-05-26에 MySQL OOM 에러 존재	해당 트레이스 시점(08:05)에 DB 에러 없음. OOM은 전날(23:03) 발생. 정상 DB 조회는 수 ms 수준	Rejected

Fix Recommendation#

즉시 조치 (Critical)#

조치 불필요. 1252ms latency는 cache miss 시 발생하는 정상적인 외부 API 호출 비용이며, 발생 빈도도 1건으로 사용자 영향이 극히 제한적이다.
이 이벤트는 에러가 아닌 latency 클러스터이며, 기능적 장애 없이 정상 완료(200)되었다.

단기 개선 (1주 이내)#

Latency threshold 재검토: 500ms 임계값이 외부 API 호출을 포함하는 엔드포인트에 적절한지 평가. Power BI 토큰 엔드포인트는 특성상 cache miss 시 1-2초가 정상 범위이므로, 이 resource_name에 대해 임계값을 2000ms로 상향하는 것을 고려.
캐시 TTL 조정 검토: 현재 40분 TTL을 Power BI embed 토큰의 실제 만료 시간(일반적으로 1시간)에 맞춰 55분으로 늘려 cache miss 빈도를 줄일 수 있다.

장기 개선 (재발 방지)#

Cache warming: 주기적으로(30분 마다) Azure Entra 토큰을 백그라운드 job에서 미리 갱신하여 사용자 요청 시 cache miss를 방지.
비동기 토큰 갱신: 캐시 만료 직전에 background에서 토큰을 갱신하는 "stale-while-revalidate" 패턴 도입.
리전별 latency 모니터링: ap-southeast-2에서 Azure 엔드포인트까지의 latency를 별도 메트릭으로 추적.

Monitoring#

Power BI 토큰 엔드포인트 P95 latency 추적:

text

avg:trace.rails.request.duration{service:cupixworks-api,resource_name:api::v1::powerbi_reports_controller_access_token} by {region}

Cache hit/miss ratio 모니터링:

text

sum:rails.cache.hit{cache_key:azure_entra_token OR cache_key:power_bi_embed_token*}.as_rate()

Risk Assessment#

Risk level: low
예상 복잡도: trivial
이 latency 이벤트는 정상적인 cache miss 동작이며, 사용자에게 기능적 영향을 주지 않는다. 발생 빈도(1건)와 성공 응답(200)을 고려할 때 즉각적인 코드 변경은 불필요하다.