RCA: Api::V1::ReviewsController#index latency (avg 32943ms, max 32943ms)

Overview#

What Happened#

2026-07-01 07:43 KST에 production us-west-2의 cupixworks-api에서 Api::V1::ReviewsController#index 요청 1건이 32.9초 동안 처리되었다. 5xx 에러는 아니지만 사용자 체감 응답 지연 수준이며, 같은 시각대(±10분)에 다른 latency 클러스터(CapturesController#resource_upload_url, ElementTracesController#refresh, ElementsController#index)가 함께 발생하여 status-board가 cupixworks-api service degraded 인시던트(2026-06-30-svc-cupixworks-api--unknown-1)로 묶었다. 요청은 admin team 소속 내부 사용자(jin.lee@cupix.com, user_id=16414)가 일으켰고, 권한 캐시가 admin 사용자에 한해 동작하지 않는 구조 때문에 권한 lookup이 매 호출마다 DB로 흘렀다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-01 07:35 KST — status-board가 cupixworks-api service degraded 인시던트(2026-06-30-svc-cupixworks-api--unknown-1) 오픈 (첫 latency cluster 3ce7061c…)
2. 2026-07-01 07:42:55 KST 부터 — user 16414의 directly_permitted_items / readable_facility_ids cache "Flushing" 로그가 2초 간격으로 계속 출력 (cache miss 반복)
3. 2026-07-01 07:43:08 KST — Api::V1::ReviewsController#index 호출 시작 (cluster 본건 first_seen)
4. 2026-07-01 07:43:43 KST — 32.9초 후 [200] GET /api/v1/reviews 응답
5. 2026-07-01 07:46:51 KST — 인시던트의 마지막 관련 cluster (0c05ab76…) 발생

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ReviewsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 32943,
  "max_ms": 32943,
  "sample_trace_id": "1381676408555254902"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-01 07:43 KST
• 최근 발생: 2026-07-01 07:43 KST
• 연관 인시던트: 2026-06-30-svc-cupixworks-api--unknown-1 (cupixworks-api service degraded — 5 clusters)

Root Cause Summary#

AccessibleEntities::Cache#cached_permission_timestamp 가 admin team 사용자에 대해 매 호출마다 SecureRandom.hex(10)을 반환한다. 이 timestamp는 _directly_permitted_item_ids, _readable_facility_ids 등 모든 권한 cache key 의 t: 필드에 들어가므로, admin 사용자에 한해 cache key가 매번 달라져 캐시가 사실상 비활성화된다. Api::V1::ReviewsController#index → ReviewRepository#_search 는 한 요청에서 current_user.readable_facility_ids 와 current_user.directly_accessible_review_ids 를 호출하고, 각 호출이 모두 DB에서 전체 권한 테이블을 join/pluck하는 무거운 SQL로 떨어진다. admin 사용자는 facility/review 가시 범위가 전 테넌트라서 결과 집합이 거대하고, 이어지는 Elasticsearch ::Review.search 도 매우 큰 terms 조건을 받게 되어 단일 요청이 32.9s까지 늘어났다.

Technical Analysis#

Code Path#

• Entry: app/controllers/api/v1/reviews_controller.rb:14-22 — index action
• Repository search: app/repositories/review_repository.rb:489-554 — _search
• Permission lookup #1 (facility): app/repositories/review_repository.rb:525
• Permission lookup #2 (review): app/repositories/review_repository.rb:530
• Cache key generator (failure point): app/models/concerns/accessible_entities/cache.rb:7
• Cache fetch wrappers: app/models/concerns/accessible_entities/cache.rb:19-33, cache.rb:50-63

def index
  review_query_option = Cupix::QueryOption::Review.new(get_query_option, params)
  reviews = repository_instance.search(review_query_option)

  render_api Renderable.new({
    search_result: reviews,
    is_collection: true,
    serializer_option: @serializer_option
  })
end

self.query_option.query[:bool][:must] += [
  {
    bool: {
      should: [
        {
          terms: {
            "facility.id": self.current_user.readable_facility_ids       # ← cache miss every call for admin
          }
        },
        {
          terms: {
            id: self.current_user.directly_accessible_review_ids         # ← cache miss every call for admin
          }
        }
      ]
    }
  }
]
# ...
response = ::Review.search(
  self.query_option.serializable_hash
).paginate(
  per_page: self.query_option.per_page,
  page: self.query_option.page
)

included do
  def cached_permission_timestamp
    return SecureRandom.hex(10) if admin_team?         # ← root cause: cache key randomized for admin users

    Rails.cache.fetch({ cached_permission: { user_id: id } }, expires_in: DEFAULT_PERMISSION_CACHE_EXPIRES_IN) do
      DateTime.now.to_i
    end
  end
  # ...
end

def _directly_permitted_item_ids(model, visibility = Cyclable.visibility[:UNTRASHED], min_permission: 1, max_permission: MAX_PERMISSION)
  Rails.cache.fetch({
    cached_permission: {
      user_id: id,
      model: model.try(:name),
      min_permission: min_permission,
      max_permission: max_permission,
      t: cached_permission_timestamp                   # ← random for admin → key never collides → block always runs
    }
  }, expires_in: DEFAULT_PERMISSION_CACHE_EXPIRES_IN) do
    Cupix::Logger.info("Flushing directly_permitted_items on user #{id}, model: #{model}, min_permission: #{min_permission}}", ...)

    directly_permitted_items(model, visibility, min_permission: min_permission, max_permission: max_permission).pluck(:id).uniq
  end
end

기대 동작: Rails.cache.fetch 가 같은 cache key 에 대해 결과를 재사용하여, 같은 사용자/모델 조합의 권한 lookup 이 짧은 시간 내 반복 호출되면 단 한 번만 DB로 떨어진다.

실제 동작: admin team 사용자의 cached_permission_timestamp 가 매번 새 random hex 를 반환하므로 cache key 의 t: 가 매번 달라져, Rails.cache.fetch 의 inner block 이 매 호출마다 실행된다. 같은 한 요청 내에서도 권한 lookup 이 여러 번 일어나는 컨트롤러(ReviewsController#index, ElementsController#index 등) 는 매번 전체 권한 join SQL 을 다시 실행한다.

Log Evidence#

Datadog query:

service:cupixworks-api "user 16414"

시간 범위 2026-06-30T22:30:00Z ~ 2026-06-30T22:50:00Z. 같은 user_id(16414, admin team jin.lee@cupix.com) 에 대해 cache miss 로그(Flushing …) 가 짧은 간격으로 반복:

2026-07-01 07:43:43  info  [200] GET /api/v1/reviews (Api::V1::ReviewsController#index)
2026-07-01 07:43:39  info  Flushing directly_permitted_items on user 16414, model: Review, min_permission: 1
2026-07-01 07:43:11  info  Flushing directly_permitted_items on user 16414, model: Facility, min_permission: 2
2026-07-01 07:43:11  info  Flushing readable_facility_ids on user 16414
2026-07-01 07:43:13  info  Flushing readable_facility_ids on user 16414
2026-07-01 07:43:13  info  Flushing directly_permitted_items on user 16414, model: Facility, min_permission: 2
2026-07-01 07:43:17  info  Flushing directly_permitted_items on user 16414, model: Record, min_permission: 1
2026-07-01 07:43:19  info  Flushing directly_permitted_items on user 16414, model: Facility, min_permission: 1
2026-07-01 07:43:35  info  Flushing readable_facility_ids on user 16414
2026-07-01 07:43:35  info  Flushing directly_permitted_items on user 16414, model: Facility, min_permission: 2
2026-07-01 07:43:45  info  Flushing readable_facility_ids on user 16414
2026-07-01 07:43:45  info  Flushing directly_permitted_items on user 16414, model: Facility, min_permission: 2
2026-07-01 07:43:53  info  Flushing directly_permitted_items on user 16414, model: Review, min_permission: 1

같은 (user_id=16414, model=Facility, min_permission=2) 조합에서 Flushing readable_facility_ids 가 07:43:11, 07:43:13, 07:43:35, 07:43:45 에 반복 출력 — 캐시가 동작했다면 첫 호출만 출력되어야 한다. user/model 키가 동일한데 매번 inner block 이 실행됨이 곧 root cause 의 직접 증거다.

Datadog query for trace:

service:cupixworks-api trace_id:1381676408555254902

trace 의 끝 응답 로그 (32.9s 후 200 OK):

2026-07-01 07:43:43  info  [200] GET /api/v1/reviews (Api::V1::ReviewsController#index)
2026-07-01 07:43:39  info  Flushing directly_permitted_items on user 16414, model: Review, min_permission: 1
2026-07-01 07:43:11  info  Flushing directly_permitted_items on user 16414, model: Facility, min_permission: 2
2026-07-01 07:43:11  info  Flushing readable_facility_ids on user 16414

같은 trace 안에서 _readable_facility_ids (line 525 경로) 와 _directly_permitted_item_ids(Review, ...) (line 530 경로) 가 모두 cache miss 로 흘러 두 번의 무거운 권한 join SQL 이 발생한 것이 확인된다.

같은 시간대 다른 latency cluster (인시던트 동반 발생):

모두 권한 lookup 을 거치는 list/refresh 류 endpoint 라는 공통점이 있다 (ElementsController#index 등도 동일 cache 경로 사용 — uncertain, separate RCA에서 검증 필요).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 파일: app/models/concerns/accessible_entities/cache.rb:7
• 변경 방향: admin team 사용자에 대해 cache key 를 randomize 하지 않도록 한다. admin 의 권한이 변경될 때 명시적으로 invalidation 하는 경로(flush_cached_permission / delete_cached_permission_timestamp 가 이미 존재) 를 사용하면 일반 사용자와 동일한 캐시 동작을 가질 수 있다. randomize 가 도입된 의도(예: admin 의 권한이 너무 자주 바뀌어 stale cache 위험) 가 있다면, 그 의도를 만족하는 다른 메커니즘(예: admin 그룹 권한 변경 시 명시적 cache bust hook)으로 대체해야 한다. 변경 전에 git blame 으로 도입 commit 의 PR/이슈를 확인하여 의도 검증 필요 (uncertain — needs verification).
• 단기 완화책 (코드 변경이 위험할 경우): admin 사용자에 한해서 directly_permitted_items 자체를 query 단순화 (admin 은 모든 facility 접근 가능 → DB 조회 대신 Facility.untrashed.pluck(:id) 같은 단순 path 또는 terms 조건 자체를 생략) 하도록 ReviewRepository#_search 분기 추가.

단기 개선 (1주 이내)#

• app/repositories/review_repository.rb:519-536: admin/super_admin 사용자의 경우 terms: { "facility.id": [...] } terms: { id: [...] } 조건을 통째로 생략하고 ES 측에서도 match_all 같이 가볍게 처리하도록 분기. 거대한 ID 배열을 ES에 보내는 것 자체가 ES side cost 도 키운다.
• _directly_permitted_item_ids 등 cache wrapper 가 같은 process / 같은 request 안에서 동일 키를 여러 번 부르는 경우, in-memory memoization 한 layer 추가 (@_permission_memo). admin 사용자에서도 한 요청 내에선 안정적인 응답시간 확보.

장기 개선 (재발 방지)#

• 권한 lookup 의 비용을 APM custom span 으로 측정하여 단일 요청에서 동일 사용자/모델 조합 cache miss 가 N회 이상이면 warn 발생. 회귀를 metric 으로 감지.
• admin team 사용자의 권한 모델을 “전체 접근”으로 short-circuit 하는 명시적 경로를 모델 레벨에 두고, 각 repository 가 이 경로를 사용하도록 통일. 컨트롤러/repository 마다 분기를 분산시키지 않는다.

Monitoring#

권한 cache miss 가 admin 사용자에서 폭발하는지 확인하는 dashboard timeseries widget. 모두 count aggregator 사용.

권한 cache miss 빈도:

logs("service:cupixworks-api @class:User @function:_directly_permitted_item_ids").index("*").rollup("count", "60").by("@user.id")

ReviewsController#index p95 latency:

trace.rails.request.duration{service:cupixworks-api,resource_name:Api::V1::ReviewsController#index}.rollup(avg, 60).as_count()

cupixworks-api 전반 latency p95:

trace.rails.request.duration{service:cupixworks-api}.rollup(percentile, 60, 95)

(Datadog metric name 은 실제 환경 metric 명세 확인 필요 — trace.rails.request.duration 가 우리 환경 metric 명과 일치하는지 검증 후 dashboard 에 반영 — uncertain.)

알림 가이드:

• 단일 admin user_id 에서 _directly_permitted_item_ids cache miss 가 30s 안에 10회 이상 발생하면 warn.
• Api::V1::ReviewsController#index p95 가 5s 초과 시 page.

Risk Assessment#

• Risk level: medium — admin 사용자만 영향을 받지만 내부 운영/CS 흐름을 차단할 수 있고, 동시에 다른 endpoint(ElementsController, ElementTracesController, CapturesController)도 같은 root cause로 함께 느려진다.
• 예상 복잡도: standard — 한 줄(cache.rb:7) 변경이지만 admin 권한 변경 시 cache invalidation 경로가 적절히 동작하는지 검증이 필요. 도입 의도(PR/commit)를 먼저 확인 후 변경 권장.