RCA: Api::V1::FacilitiesController#share latency (avg 33s, max 83s)

Overview#

What Happened#

2026-06-24 KST 오후 시간대에 PUT /api/v1/facilities/:key/share 요청이 cupixworks-api에서 평균 33초, 최대 83초까지 지연되었다. 단일 요청에서 다수의 사용자(exyte 팀 사례: 약 127명)를 한 번에 공유 대상으로 추가했고, 각 사용자마다 notification-service로 동기 HTTP 호출이 직렬로 발생하면서 응답 시간이 사용자 수에 비례해 선형으로 증가했다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-24 19:23 KST — 클러스터 first_seen. APM 상 share 요청 평균 지연 임계치 초과 시작 (first_seen: 2026-06-24T10:23:45.444Z).
2. 2026-06-24 19:25:09 KST — exyte 팀의 wjclnb Facility share 요청에서 127건의 subscription of … created, 379건의 recipe created 로그가 동기적으로 누적됨.
3. 2026-06-24 19:25:10 KST — 같은 요청이 ENT10003 Validation failed: Accessor has already been taken로 400 응답, 총 duration: 83137.58 ms.
4. 2026-06-24 19:25:12 KST — 동일 사용자/Facility 재시도 성공, 200 응답이지만 duration: 23313.33 ms로 여전히 22초 이상 소요.
5. 2026-06-24 21:46 KST — 클러스터 last_seen (last_seen: 2026-06-24T12:46:46.873Z), 동일 패턴의 share 요청이 계속 등장.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::FacilitiesController#share",
  "service": "cupixworks-api",
  "occurrences": 4,
  "avg_ms": 33254,
  "max_ms": 83140,
  "sample_trace_id": "1754067066426027647"
}

샘플 슬로우 요청 (request_id: 6f2ee359-6c79-4ed4-a4b0-6f4d9e6a5309, team exyte, region us-west-2):

{
  "duration": 83137.58,
  "db": 1702.38,
  "controller": "Api::V1::FacilitiesController",
  "action": "share",
  "params": { "key": "wjclnb" },
  "http": { "status_code": 400, "method": "PUT", "url_details": { "path": "/api/v1/facilities/wjclnb/share" } },
  "error": {
    "reason": "Validation failed: Accessor has already been taken",
    "code": "ENT10003",
    "class": "Cupix::Errors::Entity"
  },
  "team": { "domain": "exyte", "id": 783 },
  "@timestamp": "2026-06-24T10:25:10.015Z"
}

직후 재시도(200) 요청 (request_id: 46d7d865-3b9f-41ac-b192-589523444683):

{
  "duration": 23313.33,
  "db": 707.62,
  "controller": "Api::V1::FacilitiesController",
  "action": "share",
  "params": { "key": "wjclnb" },
  "http": { "status_code": 200, "method": "PUT" },
  "team": { "domain": "exyte", "id": 783 },
  "@timestamp": "2026-06-24T10:25:12.071Z"
}

duration 대비 db 비율은 각각 2.0%, 3.0% 수준이라 DB 시간이 아닌 외부 호출·캐시 작업이 지연의 주범임을 보여준다.

Impact#

• Service: cupixworks-api
• 발생 횟수: 4 (cluster.occurrence_count)
• 최초 발생: 2026-06-24 19:23 KST
• 최근 발생: 2026-06-24 21:46 KST
• 사용자 영향: 공유 대상 사용자 수가 수십수백 명 규모인 팀(exyte 등)에서 공유 동작이 3083초간 멈추고, 종종 ENT10003(중복 권한) 검증 실패로 400을 반환한 뒤 사용자가 재시도하면서 동일 부하가 반복된다. ALB/CloudFront idle timeout(통상 60s) 근접 또는 초과로 503/타임아웃 위험.

Root Cause Summary#

Api::V1::FacilitiesController#share → FacilityRepository#share는 요청에 포함된 user/group을 단일 트랜잭션 없이 순차 루프((@users + @groups + … ).each)로 add_permission!을 호출한다. 각 FacilityPermission 생성은 Cupix::PubSub::Subscribers::UserRecipeGenerator를 동기적으로 호출하고, 이 subscriber는 사용자마다 notification-service에 3개의 recipe 생성 HTTP 요청(record_preview_ready, record_processing_completed, facility_new_project) + subscribe 등 추가 HTTP 호출을 직렬로 발행한다. exyte 팀 사례에서는 단일 요청에 약 127명이 포함되어 subscription created 로그 127건, recipe created 로그 379건(127×3)이 발생했고, 외부 서비스 한 번의 latency가 누적되면서 총 83초까지 늘어났다. DB time은 1.7초로 전체의 2%에 불과하므로 root cause는 명백히 synchronous fan-out HTTP calls to notification-service per added user이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/share_controller.rb:32-45 (def share)
• Repository: app/repositories/concerns/sharable_repository.rb:131-193 (def share)
• Per-user fan-out: app/repositories/concerns/sharable_repository.rb:159-164
• Permission create + 캐시 무효화: app/models/concerns/permissionable.rb:60-71 (def add_permission!)
• Event dispatch + 외부 HTTP 호출: lib/cupix/pub_sub/subscribers/user_recipe_generator.rb:24-42
• 동기 HTTP 호출: lib/cupix/notification_service.rb:11-46 (create_user_recipe), lib/cupix/notification_service.rb:70-93 (subscribe)

def share
  validate_project_permissions_feature!

  members = repository_instance.share(
    params.slice(*SHARE_REQUEST_PARAMS),
    params[:permission]
  )

  render_api Renderable.new({
    contents: members,
    is_collection: true,
    serializer: MemberSerializer
  })
end

(@users + @groups + already_joined_or_invited_users + invited_users).each do |user_or_group|
  @model.add_permission! user_or_group, permission
  shared_users_and_groups << user_or_group
rescue ActiveRecord::RecordInvalid => e
  raise Cupix::Errors::Entity.new(code: 'ENT10003', reason: e.message)
end

def add_permission!(user_or_group, permission)
  _permission = permissions.find_or_initialize_by(accessor: user_or_group)
  _permission.permission = permission
  _permission.save!

  Permissionable.flush_cached_permissions(user_or_group)
  Permissionable.flush_cached_permissions_by_user(user_or_group, self)

  _permission
rescue ActiveRecord::RecordNotUnique
  Cupix::Logger.warn(...)
end

_permission.save!는 ActiveRecord after_create 콜백으로 PubSub 이벤트를 발행하고, UserRecipeGenerator가 이를 받아 즉시 외부 호출을 시작한다:

def _create_recipes_for_facility_permission(model)
  return false unless model.accessor_type == ::User.name

  user = model.accessor
  team_id = model.facility.team_id
  facility_key = model.facility.key

  _create_recipes(user: user, team_id: team_id, facility_key: facility_key)
end

def _create_recipes(opts = {})
  %w[
    record_preview_ready
    record_processing_completed
    facility_new_project
  ].each do |recipe_name|
    Cupix::NotificationService.new(user: opts[:user]).create_user_recipe(recipe_name, team_id: opts[:team_id], facility_key: opts[:facility_key])
  end
end

def create_user_recipe(recipe_name, team_id: nil, facility_key: nil)
  return if @service_url.nil?

  params = email_recipe_params(recipe_name, team_id, facility_key)
  response = Cupix::HttpClient.post(
    "#{@service_url}/api/recipes/v2",
    params.to_json,
    {
      content_type: :json,
      'x-cupix-auth': @user.api_token
    }
  )
  ...
end

기대 동작: 공유 대상 N명을 추가할 때, recipe/subscription 생성과 같이 사용자에게 즉시 보여주지 않아도 되는 후속 작업은 비동기 워커로 분리되어 API는 N에 무관하게 일정한 latency로 응답한다.

실제 동작: per-user 동기 HTTP 호출 ≥ 4회(subscribe + 3개 recipe)가 직렬로 발생. 127명 기준 ≥ 508회 외부 HTTP 호출이 한 요청 안에서 직렬화되어 총 응답시간이 외부 서비스 latency에 선형 비례하게 늘어난다. 트랜잭션 경계도 없어, 중간에서 한 사용자에 대해 ActiveRecord::RecordInvalid(중복 권한)가 발생하면 이미 처리된 N-1명에 대한 HTTP 호출은 그대로 남고, 클라이언트는 400을 받아 재시도하며 동일 부하가 반복된다(실측 19:25:10 400 → 19:25:12 200).

Log Evidence#

Datadog query (slow requests):

service:cupixworks-api @controller:"Api::V1::FacilitiesController" @action:share @duration:>30000

Datadog query (per-request fan-out trace):

service:cupixworks-api @request_id:6f2ee359-6c79-4ed4-a4b0-6f4d9e6a5309

샘플 슬로우 요청 카운트 (request_id: 6f2ee359-6c79-4ed4-a4b0-6f4d9e6a5309, 단일 share 호출):

대표 fan-out 로그 (한 사용자 분):

{"message":"subscription of marcel.orlandin@exyte.net on Facility wjclnb created","class":"Cupix::NotificationService","function":"subscribe","timestamp":"2026-06-24 19:25:09"}
{"message":"recipe created: {...\"name\":\"facility_new_project\",\"user_id\":\"51278\",\"team_id\":\"783\",\"facility_key\":\"wjclnb\"...}","class":"Cupix::NotificationService","function":"create_user_recipe","timestamp":"2026-06-24 19:25:09"}
{"message":"recipe created: {...\"name\":\"record_processing_completed\",\"user_id\":\"51278\"...}","class":"Cupix::NotificationService","function":"create_user_recipe","timestamp":"2026-06-24 19:25:09"}
{"message":"recipe created: {...\"name\":\"record_preview_ready\",\"user_id\":\"51278\"...}","class":"Cupix::NotificationService","function":"create_user_recipe","timestamp":"2026-06-24 19:25:09"}
{"message":"Flush cached permissions By User for User 51278 on Facility 21134","class":"Module","function":"flush_cached_permissions_by_user","timestamp":"2026-06-24 19:25:09"}
{"message":"Deleting cached_permission on user 51278","class":"User","function":"flush_cached_permission","timestamp":"2026-06-24 19:25:09"}

400 응답 시 정확한 실패 지점 로그:

{
  "message": "Validation failed: Accessor has already been taken",
  "class": "FacilityPermission",
  "function": "write_log",
  "status": "warn",
  "timestamp": "2026-06-24 19:25:09"
}

이는 add_permission!이 find_or_initialize_by(accessor: user_or_group).save!인데, 동시 요청이나 group 멤버 / already_joined_or_invited_users 중복으로 같은 accessor pair가 두 번 시도되어 unique constraint를 hit한 결과이며, 같은 transaction 안이 아니므로 rollback 없이 N-1명 분량의 외부 호출만 누적된 채 400으로 빠져나간다.

성공 응답(request_id: 46d7d865-3b9f-41ac-b192-589523444683)도 duration 23313.33 ms, db 707.62 ms로 외부 호출 비중이 압도적임을 보여준다.

us-west-2 region에서는 notification-service endpoint가 동일 region에 있다고 가정해도 호출 1회 ~ 50ms × ~500회 = ~25s 수준이며, 관측된 max 83s는 일부 호출이 더 느렸거나 일부 user가 group 멤버로 펼쳐져 횟수가 더 늘었음을 시사한다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• UserRecipeGenerator의 recipe 생성 호출을 비동기화한다. lib/cupix/pub_sub/subscribers/user_recipe_generator.rb:34-42의 _create_recipes가 controller 응답 경로 안에서 외부 HTTP를 직접 호출하지 않도록, Sidekiq 워커로 enqueue 후 워커 안에서 Cupix::NotificationService#create_user_recipe을 호출하도록 변경.
• 마찬가지로 subscribe 호출(요청별 127회 관측) 역시 워커로 분리. 이는 share 응답 경로(controller→repository→after_create 콜백)에서 분리되는 것이 핵심.
• Rationale: 단일 share 요청의 외부 HTTP 호출 수를 O(N) → O(0)로 줄이면, 관측된 83s가 DB 시간 1.7s 수준에 가깝게 떨어진다.

단기 개선 (1주 이내)#

• 벌크 처리: app/repositories/concerns/sharable_repository.rb:159-164의 per-user loop를 트랜잭션으로 감싸거나, 중복 accessor를 사전 필터링(@model.users.reload에 이미 있는 사용자 제외)하여 ActiveRecord::RecordInvalid → 400 재시도 패턴을 제거한다. 현재는 중간 실패 시 부분 처리된 N-1명에 대한 외부 호출 비용만 낭비되고 사용자는 동일 요청을 재시도한다.
• NotificationService bulk API: notification-service 측에 POST /api/recipes/v2/bulk 같은 batch endpoint를 추가하고, 워커 안에서 1회 호출로 다수 user×recipe를 등록한다. 동기 fan-out을 제거한 후에도 워커 큐 점유 감소 효과 있음.

장기 개선 (재발 방지)#

• 공유 응답 latency SLO 정의(예: p95 < 3s) 및 위반 시 알람.
• 응답 경로 외부 호출 가드레일: controller 안에서 호출되는 모든 외부 HTTP 클라이언트가 동기 호출을 시도하지 않도록 정적 검사(Rubocop rule 또는 spec lint)를 추가. Group/배치 share 케이스의 fan-out을 코드 리뷰 시 자동 발견할 수 있게 한다.
• bulk_share/공유 UX: 프론트엔드에서 다수 사용자 추가 시 chunked 호출(예: 10명씩 분할) 정책을 두어, 백엔드 변경 전까지 latency를 제한.

Monitoring#

p95/p99 latency for the share resource:

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::FacilitiesController#share,env:production}

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::FacilitiesController#share,env:production}

Slow request count (>10s):

logs("service:cupixworks-api @controller:Api::V1::FacilitiesController @action:share @duration:>10000").index("*").rollup("count").by("region").last("5m")

ENT10003 400 응답 발생률:

logs("service:cupixworks-api @controller:Api::V1::FacilitiesController @action:share @http.status_code:400 @error.code:ENT10003").index("*").rollup("count").last("5m")

NotificationService 호출량(요청 경로에서 인입되는 fan-out을 가시화):

logs("service:cupixworks-api @class:Cupix::NotificationService @function:create_user_recipe").index("*").rollup("count").last("5m")

logs("service:cupixworks-api @class:Cupix::NotificationService @function:subscribe").index("*").rollup("count").last("5m")

배포 후 검증용: share 요청별 외부 호출 수가 0에 가까운지 확인 (@request_id로 그룹화하여 fan-out 비율 확인).

Risk Assessment#

• Risk level: medium (사용자 영향은 30~80초의 UX 정체 + 400 후 재시도 루프이며, 데이터 손상은 없음. 다만 다수 사용자 공유 빈도가 높은 엔터프라이즈 팀에서는 high에 가까움.)
• 예상 복잡도: standard (이미 ShareEntityMailerWorker.perform_async 같은 비동기 패턴이 존재하므로 동일 패턴으로 UserRecipeGenerator를 워커로 분리 가능. after_create PubSub 흐름 변경은 회귀 테스트 영역이 넓어 spec 보완이 필요.)