RCA: Api::V1::AssetsController#check_cover_uploading — 14.7s latency spike

Overview#

What Happened#

2026-07-21 13:11 KST, cupixworks-api (ap-southeast-2) 에서 Api::V1::AssetsController#check_cover_uploading 요청 한 건이 14,708ms 동안 처리되었다. 요청은 최종적으로 200 OK 로 응답했지만 지연은 응답 계층이 아닌 S3 HeadObject 호출 (asset 커버 이미지 존재 확인) 에서 발생한 것으로 보이며, DB 시간은 22.5ms 로 미미했다. 동일 팀·동일 세션의 서버-사이드 thumbnail agent 가 짧은 시간 안에 다수의 asset 을 순차적으로 폴링하던 중 이 스파이크가 관측되었다.

Quick Facts#

Affected Teams#

증거: Datadog 로그 필드 team.id:180, user_agent:cupix-tesla-thumbnail-agent, session_id:7bc9d1725cb4b4a13ee0e0d8fa9b7b4b297e9f6b.

Timeline#

1. 2026-07-21 13:11:11 KST — Api::V1::AssetsController#check_cover_uploading (asset key dil21ai0jn1p) 요청 시작. duration 14,708.85ms 로 완료. 본 클러스터의 대표 이벤트.
2. 2026-07-21 13:11:55 KST — 같은 세션의 다른 asset key aw5xqq3o0kyr 요청이 5,095.44ms 소요. 동일 인시던트(svc:cupixworks-api::unknown) 내 5초 초과 지연 두 건 확인.
3. 2026-07-21 13:23:39 KST 이후 — 동일 팀에서 다수의 check_cover_uploading 요청이 정상 latency (100ms 대) 로 재개됨. 지연 스파이크는 자연 소멸.

Error Log#

Datadog Traces

{
  "resource_name": "Api::V1::AssetsController#check_cover_uploading",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 14710,
  "max_ms": 14710,
  "sample_trace_id": "7330170859071061807"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (본 클러스터), 인접 5초-초과 요청 포함 시 2건
• 최초 발생: 2026-07-21 13:11 KST
• 최근 발생: 2026-07-21 13:11 KST
• 사용자 영향: 실제 사용자 대면 UI 가 아닌 서버-사이드 thumbnail agent 의 폴링 요청이 지연됨. 커버 업로드 완료 인식이 최대 ~15초 지연되어 downstream 파이프라인 (썸네일 표시) 이 그만큼 미뤄짐. 200 응답이므로 실패는 아님.

Root Cause Summary#

Api::V1::AssetsController#check_cover_uploading 는 controller → repository → model concern 을 거쳐 최종적으로 Aws::S3::Object#exists? (S3 HeadObject) 를 동기 호출한다 (app/models/concerns/coverable.rb:37). 이 요청 한 건의 총 지연 14,708ms 중 DB 시간은 22.5ms 이고 나머지는 Rails 애플리케이션 밖으로 나간 시간이며, 서비스는 S3 호출에 대해 명시적인 http_read_timeout/http_open_timeout 을 설정하지 않아 AWS Ruby SDK 기본값 (open 15s, read 60s, retry 3회) 을 사용한다 (app/services/cupix/storage_service.rb:29-36, 290-307). 서버-사이드 cupix-tesla-thumbnail-agent 가 동일 세션·팀에서 다수의 asset 을 폴링하는 도중 S3 HeadObject 응답이 일시적으로 늦어지면 (또는 초기 open 이 재시도되면) 요청 하나가 SDK retry backoff 를 그대로 흡수해 10초 이상 지연되는 구조다. 본 이벤트는 그러한 일시적 S3/네트워크 지연이 timeout 방어 없이 그대로 관측된 케이스로 판단된다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/coverable_controller.rb:4-9
• Business logic: app/repositories/concerns/coverable_repository.rb:4-13
• Downstream failure/latency point: app/models/concerns/coverable.rb:36-46 → Aws::S3::Object#exists?

Controller 는 repository 위임 후 즉시 렌더링한다:

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

Repository 는 model 상태에 따라 check_cover_uploading 을 호출한다:

def check_cover_uploading
  case @model.cover_state_name
  when :uploading, :created
    unless @model.check_cover_uploading
      raise Cupix::Errors::Resource.new(code: 'RESC10000', reason: 'Resource does not uploaded')
    end
  end

  @model
end

Model 은 cover_uploaded? 를 통해 S3 존재 여부를 조회한다:

def check_cover_uploading
  if self.cover_uploaded?
    self.uploaded_cover_state
    true
  else
    false
  end
end

def cover_uploaded?
  cover_object.exists?
end

def cover_object
  Cupix::StorageService.object(
    storage_option: storage_option,
    bucket_name: hosting_bucket_name,
    key: cover_object_key
  )
end

StorageService.object 는 Aws::S3::Object 를 반환하고 이후 .exists? 가 S3 HeadObject 호출을 발생시킨다. HTTP timeout 이 명시되지 않아 SDK 기본값을 사용한다:

def object(storage_option: nil, **kwargs)
  opts = parse_storage_option(storage_option).merge(kwargs)
  opts[:force_path_style] = true

  check_required_params(opts, %i[region bucket_name key])

  Aws::S3::Object.new(opts)
end

def parse_storage_option(storage_option)
  return {} if storage_option.nil?

  opts = {}
  opts[:region] = storage_option.s3_bucket_region
  opts[:endpoint] = storage_option.endpoint if storage_option.endpoint.present?

  if storage_option.bucket_type == 'minio'
    opts[:credentials] = Aws::Credentials.new(
      Cupix::Storage::Credential.minio[:access_key_id],
      Cupix::Storage::Credential.minio[:secret_access_key]
    )
  else
    opts[:credentials] = Aws.config[:credentials]
  end

  opts
end

기대 동작: check_cover_uploading 은 짧은 HeadObject 한 번으로 수백 ms 이내 응답. 실제 관측: 동일 팀 세션에서 대다수 요청은 <200ms 로 완료되지만 (예: 13:12:44 KST 요청 duration 112.97ms), 본 클러스터의 요청은 14,708.85ms 로 처리되어 90th~99th percentile 대비 100배 이상 벌어졌다.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api @action:check_cover_uploading @duration:>10000

시간 범위 2026-07-21T03:00:00Z ~ 2026-07-21T05:00:00Z. 결과 1건, 본 클러스터의 이벤트.

핵심 로그 (요약, 원문 필드 유지):

{
  "@timestamp": "2026-07-21T04:11:26.118Z",
  "service": "cupixworks-api",
  "controller": "Api::V1::AssetsController",
  "action": "check_cover_uploading",
  "http": { "method": "PUT", "url_details": { "path": "/api/v1/assets/dil21ai0jn1p/check_cover_uploading" }, "status_code": 200 },
  "duration": 14708.85,
  "view": 0.07,
  "db": 22.5,
  "user_agent": "cupix-tesla-thumbnail-agent",
  "team": { "domain": "endeavourgroup", "id": 180 },
  "session_id": "7bc9d1725cb4b4a13ee0e0d8fa9b7b4b297e9f6b",
  "host": { "name": "ip-10-1-19-221.ap-southeast-2.compute.internal" },
  "tags": ["region:ap-southeast-2", "env:production", "version:production-ap-southeast-2-20260721t0110z0-f2b18e95-cupixworks"]
}

인접 요청 비교:

두 스파이크가 서로 다른 API 호스트 (ip-10-1-19-221 vs ip-10-1-80-234) 에서 30초 간격으로 관측된 점은, 원인이 특정 앱 인스턴스 이슈가 아니라 그 시점의 S3/네트워크 계층 응답 지연이었음을 시사한다.

status_error 로그 존재 여부 확인:

service:cupixworks-api status:error region:ap-southeast-2

시간 범위 2026-07-21T04:00:00Z ~ 2026-07-21T04:20:00Z — 0건. 예외는 발생하지 않았고 순수 지연 클러스터.

Status board 상 동일 시간대 svc:cupixworks-api::unknown 인시던트 (2026-07-21-svc-cupixworks-api--unknown-1) 에 본 클러스터 포함 5개 클러스터가 묶여 있음 — 03:59~04:11Z 구간의 서비스 열화 창이었음을 뒷받침.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• Cupix::StorageService.client/.object 경로에 HTTP timeout 을 명시 — app/services/cupix/storage_service.rb:29-36 의 parse_storage_option 산출물에 http_open_timeout (예: 5초) 과 http_read_timeout (예: 5초) 을 추가. HeadObject 는 원래 수백 ms 안에 끝나야 하는 호출이므로 SDK 기본 60초 read timeout 은 API 요청 지연을 그대로 반영한다. 근거: duration:14708ms 중 Rails 내부는 22.6ms 뿐이며 controller 는 timeout 을 방어하지 않는다 (app/controllers/concerns/coverable_controller.rb:4-9).
• 폴링 요청 timeout 관측 지표 추가 — 현재 로그에는 duration 만 있고 S3 호출 자체의 지속 시간이 별도 지표로 남지 않아 근본 원인 판정에 시간이 소요된다.

단기 개선 (1주 이내)#

• check_cover_uploading 응답 latency SLO 설정 (예: p99 < 1s). p99 를 벗어나면 Datadog monitor 로 알림.
• thumbnail agent 폴링 백오프 검토 — 서버 측 응답이 느릴 때 재시도가 몰려 부하를 더 유발하지 않는지, agent 측 (cupix-tesla-thumbnail-agent/src/model/cpasset.ts:118-122) 의 재시도 정책 확인.
• HeadObject 우회 옵션 검토 — 커버 업로드 완료 시점을 S3 이벤트 (S3 → SNS/SQS) 또는 클라이언트의 명시적 완료 콜백으로 받고, cover_object.exists? 폴링을 fallback 으로만 두면 지연에 훨씬 강해진다.

장기 개선 (재발 방지)#

• 모든 외부 IO (S3, STS, external HTTP) 호출에 팀 전역 표준 timeout 을 강제 — 서비스 wrapper 계층에서 SDK 옵션을 주입하여 개별 호출자가 잊지 않도록 한다.
• Controller 레벨 request timeout (예: Rack::Timeout) 도입 검토 — 백그라운드 agent 폴링 요청이 절대 15초 넘게 유지되지 않도록 하드 상한을 둔다.

Monitoring#

writing-datadog-monitoring-queries 가이드에 따라 timeseries widget 에서 렌더 가능한 형태로 작성.

• check_cover_uploading p95/p99 latency (Rails request 로그의 @duration 사용):

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

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

• 5초 이상 걸린 check_cover_uploading 요청 카운트 (로그 기반):

logs("service:cupixworks-api @action:check_cover_uploading @duration:>5000").index("*").rollup("count").by("region").last("5m")

• 리전별 요청 처리량 대비 slow 비율:

logs("service:cupixworks-api @action:check_cover_uploading").index("*").rollup("count").by("region").last("5m")

알림: p99 > 3000ms 5분 지속 시 warn, > 8000ms 5분 지속 시 critical.

Risk Assessment#

• Risk level: medium — 현재는 서버-사이드 agent 폴링에만 영향이 국한되며 실패로 이어지진 않지만, 동일 취약점 (외부 IO 에 timeout 부재) 이 다른 controller/worker 에도 존재할 수 있어 재발 소지가 있다.
• 예상 복잡도: standard — timeout 옵션 추가 자체는 trivial 이나, timeout 값 결정과 회귀 테스트 (특히 재시도 후 429/5xx 시 사용자 응답 유형) 조정에 표준 작업 분량이 필요.