RCA: Api::V1::CapturesController#create (avg 10301ms, max 10301ms)

Overview#

What Happened#

2026-06-24 18:53 KST에 cupixworks-api (eu-central-1) 의 POST /api/v1/captures 요청 1건이 약 10.3초 소요되었다. 트레이스 로그를 따라가 보면, Capture 생성 자체는 빨랐으나 후속 ActiveSupport::Notifications 구독자가 요청 스레드에서 동기적으로 notification-service 로 4개의 HTTP 호출(recipe 3개 + subscription 1개)을 차례로 보내며 응답을 보류했다. notification-service 자체는 정상이었다 (Lambda Duration 70~80ms).

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-24 18:53:48 KST — 트레이스 시작 (Api::V1::CapturesController#create)
2. 2026-06-24 18:53:50 KST — RecordFactory 가 Record(7227) 생성, Spacetime 4건 생성 + facility review 캐시 무효화
3. 2026-06-24 18:53:52 KST — Capture(40036) 생성 완료, cupix-trace-id 발급, Cupix::EventService.publish_event 호출, User/Capture 권한 캐시 flush
4. 2026-06-24 18:53:55 KST — notification-service 가 record_preview_ready recipe 저장 (1번째 외부 HTTP)
5. 2026-06-24 18:53:57 KST — record_processing_completed, facility_new_project recipe 저장 (2~3번째 외부 HTTP)
6. 2026-06-24 18:54:00 KST — Facility sirg5z subscription 생성 (4번째 외부 HTTP)
7. 2026-06-24 18:54:02 KST — [200] POST /api/v1/captures 응답 완료 (총 약 10.3초)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::CapturesController#create",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10301,
  "max_ms": 10301,
  "sample_trace_id": "1886599198934093405"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-24 18:53 KST
• 최근 발생: 2026-06-24 18:53 KST
• 사용자 영향: 응답 자체는 200 성공이므로 데이터 손상은 없음. 다만 모바일/웹 클라이언트의 capture 업로드 첫 요청이 10초 대기하며 사용자 체감 품질 저하 및 클라이언트측 timeout 위험이 발생.
• 재발 조건: facility 에 처음으로 권한이 부여되는 사용자(즉 FacilityPermission 가 새로 생성되는 사용자) 의 capture 생성 시 동일하게 재현되는 구조적 패턴.

Root Cause Summary#

Api::V1::CapturesController#create 의 처리 시간이 길어진 이유는 컨트롤러 자체 로직이 아니라, capture 생성 과정에서 함께 만들어지는 FacilityPermission 의 created 이벤트가 두 개의 ActiveSupport::Notifications 구독자(UserRecipeGenerator, SubscriptionGenerator) 를 동기적으로 깨우기 때문이다. 두 구독자는 합쳐서 notification-service 로 4번의 RestClient HTTP 호출을 순차 실행한다 (recipe 3개 + subscription 1개). Datadog 로그상 이 구간이 18:53:55 ~ 18:54:00 KST 약 5초를 차지하며, 그 외 capture 생성에 따른 Spacetime/Record 4건 + 권한 캐시 flush 동기 처리까지 합쳐 총 10.3초가 된다. notification-service 자체는 정상(Lambda 70~80ms)이었으므로 외부 의존성 장애가 아니라, 요청 경로에 비핵심(notification recipe seeding) 동기 fan-out 이 누적된 구조적 latency 다.

Technical Analysis#

Code Path#

진입점은 CapturesController#create 이며 factory_instance.create!(params) 한 번 호출 후 super 로 표준 응답을 렌더링한다.

def create
  @model = factory_instance.create!(params)

  super
end

CaptureFactory#create! 는 facility/record 조회 또는 생성, capture_type 등록, 검증을 거친 뒤 super 로 BaseFactory 에 위임한다. BaseFactory 가 model.save! 를 호출하면 model 의 콜백 체인과 ActiveSupport::Notifications 가 트리거된다.

def create!(params = {})
  self.model = ::Capture.new
  # ... facility / record 결정, capture_type 결정, capture_mode/manual_align_type 검증 ...
  super
end

이 흐름 안에서 FacilityPermission 가 created 이벤트를 발행하면, 같은 namespace 에 attach 된 두 구독자가 모두 동기 호출된다.

Cupix::PubSub::Subscribers::UserRecipeGenerator.attach_to(::FacilityPermission.name.underscore)
Cupix::PubSub::Subscribers::SubscriptionGenerator.attach_to(::FacilityPermission.name.underscore)

Subscribers::Base 는 ActiveSupport::Notifications.subscribe 로만 등록하고 별도 Sidekiq enqueue 를 하지 않으므로, 핸들러는 publisher 와 동일한 Rack 요청 스레드 에서 실행된다.

def attach_to(namespace)
  _subscriber = new(namespace)
  _subscriber.public_methods(false).each do |event_name|
    ActiveSupport::Notifications.subscribe("#{namespace}.#{event_name}", _subscriber)
  end
end

def call(subscription_name, *args)
  method_name = subscription_name.gsub("#{namespace}.", '')
  handler = self.class.new(namespace)
  handler.send(method_name, ActiveSupport::Notifications::Event.new(subscription_name, *args))
rescue StandardError => e
  Cupix::Logger.error("processing '#{subscription_name}' failed: #{e.message}", ...)
end

UserRecipeGenerator 는 facility_permission 한 건당 3개의 recipe 를 for-each 동기 루프 로 만든다.

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

SubscriptionGenerator 는 추가로 1번의 subscribe 호출을 발생시킨다.

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

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

  _create_subscription(user: user, facility_key: facility_key)
end

def _create_subscription(opts = {})
  Cupix::NotificationService.new(user: opts[:user]).subscribe(facility_key: opts[:facility_key])
end

Failure point — Cupix::NotificationService#create_user_recipe 와 subscribe 가 그대로 Cupix::HttpClient.post/put 를 호출하며, 이 호출은 RestClient.post 에 timeout/connect_timeout 을 명시하지 않아 각 호출이 RestClient 기본 동작에 의존한다. 게다가 502/503/504 에 대해 지수 backoff(1, 2, 4초) 로 최대 3회 재시도하므로, 단 한 번의 retry 가 발생하면 동기 경로에 수 초가 추가된다.

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
    }
  )

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

기대 동작: capture 생성 응답은 핵심 자원 저장 직후 빠르게 반환되어야 하며, recipe seeding/subscription 같은 보조 작업은 비동기 worker(Sidekiq) 또는 after_commit 후 enqueue 로 분리되어야 한다.

실제 동작: 위 보조 작업이 모두 요청 스레드에서 직렬 실행되며 응답을 차단한다. 이번 트레이스는 facility 11415 (sirg5z) 에 대해 처음 권한 부여가 일어난 사용자로 보이며, 따라서 4건의 외부 HTTP 호출이 모두 발생했다.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api trace_id:1886599198934093405

service:notification-service "user_recipe"

핵심 로그(KST 기준, 일부 압축):

2026-06-24 18:53:50  Cachable::ReviewLoad | Invalidated facility review cache on create | model=Spacetime | model_id=55539 | facility_id=11415
2026-06-24 18:53:50  [RecordFactory] Record(7227) created with captured_at: 2026-06-24 05:21:10 UTC
2026-06-24 18:53:52  Success to get cupix-trace-id when Capture create
2026-06-24 18:53:52  Published event - failed_record_count: 0 / 1
2026-06-24 18:53:52  reset Facility (ID: 11415) cached entity updates
2026-06-24 18:53:52  Flush cached permissions By User for User 4236 on Capture 40036
2026-06-24 18:53:58  recipe created: {"result":{"data":{"id":"48e0356d-...","name":"record_preview_ready",...}}}
2026-06-24 18:53:58  recipe created: {"result":{"data":{"id":"89a5fbbd-...","name":"record_processing_completed",...}}}
2026-06-24 18:53:58  recipe created: {"result":{"data":{"id":"85aef5bb-...","name":"facility_new_project",...}}}
2026-06-24 18:54:00  subscription of baldivin.hilary@shapoorji.com on Facility sirg5z created
2026-06-24 18:54:02  [200] POST /api/v1/captures (Api::V1::CapturesController#create)

notification-service 측 로그(KST):

2026-06-24 18:53:55  RecipeRepository::create | creating recipe: ... record_preview_ready ...
2026-06-24 18:53:57  RecipeRepository::create | creating recipe: ... record_processing_completed ...
2026-06-24 18:53:57  RecipeRepository::create | creating recipe: ... facility_new_project ...

같은 1분 창에 notification-service Lambda 의 REPORT 항목은 모두 70~80ms 로 정상 종료되었다. 즉 외부 의존성 자체는 빠르게 응답했고, 지연은 호출 수와 직렬화에 기인한다.

REPORT RequestId: f2d55aec-...  Duration: 79.77 ms  Billed Duration: 80 ms
REPORT RequestId: 05836ea2-...  Duration: 72.12 ms  Billed Duration: 73 ms

같은 시간대 cupixworks-api 의 status:warn 은 NotFound - attributes_in_database (Mongoid 인덱싱 관련) 만 보였고, capture 트랜잭션의 DB lock/timeout 이나 connection-pool 경고는 관찰되지 않았다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

해당 단일 트레이스만으로는 즉시 코드 변경이 불필요하다. 다만 같은 패턴이 facility 첫 권한 부여 시마다 재현되므로, 다음 항목을 알람화한다.

• service:cupixworks-api resource_name:"Api::V1::CapturesController#create" 의 p95 latency 가 5초를 초과하면 noti(또는 page) 발송.
• Cupix::HttpClient 가 timeout 옵션을 명시하지 않는 위험을 단기 핫픽스로 좁힌다 (open_timeout, read_timeout 명시적 설정 — 별도 PR 권장).

단기 개선 (1주 이내)#

1. UserRecipeGenerator#_create_recipes 와 SubscriptionGenerator#_create_subscription 를 after_commit 기반 비동기 worker(Sidekiq) 로 이관한다. 권한 부여 직후 recipe 생성/subscription 등록은 응답 경로의 핵심 동작이 아니다.
   • 대상 파일: lib/cupix/pub_sub/subscribers/user_recipe_generator.rb, lib/cupix/pub_sub/subscribers/subscription_generator.rb
   • 접근: 기존 ActiveSupport::Notifications 핸들러는 유지하되 내부에서 NotificationRecipeSeedJob.perform_async(user_id, team_id, facility_key) 형태로 enqueue.
2. Cupix::HttpClient.post/put/get/delete 에 open_timeout: 5, read_timeout: 10 등 명시적 timeout 을 추가해 무한 대기를 차단. 현재는 RestClient 기본값에 의존.
   • 대상 파일: lib/cupix/http_client.rb:34-105

장기 개선 (재발 방지)#

1. ActiveSupport::Notifications 구독자가 IO/HTTP 호출을 하는 패턴을 전반적으로 감사한다. Subscribers::Base#attach_to 를 통한 모든 등록 지점에 대해 동기 IO 금지 가이드라인을 정하고, base class 자체를 perform_async 한 번만 수행하는 thin wrapper 로 강제하는 방안을 검토한다.
2. capture 생성 트랜잭션 내부에서 발생하는 모든 부수 효과(Spacetime 4건 생성, 권한 캐시 flush, event publish, recipe seeding) 를 after_commit + Sidekiq 로 일관되게 분리해 컨트롤러 응답 시간을 100ms 이하 SLO 로 잡는다.
3. notification-service recipe 시드 작업을 facility/team onboarding 시점에 idempotent 하게 한 번 처리하도록 수명주기를 옮긴다. 현재는 user 단위 facility_permission 마다 매번 같은 3종 recipe 를 시도해 ARG12001(이미 존재) 분기에 자주 진입한다 — 호출 자체를 줄이는 게 가장 효과적.

Monitoring#

writing-datadog-monitoring-queries 가이드를 따른 timeseries 쿼리.

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::CapturesController#create}

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::CapturesController#create}

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:Api::V1::CapturesController#create}.as_count()

avg:trace.rest_client.request.duration{service:cupixworks-api,resource_name:notification-service}

추가 알람 권장:

• 위 p95 가 연속 5분간 5초를 초과하면 알림.
• Cupix::NotificationService Recipe creation failed 로그 비율 (errors / total) 이 5% 초과 시 알림.

Risk Assessment#

• Risk level: medium — 사용자 데이터 손실/오류는 없으나 capture 첫 등록 사용자(특히 신규 facility 권한자) 의 첫 인상 지표를 직접 깎고, 클라이언트 timeout 시 데이터 정합 이슈로 번질 수 있음.
• 예상 복잡도: standard — 구독자를 Sidekiq 로 옮기는 변경은 기존 idempotent ARG12001 분기 덕분에 비교적 안전. HttpClient timeout 추가는 trivial.