RCA: Api::V1::ElementRecordsController#bulk latency (224.6s)

Overview#

What Happened#

2026-07-09 09:32 KST 경 cupixworks-api의 Api::V1::ElementRecordsController#bulk 엔드포인트에서 단일 요청이 224,651ms(약 3분 45초) 동안 지속된 latency outlier가 감지되었다. 해당 엔드포인트는 external Siteinsights API Gateway로 PUT 요청을 프록시하는 얇은 controller로, 동일 시간대 정상 요청은 2~4초 범위였다. 요청 로그(Rails)에는 완료 기록이 없어 응답이 클라이언트에 도달하기 전에 hang 상태로 지속된 것으로 보인다.

Quick Facts#

Affected Teams#

주변 로그에서 확인된 이 엔드포인트의 실사용자는 특정 팀 하나이다.

Timeline#

1. 2026-07-09 09:29 KST — clark-vdc cupix-agent가 PUT /api/v1/siteinsights/element_records 폴링을 정상 지속 (duration 1.5~4.1s)
2. 2026-07-09 09:31:00 KST — 정상 요청 마지막 완료 로그 (request_id=2003fabe, 2096ms)
3. 2026-07-09 09:3109:32 KST — 슬로우 요청 시작 (trace 3809733074415148890)
4. 2026-07-09 09:32:09 KST — Datadog APM이 224,651ms span 종료 시점을 first_seen으로 기록
5. 2026-07-09 09:32:20 KST — 다른 bulk 요청이 정상적으로 다시 완료 (request_id=72be69a7, 2520ms)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ElementRecordsController#bulk",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 224651,
  "max_ms": 224651,
  "sample_trace_id": "3809733074415148890"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-09 09:32 KST
• 최근 발생: 2026-07-09 09:32 KST

단일 outlier이며, 동일 시간대 다른 요청은 정상 응답. 클라이언트(cupix-agent) 하나의 폴링 사이클이 최대 ~3분 45초 지연됨. ALB idle timeout(보통 60s)을 초과하므로 클라이언트 측에는 소켓 종료로 관측되었을 가능성이 높다.

Root Cause Summary#

Api::V1::ElementRecordsController#bulk는 Cupix::SiteinsightsService.bulk_element_records!를 통해 외부 Siteinsights API Gateway(https://*.execute-api.*.amazonaws.com/api)로 Cupix::HttpClient.put을 동기 호출한다. Cupix::HttpClient는 RestClient.put을 timeout 옵션 없이 호출하고, 429/502/503/504 응답에 대해 최대 3회 exponential backoff(sleep 1s+2s+4s)로 재시도한다. RestClient의 default open/read timeout은 무제한이므로, upstream이 응답 지연 또는 연결 미종료(예: API Gateway integration timeout, TCP half-open, TLS retransmit)를 겪으면 controller가 blocking 상태로 무한히 대기한다. 이번 트레이스에서 224,651ms 동안 request log에 완료 기록이 남지 않은 점은 Rails가 Siteinsights 응답을 기다리다가 Puma worker가 다른 방식으로 회수되었을 가능성(예: request timeout middleware, worker recycle, ALB reset)을 시사한다. Root cause는 HttpClient에 read/open timeout이 설정되지 않아 upstream이 hang될 때 request-level bound가 없다는 것이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/element_records_controller.rb:17 — bulk action
• Service: app/services/cupix/siteinsights_service.rb:155 — bulk_element_records!
• HTTP proxy: lib/cupix/http_client.rb:56 — Cupix::HttpClient.put
• Failure point: lib/cupix/http_client.rb:59 — RestClient.put(url, payload, headers) (no timeout)

Controller는 파라미터 검증 없이 그대로 service로 위임한다:

def bulk
  response = Cupix::SiteinsightsService.bulk_element_records!(params, current_user: @current_user, current_team: @current_team)

  render_json 200, response
end

Service 계층은 facility 권한 체크 후 payload를 그대로 upstream으로 PUT:

def bulk_element_records!(params = {}, current_user: nil, current_team: nil, visibility: nil)
  raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'facility_key is required') if params[:facility_key].blank?

  facility = ::FacilityRepository.new(current_user: current_user, current_team: current_team).show(params[:facility_key], visibility: visibility)
  raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied') unless facility.updatable_by?(current_user)

  begin
    params = self._merge_current_user(params, current_user)
    response = Cupix::HttpClient.put("#{Cupix::Siteinsights.service_url}/element_records/bulk", params.to_json, { content_type: :json })

    JSON.parse(response.body)['result']
  rescue RestClient::Exception => e
    Cupix::Logger.error("failed to bulk element records - error: #{e.message}", class: self.name, function: __method__, params: params)

    raise Cupix::Errors::System.new(code: 'SYS20000', reason: "failed to bulk element records - error: #{e.message}")
    # ...
  end
end

HttpClient는 재시도 backoff은 있지만 RestClient 호출에 timeout을 지정하지 않는다:

def self.put(url, payload, headers = {}, retries: MAX_RETRIES)
  attempt = 0
  begin
    RestClient.put(url, payload, headers)  # no :timeout, :open_timeout
  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

RestClient의 기본 timeout은 nil (=Ruby Net::HTTP 기본, open_timeout 60s이나 read_timeout 무제한). 즉 서버가 TCP는 열지만 body를 보내지 않으면 요청이 무기한 대기한다.

기대 동작: upstream이 slow하면 명시적 read timeout(예: 30s)에 도달 후 RestClient::Exceptions::ReadTimeout으로 실패 → 재시도 최대 3회 → 유한한 총 시간 내 종료.

실제 동작: read timeout 미설정 → controller가 upstream을 무기한 대기 → Puma worker 점유 → 상위(APM/ALB) 레이어에서만 종료가 관측됨.

Log Evidence#

Datadog 쿼리 (재현용):

service:cupixworks-api "ElementRecordsController#bulk"

시간 범위 2026-07-09T00:29:00Z ~ 2026-07-09T00:33:00Z에서 정상 요청 timeline (모두 200 OK):

2026-07-09T00:29:11.795Z dur=3762.77ms  req=30c187e3
2026-07-09T00:29:25.836Z dur=4090.79ms  req=ab5a0c14
2026-07-09T00:29:39.875Z dur=2396.53ms  req=85c7fc2d
2026-07-09T00:29:45.900Z dur=2165.51ms  req=efa5db10
2026-07-09T00:29:55.926Z dur=1549.00ms  req=a1653838
2026-07-09T00:30:24.018Z dur=3316.97ms  req=793ee034
2026-07-09T00:30:28.028Z dur=3095.19ms  req=85a2e590
2026-07-09T00:30:30.038Z dur=3119.08ms  req=c64fb7d8
2026-07-09T00:30:34.054Z dur=3132.83ms  req=03d82a50
2026-07-09T00:30:42.075Z dur=2497.74ms  req=fd6f91ae
2026-07-09T00:30:50.107Z dur=2361.81ms  req=3967b554
2026-07-09T00:31:00.156Z dur=2096.00ms  req=2003fabe
[GAP ~80s — no completed bulk requests]
2026-07-09T00:32:20.429Z dur=2520.22ms  req=72be69a7
2026-07-09T00:32:30.463Z dur=2758.61ms  req=f478c006

정상 요청 대표 로그 (한 개 발췌):

{
  "@timestamp": "2026-07-09T00:35:59.062Z",
  "action": "bulk",
  "controller": "Api::V1::ElementRecordsController",
  "duration": 2442.08,
  "db": 156.06,
  "view": 0.57,
  "http": { "status_code": 200, "method": "PUT", "url_details": { "path": "/api/v1/siteinsights/element_records" } },
  "user_agent": "cupix-agent",
  "team": { "domain": "clark-vdc", "id": 87 },
  "params": { "facility_key": "dwwuda", "fields": ["oid", "bim_external_id", "texture", "bim", "element", "task", ...] }
}

관찰 사실:

• 정상 요청은 duration 1.5~4.1s (평균 ~2.7s), 모두 200 OK
• 00:31:00과 00:32:20 사이 ~80초간 완료된 bulk 요청 로그 없음
• 슬로우 트레이스(trace_id 3809733074415148890)는 request log에 매칭되는 완료 항목이 없음
• service:cupixworks-api "failed to bulk element records" 검색 결과 지난 14일간 0건 — Siteinsights 자체가 5xx로 실패하고 재시도를 소진한 시나리오는 아님
• service:cupixworks-api status:error 검색 결과 해당 시간대 Siteinsights 관련 error 로그 없음

Datadog 쿼리 (에러 확인용):

service:cupixworks-api "failed to bulk element records"

service:cupixworks-api status:error

Hypotheses Considered#

Fix Recommendation#

현재 develop 상태 (Revision 1에서 확인)#

• 대상 레포: tesla (cupixworks-api). origin/develop HEAD e4be083ad 기준.
• lib/cupix/http_client.rb 최근 커밋: 1787acf36 (2026-04-15, "TSLA-12415: replace all RestClient/Net::HTTP with Cupix::HttpClient …") — 인시던트(2026-07-09) 이전 커밋이며 이후 수정 없음.
• origin/develop:lib/cupix/http_client.rb 전체 소스에서 timeout/open_timeout/read_timeout 문자열 grep 결과 0건 (GET/POST/PUT/PATCH/DELETE 모두 RestClient.<verb>(url[, payload], headers)만 호출).
• origin/master와 origin/develop의 해당 파일 diff 없음(git rev-list --count origin/master..origin/develop -- lib/cupix/http_client.rb = 0).
• 결론: 현 시점(develop) 기준으로 아래 즉시 조치가 아직 반영되어 있지 않다. 별도 PR을 만들어야 한다.

즉시 조치 (Critical)#

• 파일: lib/cupix/http_client.rb
• 접근: RestClient.put(및 get/post/patch/delete)에 명시적 timeout / open_timeout 옵션 지정. 예: open_timeout: 5, read_timeout: 30. RestClient 4.x는 RestClient::Request.execute(method:, url:, payload:, headers:, timeout:, open_timeout:) 형식을 지원하므로 wrapper를 그 방식으로 리팩터.
• 근거: timeout 미설정으로 upstream hang이 request-level bound 없이 blocking을 유발. Read timeout(예: 30s)이 설정되면 최악의 경우 3회 재시도 포함 총 (30+30+30) + (1+2+4) = 97s 이내에 실패하여 client에 5xx가 전달된다.

단기 개선 (1주 이내)#

• Timeout 값을 endpoint별로 다르게: Cupix::HttpClient.put(..., timeout:, open_timeout:) 시그니처 확장 후, bulk_element_records!처럼 대량 payload가 예상되는 호출은 별도 값(예: 60s) 사용. 짧은 metadata 호출(last_synced_at)은 5s.
• Rack::Timeout / puma_worker_killer 도입 검토: 개별 요청이 upstream 무관하게 Puma worker를 잡고 있는 경우를 방지.
• Siteinsights bulk를 비동기 처리로 전환 검토: 요청 폴링(cupix-agent가 초당 다수 발생) 특성상, controller가 큐(Sidekiq)로 위임하고 immediately 202/303을 반환한 뒤 결과를 폴링하도록 API 계약 변경 검토.

장기 개선 (재발 방지)#

• 모든 upstream HTTP 호출에 timeout 강제: Cupix::HttpClient 사용을 팀 컨벤션으로 강제하고, RestClient.* 직접 사용을 lint(RuboCop custom cop)로 금지.
• Circuit breaker: 반복적으로 slow인 upstream에 대해 Semian/Faraday circuit breaker 도입, latency SLO 기반 fast-fail.
• APM span attribute 추가: HttpClient wrapper에서 http.request.timeout, http.retries.attempted 등 span attribute를 기록해 이번 같은 outlier의 원인 분리를 로그 없이도 가능하게 함.

Monitoring#

• 추가 메트릭/알림
  • Api::V1::ElementRecordsController#bulk의 p99 latency > 10s 지속 시 알림
  • Siteinsights upstream 5xx rate 알림
• Datadog 쿼리 예시:

Bulk endpoint의 요청 duration 분포 (request log 기반, timeseries widget 호환):

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::elementrecordscontroller#bulk} by {env}

Bulk endpoint의 slow 요청 개수 (>= 30s):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::elementrecordscontroller#bulk,duration:>30s}.as_count()

Siteinsights 관련 에러 로그 발생율:

sum:logs.hits{service:cupixworks-api,@class:Cupix::SiteinsightsService,status:error}.as_count()

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard

단일 outlier이지만 timeout 미설정이라는 코드 결함은 항시 재발 가능하며 향후 upstream 장애 시 다수 worker가 동시에 blocking될 수 있다. 수정 자체는 HttpClient wrapper 하나에 집중되지만, 전역 timeout 도입은 짧은 timeout으로 인한 false-negative 회귀 위험이 있어 endpoint별 값 튜닝과 회귀 테스트가 필요하다.

Revision History#

Revision 1#

Feedback: "이거 develop 에 적용되어있는지 검토" — 권장 수정(HttpClient timeout 설정)이 tesla develop 브랜치에 이미 반영돼 있는지 확인 요청.

판정:

변경 사항:

• ## Fix Recommendation 상단에 ### 현재 develop 상태 (Revision 1에서 확인) 서브섹션 추가 — develop 브랜치 커밋 해시, 최근 수정 커밋, grep 결과, master/develop 동일성을 명시하고 "아직 미반영 → 별도 PR 필요" 결론 기재.

추가 조사 내용:

• Repo: tesla (cupixworks-api)
• Branch: origin/develop HEAD e4be083ad
• File: lib/cupix/http_client.rb (전체 5개 verb 메서드 확인)
• Grep: timeout|open_timeout|read_timeout → 0건
• Diff vs master: origin/master..origin/develop -- lib/cupix/http_client.rb = 0 커밋