RCA: Api::V1::PowerBiReportsController#access_token slow trace (10.3s)

Overview#

What Happened#

2026-07-01 11:05 KST, cupixworks-api production(us-west-2, tenant cupix)에서 POST /api/v1/power_bi_reports/1/access_token 요청 1건이 10,293ms 동안 실행된 뒤 [403] Cupix::Errors::PermissionDenied (PERM34000)로 종료되었다. Pundit 권한 검사에서 즉시 거부되어야 할 요청이 10초를 소요한 것으로, 컨트롤러의 access_token 액션 본문이 아닌 그 앞단(before_action 체인 및 set_power_bi_report의 DB 조회)에서 시간이 소진되었다는 신호다. 발생 직전 동일 서비스에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 두 건이 관측되었고, 광범위한 svc:cupixworks-api::unknown 인시던트가 3분 전(11:02:16 KST) resolved 상태로 마감된 시점이라 MySQL 락 경합에 따른 잔여 latency 스파이크로 판단된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-01 10:43 KST — svc:cupixworks-api::unknown 서비스 저하 인시던트 시작 (incident id 2026-07-01-svc-cupixworks-api--unknown-1)
2. 2026-07-01 11:02:16 KST — 위 인시던트 resolved 마킹
3. 2026-07-01 11:04:27 KST — PanosController#check_uploading [502] ActiveRecord::LockWaitTimeout 발생
4. 2026-07-01 11:04:31 KST — PanosController#stitched [502] ActiveRecord::LockWaitTimeout 발생
5. 2026-07-01 11:05:19 KST — 슬로우 트레이스 시작 (POST /power_bi_reports/1/access_token, trace 1901029771432711949)
6. 2026-07-01 11:05:31 KST — 동일 요청 [403] PERM34000 로그 출력 (약 12초 후, 10.3s 요청 실행 + 로깅 지연)

Error Log#

Datadog Logs

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

동일 request의 로그 라인:

{
  "timestamp": "2026-07-01T02:05:31.447Z",
  "status": "info",
  "message": "[403] POST /api/v1/power_bi_reports/1/access_token (Api::V1::PowerBiReportsController#access_token)",
  "error": {
    "reason": "Only administrator can get power bi embedded token",
    "code": "PERM34000",
    "message": "Only administrator can get power bi embedded token",
    "class": "Cupix::Errors::PermissionDenied"
  }
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-01 11:05 KST
• 최근 발생: 2026-07-01 11:05 KST

Root Cause Summary#

PowerBiReportsController#access_token 요청이 10.3초를 소요하고 403으로 종료된 원인은, 액션 본문(repository_instance.generate_power_bi_embedded_token)이 아니라 그 앞단인 before_action :set_power_bi_report에서 실행하는 PowerBiReportRepository.show(params[:id])가 광범위한 permission_joins(팀 권한/그룹 권한/시스템 그룹 권한 3중 LEFT JOIN)를 포함한 MySQL 쿼리를 수행하기 때문이다. 발생 시점 직전 동일 API에서 ActiveRecord::LockWaitTimeout 두 건이 관측되었고, 광범위한 svc:cupixworks-api::unknown 서비스 저하 인시던트가 3분 전에 resolved 처리된 시점이라, DB 락 경합(또는 그 여파로 인한 pool/latency 스파이크)이 무거운 permission_joins 쿼리를 지연시켰다고 판단된다. 쿼리가 반환된 뒤 Pundit 검사가 즉시 실패해 403이 나갔지만, 총 응답 시간은 앞단 대기시간만큼 늘어난 상태였다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/power_bi_reports_controller.rb:39 — def access_token
• before_action :set_power_bi_report 가 액션 본문보다 먼저 실행되어 permission_joins 를 포함한 DB read 수행 (power_bi_reports_controller.rb:2, :46-48)
• 액션 본문 진입 후 첫 라인에서 Pundit 검사가 실패해 즉시 403 raise (power_bi_report_repository.rb:35)
• Failure point: 액션이 실패한 것이 아니라, set_power_bi_report 단계의 DB 쿼리가 지연되어 총 duration 이 10.3s로 늘어남

class Api::V1::PowerBiReportsController < Api::V1::ApiController
  before_action :set_power_bi_report, except: %i[index create]
  # ...
  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

  protected

  def set_power_bi_report
    @model = repository_instance.show(params[:id])
  end

generate_power_bi_embedded_token 의 첫 줄에서 Pundit 검사가 실패하면 나머지 코드(Azure Entra 토큰 발급, Power BI GenerateToken 호출)는 실행되지 않는다. 즉, 외부 HTTP 호출은 이 트레이스의 지연 원인이 될 수 없다.

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?

Pundit policy는 순수 in-memory 검사(팀 매핑/그룹 매핑)로, DB 조회 없이 반환된다:

class PowerBiReportPolicy < ApplicationPolicy
  def generate_access_token?
    return true if user.sales_team_of?(record)
    return true if user.member_of_groups?(%w[administrators super_admin])
    return true if user.member_of_admin_groups?(%w[administrator])

    # NSW tenant: allow access for team members of the report's team
    return true if Cupix::Tesla.tenant == 'nswgov' && user.team_id == record.team_id

    false
  end

set_power_bi_report이 호출하는 PowerBiReportRepository의 permission_joins는 3개의 서브쿼리(team_user_permissions, team_group_permissions, team_system_group_permissions)를 power_bi_reports와 LEFT JOIN 하며 GREATEST(...) 필터를 씌운다. team_permissions/grouped_users 대상 테이블에 락이 걸려 있으면 이 read 도 대기하게 된다:

record.joins("
  LEFT JOIN (
    SELECT team_id, permission
    FROM team_permissions
    WHERE team_permissions.accessor_id = #{sanitized_user_id}
      AND team_permissions.accessor_type = 'User'
    ) AS team_user_permissions
      ON team_user_permissions.team_id = power_bi_reports.team_id

  LEFT JOIN (
    SELECT team_id, permission
    FROM team_permissions
      LEFT JOIN grouped_users
        ON grouped_users.group_id = team_permissions.accessor_id
        AND grouped_users.user_id = #{sanitized_user_id}
    WHERE team_permissions.accessor_type = 'Group'
      AND grouped_users.user_id = #{sanitized_user_id}
    ) AS team_group_permissions
    ...

또한 Api::V1::ApiController의 before_action 체인(check_team_license, check_access_token_scope, check_session_scope, check_scope_in_header, set_updated_since 등)도 요청마다 실행되며, 상당수가 DB read를 유발한다:

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

Log Evidence#

사용 Datadog 쿼리:

service:cupixworks-api "access_token"

시간 범위: 2026-07-01T02:00:00Z ~ 2026-07-01T02:10:00Z

service:cupixworks-api ("timeout" OR "slow query" OR "ConnectionPool" OR "PoolExhausted")

시간 범위: 2026-07-01T02:00:00Z ~ 2026-07-01T02:10:00Z

슬로우 트레이스와 동일 요청의 완료 로그 (03:05:31 UTC ≈ 요청 시작 후 12초):

{
  "timestamp": "2026-07-01T02:05:31.447Z",
  "status": "info",
  "message": "[403] POST /api/v1/power_bi_reports/1/access_token (Api::V1::PowerBiReportsController#access_token)",
  "error": {
    "reason": "Only administrator can get power bi embedded token",
    "code": "PERM34000",
    "class": "Cupix::Errors::PermissionDenied"
  }
}

동시에 발생한 DB 락 경합 신호 — 슬로우 트레이스 48~52초 전:

{
  "timestamp": "2026-07-01T02:04:31.624Z",
  "status": "info",
  "message": "[502] PUT /api/v1/panos/90873095/stitched (Api::V1::PanosController#stitched)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

{
  "timestamp": "2026-07-01T02:04:27.301Z",
  "status": "info",
  "message": "[502] PUT /api/v1/panos/90883856/check_uploading (Api::V1::PanosController#check_uploading)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

최근 서비스 저하 인시던트 (status-board):

id: 2026-07-01-svc-cupixworks-api--unknown-1
scope: svc:cupixworks-api::unknown
started_at: 2026-07-01T01:43:01.612Z
resolved_at: 2026-07-01T02:02:16.858Z
cluster_ids: 5개

슬로우 트레이스는 이 인시던트가 resolved 처리된 지 약 3분 후 발생. 인시던트 마감 시점 이후에도 잔여 락/latency가 남아 있었을 개연성이 높다.

정상 시 동일 엔드포인트의 pacing (5분 주기 헬스체크성 호출):

2026-07-01T02:02:38.656Z [200] POST /api/v1/power_bi_reports/6/access_token
2026-07-01T02:07:38.949Z [200] POST /api/v1/power_bi_reports/6/access_token
2026-07-01T02:03:09.293Z [200] POST /api/v1/power_bi_reports/1/access_token
2026-07-01T02:03:49.210Z [200] POST /api/v1/power_bi_reports/1/access_token
2026-07-01T02:08:05.760Z [200] POST /api/v1/power_bi_reports/1/access_token

인접 200 요청들은 밀리초 단위로 완료되었고, 문제의 403 요청 1건만 10.3초를 소요했다.

Hypotheses Considered#

Confirmed (indirect) 이라는 verdict는, 개별 쿼리 실행시간을 담은 slow-query log를 확보하지 못해 직접적인 증거는 부재하나, 시간·서비스·전제조건(무거운 join + 락 경합 이벤트 공존)이 정확히 일치한다는 정황증거를 기반으로 함을 의미한다. 향후 재발 시 slow query 로그로 확증이 필요 — "uncertain -- needs direct slow-query log verification".

Fix Recommendation#

즉시 조치 (Critical)#

• 별도의 코드 수정 없음. 단발성 latency 이벤트(occurrence_count 1)이고, 광범위한 svc:cupixworks-api::unknown 인시던트의 tail 로 해석됨. 해당 인시던트는 이미 resolved 상태이므로 이 클러스터 단독으로는 추가 조치가 불필요.
• 2026-07-01-svc-cupixworks-api--unknown-1 인시던트의 5개 하위 클러스터 RCA 를 우선 확인하고, 그 근본 원인(락 소스)이 규명되면 이 트레이스도 동일 조치로 해소된다.

단기 개선 (1주 이내)#

• PowerBiReportRepository.permission_joins (app/repositories/power_bi_report_repository.rb:62-117) 쿼리 실행계획 검토. 3중 subquery LEFT JOIN + GREATEST(...) 필터가 team_permissions/grouped_users 상 락 경합에 취약할 수 있으므로, MVCC read 스냅샷을 명시적으로 활용하거나 subquery 대신 인덱스가 걸린 조인 컬럼(예: (accessor_id, accessor_type, team_id))이 존재하는지 확인.
• PowerBiReportsController#access_token 처럼 external API를 호출하는 액션에는 요청 상한 timeout(예: Rack::Timeout 5s)을 두어 10초 이상 hang 하지 않도록 상한을 걺.
• Pundit 권한 검사는 in-memory 이지만, 그 앞단 set_power_bi_report DB 조회 이후에야 검사가 수행되는 구조. 권한 미보유가 확실한 사용자에 대해서는 무거운 permission_joins 없이 우선 팀/그룹 소속만 확인해 401/403 을 조기 반환하는 fast-path 도입을 검토.

장기 개선 (재발 방지)#

• team_permissions, grouped_users, team_permissions.accessor_id 등에 걸리는 write-heavy 트랜잭션을 식별하고, 해당 write path 를 짧은 트랜잭션으로 분해하거나 락 순서를 일관화해 lock wait 감소.
• 서비스 저하 인시던트 종료 후 tail latency를 별도 지표로 관측(예: p99 duration by resource_name, alert threshold 5s+)해 이번 사례처럼 인시던트 종료 3분 후 발생하는 spike도 놓치지 않도록 함.

Monitoring#

• Datadog 쿼리 예시 (release dashboard timeseries widget 용):

Api::V1::PowerBiReportsController#access_token resource 의 p99 latency:

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::powerbireportscontroller#access_token}

PowerBiReportsController 전체 resource 의 요청 수:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::powerbireportscontroller#access_token}.as_rate()

DB lock timeout 발생 건수(광범위한 락 경합 조기 감지):

sum:trace.rack.request.errors{service:cupixworks-api,error_type:activerecord::lockwaittimeout}.as_count()

• Alert 제안: PowerBiReportsController#access_token p99 > 3s 지속 5분 이상 시 경고. ActiveRecord::LockWaitTimeout 5분 rolling sum > 5 시 경고.

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial (이 클러스터 단독) / standard (락 경합 근본 원인 조사 시)
• 단발성 요청 1건이 10.3s 지연으로 403 반환. 사용자 데이터 손상이나 잘못된 권한 부여는 없음. 광범위한 svc:cupixworks-api::unknown 인시던트의 tail 로 해석되므로 이 트레이스 단독 조치는 불필요.