RCA: Api::V1::WorkspacesController#index 응답 지연 (154s)

Overview#

What Happened#

2026-06-26 10:51 KST에 cupixworks-api 서비스의 Api::V1::WorkspacesController#index 요청 한 건이 약 154초 동안 실행된 뒤 200 OK로 응답했다. APM 기준 평균/최대 모두 154,198 ms로 동일한 단일 trace(698881000166015777)에서 발생했다. tenant는 cupix, region은 ap-southeast-2 (Sydney)이며, 같은 시간대에 cupixworks-api 서비스 전체에서 svc:cupixworks-api::unknown 인시던트로 7개 cluster가 묶일 정도로 도메인 전반의 지연·오류가 관측됐다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-26 10:25 KST — svc:cupixworks-api::unknown 인시던트 시작 (status-board, 7-cluster window 최초 cluster).
2. 2026-06-26 10:53:18 KST 추정 — 본 cluster 대상 요청 시작 (APM duration 154,198 ms 역산).
3. 2026-06-26 10:55:16 KST — UserFactory#update_user_groups! "No custom groups found for user 343" 로그 출력 (controller가 권한 캐시 빌드 단계 진입).
4. 2026-06-26 10:55:16 KST — User#_directly_permitted_item_ids "Flushing directly_permitted_items on user 343, model: Team, min_permission: 2".
5. 2026-06-26 10:55:17 KST — 동일 함수 "Flushing directly_permitted_items on user 343, model: Workspace, min_permission: 1".
6. 2026-06-26 10:55:52 KST — [200] GET /api/v1/workspaces (Api::V1::WorkspacesController#index) 응답 (cluster last_seen = 2026-06-26 10:51:49 KST 기준 약 154s 경과).
7. 2026-06-26 10:53 KST — svc:cupixworks-api::unknown 인시던트 해소.

Error Log#

Datadog Logs

resource_name: Api::V1::WorkspacesController#index
service:       cupixworks-api
sample_trace_id: 698881000166015777
avg_ms:  154198
max_ms:  154198
occurrences: 1

본 cluster는 latency cluster이며 status는 200 OK다. exception/스택 트레이스 없이 응답 시간만 비정상적으로 길었다.

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-26 10:51 KST
• 최근 발생: 2026-06-26 10:51 KST
• 사용자 영향: 단일 trace이지만 154초 동안 단일 워커가 점유됨 — Puma/Unicorn 같은 thread/process pool 환경에서는 동시간대 다른 요청 대기열을 늘려 큰 폭으로 영향이 확산될 수 있음. 동일 시간대 svc:cupixworks-api::unknown 인시던트가 함께 열려 있었던 점이 그 신호.

Root Cause Summary#

Api::V1::WorkspacesController#index가 호출한 WorkspaceRepository#_search는 (1) Rails.cache(redis) 기반 권한 캐시(_directly_permitted_item_ids)를 통해 current_user.readable_team_ids와 current_user.directly_accessible_workspace_ids를 계산한 뒤, (2) Elasticsearch(::Workspace.search)에 질의한다. trace 698881000166015777의 내부 info 로그가 (1) 단계의 cache miss/flush 시점부터만 보이고 그 시점이 응답 직전 35초인 점, 그리고 동일 시간대에 svc:cupixworks-api::unknown 인시던트(7 cluster, 28분간 지속)가 열려 있던 점을 종합하면, 154초 중 대부분(~120초)은 controller 진입 이후 첫 internal log가 찍히기 전 — 즉 컨트롤러 초기화 단계(인증, 권한 캐시 lookup, Rails.cache/Redis I/O, 또는 외부 의존성 대기)에서 소진된 것으로 추정된다. 이 cluster 자체에 단일 결정적 코드 결함이 있다기보다는, 광역 service degradation 상황에서 일부 사용자의 권한 캐시 빌드 경로가 가장 오래 막혀 있다가 결국 200으로 빠져나간 사례로 본다. 외부 dependency outage(dep:*)는 status-board에 잡히지 않았으므로 외부 outage로 단정하지 않는다 — uncertain -- needs verification.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/workspaces_controller.rb:11 (#index)
• Repository search: app/repositories/workspace_repository.rb:187 (_search)
• 권한 캐시 build: app/models/concerns/accessible_entities/cache.rb:19 (_directly_permitted_item_ids)
• Permission expensive query: app/models/concerns/accessible_entities/directly_permitted_items.rb:5 (directly_permitted_items)
• 실제 검색: Workspace.search(...) (Elasticsearch, _search 내부 line 209)

def index
  workspaces = repository_instance.search(
    Cupix::QueryOption::Workspace.new(get_query_option, params)
  )
  render_api Renderable.new({
    search_result: workspaces,
    is_collection: true,
    serializer_option: @serializer_option
  })
end

def _search(query_option = nil)
  set_query_option(query_option)

  self.query_option.query[:bool][:must] += [
    {
      bool: {
        should: [
          {
            terms: {
              "team.id": self.current_user.readable_team_ids
            }
          },
          {
            terms: {
              id: self.current_user.directly_accessible_workspace_ids
            }
          }
        ]
      }
    }
  ]

  response = ::Workspace.search(
    self.query_option.serializable_hash
  ).paginate(
    per_page: self.query_option.per_page,
    page: self.query_option.page
  )

  set_response(response)
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
    }
  }, expires_in: DEFAULT_PERMISSION_CACHE_EXPIRES_IN) do
    Cupix::Logger.info("Flushing directly_permitted_items on user #{id}, model: #{model}, min_permission: #{min_permission}}", class: self.class.name, function: __method__, module: 'AccessibleEntities::Cache', user: { id: id })

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

기대 동작: Rails.cache hit이면 즉시 ID 리스트 반환. miss면 directly_permitted_items로 RDB 쿼리(joins/distinct)를 수행한 뒤 캐시에 저장 — 일반적으로 수십 ms~수백 ms.

실제 동작: trace 698881000166015777에서는 (a) controller 진입 후 첫 internal info log(UserFactory#update_user_groups! 10:55:16)까지 약 ~118초 공백, (b) 그 이후 cache flush → ES 검색 → 200 응답까지 약 36초. 첫 internal log 이전 구간이 정확히 어디서 소진됐는지를 보여주는 info 로그는 retention에 남아있지 않다 — uncertain -- needs verification.

Log Evidence#

Datadog query (재현 가능):

service:cupixworks-api trace_id:698881000166015777

응답한 4건의 로그 (info 레벨만 보존됨):

{
  "timestamp": "2026-06-26 10:55:52 KST",
  "status": "info",
  "message": "[200] GET /api/v1/workspaces (Api::V1::WorkspacesController#index)"
}

{
  "timestamp": "2026-06-26 10:55:17 KST",
  "status": "info",
  "message": "Flushing directly_permitted_items on user 343, model: Workspace, min_permission: 1}",
  "class": "User",
  "function": "_directly_permitted_item_ids"
}

{
  "timestamp": "2026-06-26 10:55:16 KST",
  "status": "info",
  "message": "Flushing directly_permitted_items on user 343, model: Team, min_permission: 2}",
  "class": "User",
  "function": "_directly_permitted_item_ids"
}

{
  "timestamp": "2026-06-26 10:55:16 KST",
  "status": "info",
  "message": "No custom groups found for user 343, liam.hong@cupix.com",
  "class": "UserFactory",
  "function": "update_user_groups!"
}

Status board (bun run cli/incident-board.ts for-cluster 48253066-26c7-486f-8ec7-2d4bb0e4a86e) 결과:

{
  "scope": "svc:cupixworks-api::unknown",
  "active": null,
  "recent": [
    {
      "id": "2026-06-26-svc-cupixworks-api--unknown-1",
      "title": "cupixworks-api service degraded",
      "started_at": "2026-06-26T01:25:34.396Z",
      "resolved_at": "2026-06-26T01:53:30.528Z",
      "cluster_ids": [
        "943fdcb4-...", "66924c5b-...", "2e4071f3-...",
        "48253066-26c7-486f-8ec7-2d4bb0e4a86e",
        "d22ba254-...", "b61f8f39-...", "fa2be8d1-..."
      ]
    }
  ]
}

본 cluster는 svc:cupixworks-api::unknown 인시던트의 7개 cluster 중 하나로 등록되어 있다. 같은 시간대 다른 cluster들과 묶여서 광역 degradation 신호를 형성한다.

같은 시간대(2026-06-26 10:54–10:55 KST)에 외부 의존성 관련 오류로 OPC Oracle Integration API 409 Conflict(Service Instance has been stopped)가 반복 발생하고 있었으나, 이는 Api::V1::IntegrationsController#access_token 경로(integration(1849))에 한정된 별도 시스템이며 WorkspacesController#index 코드 경로와는 무관하다 — 동일 시간대의 광역 부하 신호로만 참고.

{
  "timestamp": "2026-06-26 10:55:36 KST",
  "status": "error",
  "message": "[OpcOperation] Failed to get OPC API access token: ... 409 Conflict ... Service Instance has been stopped",
  "class": "OpcOperation",
  "function": "get_opc_api_access_token"
}

trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::WorkspacesController#index} 메트릭 시계열은 24h/2h 모두 빈 응답 — 해당 resource tag가 timeseries로 노출되지 않거나 권한/태그 매칭 이슈로 추정 (uncertain -- needs verification). 따라서 baseline p50/p99 latency는 본 RCA에서 정량 비교하지 못했다.

Hypotheses Considered#

H1을 confirmed(광역 degradation 신호와 정렬)로, H2/H3을 후속 검증 대상(inconclusive)으로 본다.

Fix Recommendation#

즉시 조치 (Critical)#

• 별도 코드 수정은 권장하지 않는다. 본 cluster는 svc:cupixworks-api::unknown 인시던트의 한 구성원이며 단일 trace(1회)다. 단독 fix를 위한 코드 변경 근거가 약하다 — 인시던트 전반의 root cause 확정이 선행되어야 한다.
• 동일 시간대(2026-06-26 10:25–10:53 KST) 묶인 다른 6개 cluster의 RCA(특히 동일 인시던트의 같은 윈도우에 묶인 5xx cluster들)와 교차 확인 필요. status-board의 cluster_ids 7개를 한 번에 비교.

단기 개선 (1주 이내)#

• APM custom span을 controller 초기에 삽입 — app/controllers/api/v1/workspaces_controller.rb:11에 진입한 직후, 그리고 repository_instance.search 호출 직전 두 지점에 명시적 span/info 로그를 추가하면, 154초 중 어느 구간(인증, before_action chain, set_serializer_option, repository init, ES round-trip)에서 시간을 소진했는지 확인할 수 있다. 현재 가장 이른 internal 로그가 UserFactory#update_user_groups!이므로 그 이전 구간이 블랙박스다.
• WorkspaceRepository#_search의 terms 절 크기 가드 — workspace_repository.rb:200-203에서 current_user.directly_accessible_workspace_ids가 일정 크기(예: 1만 개)를 초과하면 별도 strategy(예: ES 측 lookup, RDB pre-filter)로 분기하는 방향을 검토. 본 사례 직접 증거는 아니지만 H2 가설 차단 목적.
• _directly_permitted_item_ids의 캐시 stampede 방어 — cache.rb:19-33의 Rails.cache.fetch에 race_condition_ttl 옵션 또는 distributed lock을 도입해 동일 user의 동시 cache miss가 RDB 쿼리를 중복 수행하지 않도록 한다 (H3 가설 대응).

장기 개선 (재발 방지)#

• API 요청 단위 timeout(Rack middleware) 설정 — 154초 동안 단일 worker가 점유되어 다른 요청 대기열을 늘리는 구조 개선. Puma worker timeout과 별도로, controller 레벨에서 30–60s SLO 초과 시 503으로 빠르게 fail-fast.
• status-board의 svc:*::unknown scope를 root_cause_type별로 세분화 — 같은 인시던트에 묶인 7 cluster의 fingerprint가 다양해서 "unknown"으로 묶였다. 인시던트 단위 자동 분류 정확도를 높이면 본 같은 단일 trace cluster도 더 빠르게 광역 신호와 연결된다.

Monitoring#

본 RCA에서 사용된 트레이스/메트릭 식별자 기반 Datadog 쿼리. release dashboard timeseries widget에 그대로 사용 가능한 형태.

sum:trace.rack.request.duration.by.resource_service.hits{service:cupixworks-api,resource_name:api::v1::workspacescontroller#index} by {env}.as_count()

max:trace.rack.request.duration.by.resource_service{service:cupixworks-api,resource_name:api::v1::workspacescontroller#index} by {env}

p95:trace.rack.request.duration.by.resource_service{service:cupixworks-api,resource_name:api::v1::workspacescontroller#index} by {env}

추가 알림 (Datadog Monitor)로 권장:

• Api::V1::WorkspacesController#index p95 > 5s (5분 윈도우, env:production) — 정상치 대비 광역 신호 감지.
• 동일 service의 30초 초과 trace(@duration:>30000000000 nanosecond)가 5분에 3건 이상 — 광역 degradation 조기 경보.
• Rails.cache(Redis)의 cache_set_time, cache_get_time 분포 추적 — 권한 캐시 stampede 시그널.

Risk Assessment#

• Risk level: low (현시점) — 단일 trace, 200 OK, 동일 인시던트는 이미 자동 resolved.
• 재발 위험: medium — svc:cupixworks-api::unknown 인시던트가 최근 7일 내 4회 발생(2026-06-24 2건, 2026-06-25 1건, 2026-06-26 1건). 같은 도메인의 광역 degradation이 주기적으로 반복되고 있으며 그 신호 중 하나로 본 cluster가 잡혔다.
• 예상 복잡도: standard — 본 cluster 단독 fix는 부적절하다. 동일 인시던트 윈도우 다른 cluster들과 합쳐 root cause를 좁힌 뒤(예: ES backpressure, Redis latency, DB slow query 중 무엇이었는지) 그 layer에 맞는 fix를 진행하는 것이 옳다.