RCA: Api::V1::BimsController#check_uploading (avg 25421ms, max 25421ms)

Overview#

What Happened#

2026-07-17 16:06 KST에 cupixworks-api (production, us-west-2)의 PUT /api/v1/bims/20623/check_uploading 요청이 25.4초 소요된 뒤 200으로 응답했다. 정상 동작 시 이 엔드포인트의 지연은 수백 ms 수준이며, 같은 시간대에 Elasticsearch / RDS / S3 를 상대로 한 10 초 timeout 이 다수 관측되어 downstream backend 지연에 요청이 갇힌 것으로 판단된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-17 16:06:57 KST — PUT /api/v1/bims/20623/check_uploading 요청 시작 (trace 266672872687379098).
2. 2026-07-17 16:07:23 KST — 동일 요청 200으로 종료 (25.4s 소요). 성공했지만 latency 클러스터로 검출.
3. 2026-07-17 16:10:00 KST — Uuidable::UuidValidator.uuid_used_in_other_models? 에서 Elasticsearch Operation timed out after 10002 milliseconds with 0 bytes received (warn).
4. 2026-07-17 16:11:20 KST — 동일 ES timeout 재발.
5. 2026-07-17 16:15:34 KST — PUT /api/v1/captures/736633/check_voxels_uploading 502 (Mysql2::Error::TimeoutError: Lock wait timeout exceeded). 이후 5분간 반복.
6. 2026-07-17 16:20:38 KST — Admin::CaptureRepository 에서 외부 HTTP Operation timed out after 10002 milliseconds 다수.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::BimsController#check_uploading",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 25421,
  "max_ms": 25421,
  "sample_trace_id": "266672872687379098"
}

Impact#

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

Root Cause Summary#

BIM check_uploading 엔드포인트는 하나의 요청 안에서 (1) S3 HeadObject 4회 (_object.exists?, .etag, .size, .content_type), (2) resource.state_name 상태 전이 및 저장, (3) BimRevisionFactory.create! 로 새 BimRevision INSERT 를 모두 동기적으로 수행한다. 같은 시간대(07:10~07:20 UTC) 에 Elasticsearch·MySQL·외부 HTTP 상대로 10 초 timeout 이 연달아 관측되었고, 특히 동일 서비스에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 502 가 반복되었다. 즉 이번 요청은 downstream 하나(가장 가능성 높은 후보: RDS lock 대기 또는 S3 latency + AWS SDK 자동 재시도) 에서 최대 ~20초 대기하다가 마지막에 성공한 케이스로, 코드 로직 자체보다는 downstream 지연 + 요청 단일 스레드에 직렬로 묶인 다수의 외부 호출이 결합돼 25.4초라는 tail latency 를 만든 것으로 판단된다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/bims_controller.rb:65 — check_uploading action.
• Delegates to: app/repositories/bim_repository.rb:316 — BimRepository#check_uploading(params).
• Sub-calls:
  • app/models/concerns/resourcable/bim.rb:24 — check_resource_uploading — S3 HeadObject × 4.
  • app/models/concerns/storagable/resource.rb:163 — Resource#check_uploading — actual S3 IO.
  • app/factories/bim_revision_factory.rb:5 — BimRevisionFactory#create! — DB INSERT.
• Failure point (latency): downstream I/O 안 어느 지점 — 로그에 함수-내 진행 로그가 없어 단일 지점 특정 불가. 인접 로그(ES timeout, MySQL LockWaitTimeout, S3 timeout) 를 근거로 downstream 계열 자체가 느렸음.

Controller entry:

def check_uploading
  @model = repository_instance.check_uploading(params)
  render_api Renderable.new({
    contents: @model
  })
end

Repository — 상태에 따라 여러 외부 호출을 직렬로 수행:

def check_uploading(params = {})
  case @model.resource_state_name
  when :uploading, :missing, :created
    unless @model.check_resource_uploading
      raise Cupix::Errors::Resource.new(code: 'RESC10000', reason: 'Resource does not uploaded')
    end

    draft_bim_revision_param = { bim_id: @model.id, state: 'draft', matching_strategy: params[:matching_strategy] }

    BimRevisionFactory.new(current_user: current_user).create!(draft_bim_revision_param)
  else
    raise Cupix::Errors::InvalidState.new(code: 'STAT10000', reason: "Invalid resource_state: #{@model.resource_state}")
  end

  @model
end

S3 확인 로직 — 한 요청에서 HeadObject 를 최대 4회 호출:

def check_uploading
  _revision = self.revision
  _object = self.object(_revision + 1)

  if _object.exists?
    self.etag = _object.etag.gsub('"', '') rescue nil
    self.size = _object.size
    self.content_type = _object.content_type rescue nil

    return false if self.size.blank? || self.size.zero?

    MidasOperation.record_attachment_upload(attachment: resourcable, file_size: self.size) if resourcable.is_a?(Attachment) && MidasOperation.enabled?

    self.increase_revision
    self.done
    true

Factory — INSERT + Uuidable before_create 훅:

def create!(params = {})
  self.model = ::BimRevision.new
  self.model.state = 'draft' if params[:state] == 'draft'
  set_parent(params)
  set_forge_parameter(params) unless self.model.state_draft?
  merge_matching_strategy_to_meta!(params)
  self.model.bim = self.parent
  self.model.bim_source = self.model.bim.bim_source
  self.current_team = self.parent.team
  set_revision_version
  super
end

Uuidable.before_create_uuidable 는 UUID 로컬 생성만 수행하며 ES 조회는 하지 않는다(파라미터로 uuid: 가 오지 않는 이상). 즉 07:10~11 의 Uuidable::UuidValidator warn 로그는 이 요청과 직접 관련이 없다 — 다만 같은 시각 ES 전체가 느렸다는 신호로 사용.

Log Evidence#

Datadog 쿼리 — 대상 요청의 성공 로그 확인:

service:cupixworks-api "BimsController#check_uploading"
2026-07-17T06:00:00Z ~ 2026-07-17T08:00:00Z

결과 (트레이스 시작 07:06:57.686Z + duration 25.421s ≈ 07:07:23.107Z 에 200 로그가 정확히 매칭):

2026-07-17 16:07:23 KST  [200] PUT /api/v1/bims/20623/check_uploading (Api::V1::BimsController#check_uploading)

같은 시간대 backend/downstream 지연 근거:

service:cupixworks-api ("timed out" OR "timeout" OR "Timeout")
2026-07-17T06:30:00Z ~ 2026-07-17T07:30:00Z

핵심 발췌:

{
  "timestamp": "2026-07-17 16:10:00 KST",
  "status": "warn",
  "class": "Uuidable::UuidValidator",
  "function": "uuid_used_in_other_models?",
  "message": "ES timeout/connection failure during uuid validation. Rejecting request because uuid uniqueness could not be verified. reason: Operation timed out after 10002 milliseconds with 0 bytes received"
}

{
  "timestamp": "2026-07-17 16:15:34 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/captures/736633/check_voxels_uploading (Api::V1::CapturesController#check_voxels_uploading)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

{
  "timestamp": "2026-07-17 16:20:42 KST",
  "status": "error",
  "class": "Admin::CaptureRepository",
  "message": "Operation timed out after 10002 milliseconds with 0 bytes received"
}

Status board (bun run cli/incident-board.ts for-cluster dc0e4dfd-...) 는 이 클러스터가 열린 인시던트 2026-07-17-svc-cupixworks-api--unknown-1 (자매 클러스터 12f1df11-... 와 함께 grouping) 에 포함됨을 확인. 지난 7일간 동일 scope 에서 2026-07-15, 2026-07-13 (×2), 2026-07-10 (×3) 에 유사 degradation 이 재발했다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 관측 강화: BimRepository#check_uploading 내부에 단계별 timing/logging 추가 방향 검토. 최소한 (a) check_resource_uploading 종료 시각, (b) BimRevisionFactory.new(...).create! 종료 시각을 info 레벨로 남기면 다음 재발 시 어느 downstream 이 지연 원인인지 즉시 판별 가능.
  • 대상: app/repositories/bim_repository.rb:316-331, app/models/concerns/resourcable/bim.rb:24-34.
• AWS SDK / MySQL / Elasticsearch client timeout 값 확인: 25s 지연은 AWS SDK 기본 재시도 (3회, 지수 백오프) 로도 재현 가능. Cupix::StorageService 및 Elasticsearch client 의 open_timeout/read_timeout/retry_limit 이 실제 값인지 확인 후 SLO 에 맞춰 조정.

단기 개선 (1주 이내)#

• check_uploading 을 request-scope 에서 두 단계로 분리 검토:
  1. S3 상태 확인 (check_resource_uploading) → 응답
  2. BimRevisionFactory.create! 은 Sidekiq job 으로 후행 처리
  • 근거: 사용자는 "업로드 완료 여부" 만 알면 되고, draft revision 생성은 UI blocking 요소가 아니다. 실패 시 재시도가 용이해진다.
• check_voxels_uploading (동일 window 에서 502 반복) 과 동일한 lock 경합 여부 조사. 두 컨트롤러가 같은 resource / capture 테이블을 락킹한다면 배치 fix 로 함께 해결 가능.

장기 개선 (재발 방지)#

• Status board 가 지난 7일간 동일 svc:cupixworks-api::unknown scope 에서 6건 재발을 기록 — 서비스 전반의 tail latency 원인을 개별 클러스터가 아니라 시스템 관점 (Puma worker pool, DB connection pool, ES cluster capacity) 에서 재검토할 필요. APM p95/p99 대시보드 및 downstream 별 latency breakdown 정착 권장.
• BIM 업로드 확인 UX 재설계 — 클라이언트 폴링 or WebSocket push 로 전환하면 서버 tail latency 가 사용자 경험에 직결되지 않도록 완충 가능.

Monitoring#

writing-datadog-monitoring-queries 가이드에 맞춰 timeseries widget 에 바로 붙는 쿼리로 작성:

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::bimscontroller#check_uploading}

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

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::bimscontroller#check_uploading}.as_count()

• 알림 방향: Api::V1::BimsController#check_uploading p95 > 3s 지속 5분 → Slack 알림.
• 상관 관측: Elasticsearch client timeout 로그 빈도 (class:Uuidable::UuidValidator), ActiveRecord::LockWaitTimeout count 를 동일 대시보드에 나란히 배치.

Risk Assessment#

• Risk level: medium — 단일 요청 25s 는 사용자 실질 실패에 준하는 UX 영향, 그러나 이번 케이스는 200 응답. 반복성 관점에서 status board 에 지난주 6건 재발이 기록되어 있어 우선순위 medium 이상.
• 예상 복잡도: standard — 즉시 조치(로깅/timeout tuning) 는 trivial, 단기 개선(비동기 분리) 은 standard.