RCA: Api::V1::ClustersController#update_meta_by_key latency (11.2s)

Overview#

What Happened#

2026-07-17 01:03 KST에 cupixworks-api production (us-west-2) 에서 PUT /api/v1/clusters/1454197/meta/constr 한 요청이 11.2초 걸린 뒤 200으로 정상 종료했다. 같은 시간대에 다른 요청은 정상 응답 (< 1s) 을 보였으며, 약 20분 전후로 Cupix::Errors::BadGateway("Bad Gateway error on Elasticsearch") 502 응답이 산발적으로 관측되어, 이 latency 스파이크는 Cluster#save after_commit 콜백이 호출하는 Elasticsearch 인덱스 요청의 일시적 지연에 기인한 것으로 판단된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-17 00:36 KST — Api::V1::Admin::EditingsController#index 에서 Cupix::Errors::BadGateway (Elasticsearch) 502 발생 (2회) — ES 불안정 신호.
2. 2026-07-17 01:03:14 KST 무렵 — PUT /api/v1/clusters/1454197/meta/prop 요청 정상 처리, 이후 PUT /api/v1/clusters/1454197/meta/constr 요청 시작 (trace 1192601485234977257).
3. 2026-07-17 01:03:15 KST — Datadog APM 이 해당 트레이스를 latency 이상치 (11248 ms) 로 감지 (first_seen).
4. 2026-07-17 01:03:25 KST — Cluster 1454197 Meta updated by key: constr info 로그 및 [200] PUT ... /meta/constr 액세스 로그 기록 → 요청 종료.
5. 2026-07-17 01:25-26 KST — Api::V1::PanosController#index 에서 Cupix::Errors::BadGateway (Elasticsearch) 502 재발생 (2회) — ES 지속 불안정 확인.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ClustersController#update_meta_by_key",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11248,
  "max_ms": 11248,
  "sample_trace_id": "1192601485234977257"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-17 01:03 KST
• 최근 발생: 2026-07-17 01:03 KST

Root Cause Summary#

Cluster#update_meta_by_key 는 MetableController#update_meta_by_key 에서 @model.save 를 호출하며, Cluster 모델은 EntityIndexable concern 을 include 하고 있어 update 시 after_commit :_entity_update_document 콜백이 요청 스레드에서 동기적으로 Elasticsearch::Model.client.index(...) 를 호출한다. 같은 시간대에 Cupix::Errors::BadGateway ("Bad Gateway error on Elasticsearch") 502 응답이 관측된 것으로 보아 Elasticsearch 클러스터가 일시적으로 지연/불안정 상태였고, 이 인덱스 호출이 클라이언트 타임아웃 (약 10초 + 재시도/커넥션 정리 오버헤드) 까지 대기하면서 전체 요청 지속시간이 11.2초까지 늘어난 것으로 판단된다. _entity_update_document 는 rescue StandardError 로 감싸져 있어 최종적으로 200이 반환되었지만, 요청 latency 는 그대로 사용자에게 전달되었다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/clusters_controller.rb:1 (Api::V1::ClustersController)
• 요청 흐름:
  1. 라우팅: PUT /api/v1/clusters/:id/meta/:meta_key → MetableController#update_meta_by_key
  2. before_action :set_cluster → ClusterRepository.show(params[:id]) 로 대상 로드
  3. @model.meta[params[:meta_key]] = parsed_meta 후 @model.save
  4. save 이후 after_commit on: :update 콜백들이 순차 실행됨. 그 중 EntityIndexable#_entity_update_document 가 ES 로 동기 인덱스 요청.
• Failure point (latency 원인): app/models/concerns/entity_indexable.rb:172-182 (_entity_update_document — ES 동기 호출).

Metable 컨트롤러 진입 및 save:

def update_meta_by_key
  if !@model.updatable_by?(current_user) && (@review.present? && !@review.updatable_by?(current_user))
    raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied')
  end

  begin
    parsed_meta = JSON.parse(request.raw_post)
    @model.meta[params[:meta_key]] = parsed_meta
    @model.skip_entrypoint_flush = true if @model.respond_to?(:skip_entrypoint_flush)
    @model.save
    # ... (cluster 인 경우 info 로그)
  rescue Cupix::Errors::Parameter => e
    raise Cupix::Errors::Parameter.new(code: 'ARG10004', reason: e.to_s, message: e.message)
  else
    render_json 200, @model.meta[params[:meta_key]]
    Cupix::Logger.info("Meta updated by key: '#{params[:meta_key]}' - keys: ...", ...)
  end
end

Cluster 모델은 EntityIndexable 을 include 하고 있음:

class Cluster < ApplicationRecord
  include CaptureEntity
  include EntityIndexable
  include Storagable
  # ...
  include Metable
  # ...
end

Save 후 실행되는 동기 ES 인덱스 호출:

included do
  after_commit :_entity_index_document, on: [:create]
  after_commit :_entity_update_document, on: [:update]
  after_commit :_entity_delete_document, on: [:destroy]
end

# ...

def _entity_update_document
  return if @skip_index_document == true

  Elasticsearch::Model.client.index(
  index: self.class.entity_index_name,
    id: entity_document_id,
    body: as_entity_indexed_json
  )
rescue StandardError => e
  Cupix::Logger.error("Entity update error - #{e.message}", class: self.class.name, function: __method__)
end

이 콜백은 요청 스레드에서 실행되고, ES 응답이 늦어지면 Rack 요청 duration 이 그대로 늘어난다. rescue StandardError 로 감싸져 있어 실패해도 200 응답이 나가지만, 성공/실패에 관계없이 latency 는 사용자에게 노출된다. 또한 as_entity_indexed_json 은 ancestry 확보 과정에서 Facility.where(id: ...).pick(:name, :key) 같은 추가 DB 쿼리를 수행 (entity_indexable.rb:132-147), ES 가 느릴 때 DB round-trip 오버헤드까지 겹칠 수 있다.

기대 동작: Cluster#save 는 Cluster 레코드만 DB 에 기록하고 반환, 인덱스 갱신은 비동기 워커 (예: BulkPartialIndexWorker) 로 위임되어 요청 latency 는 100ms~수백 ms 이내여야 한다. 실제 동작: ES 호출이 요청 스레드에서 동기 실행되어, ES 가 502 를 산발적으로 반환하던 시점에 이 트레이스가 11.2초까지 대기했다.

Log Evidence#

Datadog Query (해당 리소스, 이상 latency):

service:cupixworks-api resource_name:"Api::V1::ClustersController#update_meta_by_key" env:production @duration:>500ms

Datadog Query (동시간대 ES 관련 신호):

service:cupixworks-api "Bad Gateway"

문제의 트레이스에 대응하는 액세스/정보 로그 (같은 cluster 1454197 대상, 순서와 시각 일치):

2026-07-17 01:03:25 KST  info  Meta updated by key: constr. Cluster 1454197
                                  (class=Cluster, function=update_meta_by_key)
2026-07-17 01:03:25 KST  info  [200] PUT /api/v1/clusters/1454197/meta/constr (Api::V1::ClustersController#update_meta_by_key)
2026-07-17 01:03:21 KST  info  Meta updated by key: prop. Cluster 1454197
2026-07-17 01:03:21 KST  info  [200] PUT /api/v1/clusters/1454197/meta/prop (Api::V1::ClustersController#update_meta_by_key)

Cluster 파일의 first_seen (2026-07-17 01:03:15 KST) 은 위 /meta/constr 완료 시각 (01:03:25 KST) 에서 duration 11.2s 를 뺀 시각과 정확히 일치한다 → 이 요청이 문제의 슬로우 트레이스임.

같은 시간대 ES 불안정을 보여주는 502 로그:

{
  "timestamp": "2026-07-17 01:25:57 KST",
  "status": "info",
  "message": "[502] GET /api/v1/panos (Api::V1::PanosController#index)",
  "error": {
    "reason": "Bad Gateway error on Elasticsearch",
    "code": "BG10002",
    "message": "Bad Gateway error on Elasticsearch",
    "class": "Cupix::Errors::BadGateway"
  }
}

같은 창(2026-07-17 00:36 KST) 에도 Cupix::Errors::BadGateway 502 가 Admin::EditingsController#index 에서 2회 관측됨. 즉 슬로우 요청 전후로 Elasticsearch 지연/에러가 존재.

Entity index error / Entity update error (해당 rescue 블록의 로그) 는 슬로우 시점 근방에서 관측되지 않았다:

Query: service:cupixworks-api "Entity index error" OR "Entity update error"
Range: 2026-07-16T15:00:00Z ~ 2026-07-16T17:00:00Z
Result: 0 logs

즉 ES 호출은 최종적으로 성공했거나, 로그로 남지 않는 방식으로 지연되었다 → 슬로우 트레이스만 남고 예외는 발생하지 않은 시나리오와 일치.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

별도의 즉시 코드 변경 없음. 이번 이벤트는 단일 슬로우 트레이스이고 200 응답으로 종료됨. 하지만 재발 방지 관점에서 short-term 개선을 우선 순위로 진행할 것을 권장.

단기 개선 (1주 이내)#

• EntityIndexable#_entity_update_document (그리고 _entity_index_document) 를 비동기 워커로 이동한다. 대상 파일: app/models/concerns/entity_indexable.rb:41-45, 160-194. 현재 after_commit 에서 직접 Elasticsearch::Model.client.index 를 호출하는 대신, execute_after_commit { EntityIndexWorker.perform_async(self.class.name, id, :update) } 형태로 위임하고 워커 안에서 as_entity_indexed_json 을 계산해 ES 로 전송. 이렇게 하면 ES 지연이 사용자 응답 latency 로 새어나오지 않는다.
• ES 클라이언트에 request 타임아웃과 재시도 상한을 명시한다. 현재 Elasticsearch::Model.client 는 client-level 타임아웃이 명시적이지 않음. request_timeout 을 예: 2~3초로 설정하고, retry 는 워커 (Sidekiq) 에 위임하도록 조정.
• _entity_update_document 안의 rescue 를 network 예외 (예: Faraday::TimeoutError, Elasticsearch::Transport::Transport::Errors::*) 로 좁혀 로그 level 을 warn 으로 낮추고, 진짜 예상 밖 예외는 error 로 유지. Memory 룰 참조: warn-level 다운그레이드는 예외 클래스 범위로 좁혀야 함.
• 동일 endpoint (update_meta_by_key) 의 p95/p99 latency 모니터를 추가하여, ES 지연이 latency 로 새어나오는지 상시 감지.

장기 개선 (재발 방지)#

• 모델 save 경로의 동기 외부 I/O 콜백을 전수 감사한다. 특히 data_ware_house/full_json.rb:6-7, annotatable.rb:7, firebase/*, pub_sub/publisher.rb:37-41 처럼 after_save/after_commit 에서 외부 시스템 (S3, Firebase, PubSub) 을 건드리는 콜백이 다수 존재. 각각을 워커 위임으로 표준화하고, 콜백에서 외부 I/O 를 금지하는 리뷰 룰을 문서화.
• Cluster 처럼 concerns 가 20개 넘게 include 된 모델은 save 시 콜백 그래프를 시각화 (예: bundle exec rake callbacks:list[Cluster] 같은 진단 태스크) 하여 어떤 콜백이 request path 에서 실행 중인지 개발자가 인지하도록 한다.
• ES 인덱싱 sink 를 별도 out-of-band pipeline (예: BulkPartialIndexWorker 처럼 CDC / Sidekiq) 으로 통일하여, 요청 경로에서 ES 로의 직접 write 를 원천적으로 제거.

Monitoring#

Datadog release-dashboard 용 timeseries 쿼리 (모두 metric-only, monitor 문법 사용 금지):

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::clusterscontroller#update_meta_by_key}

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::clusterscontroller#update_meta_by_key}

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::clusterscontroller#update_meta_by_key,http.status_code:2xx}.as_rate()

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::clusterscontroller#update_meta_by_key}.as_rate()

Elasticsearch health signal (동일 서비스 관점):

sum:trace.faraday.request.errors{service:cupixworks-api,http.status_code:502}.as_rate()

권장 알림 (모니터 화면 별도 구성):

• update_meta_by_key p99 duration > 3s (5분 지속)
• service:cupixworks-api "Bad Gateway error on Elasticsearch" 로그 카운트 > 5 in 10m

Risk Assessment#

• Risk level: medium — 현재 이벤트 자체는 200 응답 1건이지만, EntityIndexable 는 Cluster/Capture/Record/Facility 등 다수의 핵심 모델에 include 되어 있어 ES 가 지연되면 다수 endpoint 의 write latency 로 동시에 전파될 잠재력이 크다.
• 예상 복잡도: standard — EntityIndexable 콜백을 워커 위임으로 바꾸는 리팩터. Sidekiq 큐/재시도 정책, 인덱스 최신성 (order guarantee) 요구사항 검토 필요. execute_after_commit + Sidekiq 패턴은 이미 코드베이스에 존재 (statable/pix_genie.rb:66, taskable/job.rb 등) 하므로 새로운 인프라는 불필요.