[RecordFactory] The count has reached the maximum wait count. captured_at: 2026-04-27T14:09:36+00:00

RCA: [RecordFactory] The count has reached the maximum wait count

Overview#

What Happened#

2026-04-27 15:25Z경 eu-central-1 리전에서 cupixworks-api의 POST /api/v1/captures 엔드포인트에 대한 2건의 요청이 RecordFactory의 최대 재시도 횟수(6회)를 초과하여 400 에러로 실패했다. 동일 사용자가 동일 facility(h7cit8)에서 연속으로 캡처를 생성하는 과정에서, 아직 생성되지 않은 Record를 찾기 위한 polling이 타임아웃되었다.

Quick Facts#

Field	Value
exception.class	`Cupix::Errors::Parameter`
exception.message	`Record not found with captured_at in spite of 6 retries`
top_frame	`app/factories/record_factory.rb:56`
error_code	`ARG10022`
deploy	`production-eu-central-1-20260427T1359Z0-a4578cc0-cupixworks`
env	production, eu-central-1

Affected Teams#

Team / Domain	Error Count	Impact
equans-es (Team ID 117)	2	캡처 생성 실패, 사용자가 재시도 필요

Timeline#

15:25:32Z — 첫 번째 요청(request_id: 9db1839a)이 captured_at: 2026-04-27T14:09:36+00:00에 대한 Record 검색 시작, 6회 재시도 개시
15:25:38Z — 첫 번째 요청이 최대 재시도 초과로 실패 (6.3초 소요)
15:25:40Z — 두 번째 요청(request_id: e4d9e641)이 captured_at: 2026-04-27T14:28:49+00:00에 대한 재시도 개시
15:25:46Z — 두 번째 요청도 최대 재시도 초과로 실패 (6.3초 소요)
15:28:43Z — Record(6405)가 별도 요청에 의해 생성됨 (captured_at: 2026-04-27T13:50:47)
15:31:01Z — 이후 요청에서 Record(6405)가 정상적으로 조회됨

Error Log#

Datadog Logs

text

[RecordFactory] The count has reached the maximum wait count. captured_at: 2026-04-27T14:09:36+00:00

Impact#

Service: cupixworks-api
발생 횟수: 2
최초 발생: 2026-04-27T15:25:38.763Z
최근 발생: 2026-04-27T15:25:46.767Z
영향 범위: 단일 사용자(francesca.meliado@equans.com), 단일 facility(h7cit8), eu-central-1 리전. 캡처 생성 API가 400 응답을 반환하여 모바일 앱에서 캡처 업로드가 실패. 이후 재시도 시 Record가 생성되어 복구됨.

Root Cause Summary#

RecordFactory#find_or_create_by_captured_at! 메서드는 동일 facility의 Record가 다른 요청에 의해 생성 중일 때, cache key를 확인하며 최대 6회(총 ~12.6초)까지 polling한다. 이 사례에서는 동일 사용자가 facility h7cit8에 대해 첫 번째 Record 생성 요청(captured_at: 13:50:47)이 아직 완료되지 않은 상태에서, 후속 캡처 요청(captured_at: 14:09:36, 14:28:49)이 도착했다. 후속 요청들은 cache key가 존재하여 "다른 프로세스가 생성 중"이라고 판단하고 polling에 진입했지만, 실제 Record 생성은 ~3분 후인 15:28:43Z에야 완료되어 polling 타임아웃(~12.6초)을 훨씬 초과했다. Record 생성이 지연된 이유는 같은 시간대에 eu-central-1에서 발생한 AWS Kinesis 장애(InternalFailure, Http503Error)와 관련된 인프라 불안정 때문으로 추정된다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/captures_controller.rb:41 — CapturesController#create

app/controllers/api/v1/captures_controller.rb:40-44ruby

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

  super
end

Factory delegation: app/factories/capture_factory.rb:27-30 — captured_at 파라미터가 있으면 RecordFactory로 위임

app/factories/capture_factory.rb:27-30ruby

elsif params[:captured_at].present?
  raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'facility key is required when using captured_at') if self.model.facility.nil?

  self.parent = RecordFactory.new(current_user: self.current_user).find_or_create_by_captured_at!(facility: self.model.facility, captured_at: params[:captured_at])

Polling loop: app/factories/record_factory.rb:34-63 — Record 검색 → cache key 확인 → 재시도 루프

app/factories/record_factory.rb:34-63ruby

loop do
  ActiveRecord::Base.uncached do
    record = facility.records.untrashed.where(captured_at: captured_at_date_with_timezone..captured_at_date_with_timezone + 1.days).last
  end

  if record.present?
    Cupix::Logger.info("[RecordFactory] Record(#{record.id}) found with captured_at: #{captured_at}")
    break
  end

  if Rails.cache.read(cache_key).blank?
    Cupix::Logger.info("[RecordFactory] Record not found with captured_at: #{captured_at} on facility #{facility.key}")
    break
  end

  retry_count += 1

  if retry_count >= 6
    Cupix::Logger.error("[RecordFactory] The count has reached the maximum wait count. captured_at: #{captured_at}")
    raise Cupix::Errors::Parameter.new(code: 'ARG10022', reason: "Record not found with captured_at in spite of #{retry_count} retries")
  end

  Cupix::Logger.info("[RecordFactory] Retrying to find record captured_at: #{captured_at}... (#{retry_count}/6)")

  sleep(retry_time)
  retry_time *= 2
end

Cache key 설정: app/factories/record_factory.rb:25-29 — facility key + captured_at(날짜 단위)로 cache key 생성

app/factories/record_factory.rb:25-29ruby

cache_key = {
  type: 'Record',
  captured_at: captured_at_date_with_timezone.to_s,
  facility_key: facility.key
}

Record 생성: app/factories/record_factory.rb:65-75 — cache key가 비어있으면 새 Record 생성, cache에 1분 TTL로 기록

app/factories/record_factory.rb:65-71ruby

if record.blank?
  Rails.cache.write(cache_key, true, expires_in: 1.minutes)

  new_record = self.create!({
    facility_key: facility.key,
    captured_at: captured_at.to_s
  })

Failure point: app/factories/record_factory.rb:53-56 — retry_count >= 6일 때 ARG10022 에러 발생

기대 동작: 첫 번째 요청이 Record를 생성하고, 후속 요청은 polling을 통해 ~12.6초 이내에 생성된 Record를 발견하여 정상 처리.

실제 동작: 첫 번째 요청의 Record 생성이 비정상적으로 지연(~3분)되어 polling 타임아웃을 초과. cache key의 1분 TTL이 만료된 후에도 Record가 아직 생성되지 않아, 후속 요청이 cache key 소멸 전 이미 polling 루프에 진입한 상태에서 타임아웃.

Log Evidence#

Datadog 쿼리 — 에러 로그:

text

service:cupixworks-api status:error "The count has reached the maximum wait count"

에러 로그 원문 (2건):

json

{
  "timestamp": "2026-04-27T15:25:38.763Z",
  "status": "error",
  "message": "[RecordFactory] The count has reached the maximum wait count. captured_at: 2026-04-27T14:09:36+00:00",
  "host": "ip-10-1-147-185.eu-central-1.compute.internal",
  "request_id": "9db1839a-030a-4356-8125-769121782e3f"
}

json

{
  "timestamp": "2026-04-27T15:25:46.767Z",
  "status": "error",
  "message": "[RecordFactory] The count has reached the maximum wait count. captured_at: 2026-04-27T14:28:49+00:00",
  "host": "ip-10-1-147-185.eu-central-1.compute.internal",
  "request_id": "e4d9e641-8660-4f0f-b6a1-af81da70f3df"
}

Datadog 쿼리 — 요청 트레이스:

text

service:cupixworks-api @request_id:9db1839a-030a-4356-8125-769121782e3f

요청 1 재시도 로그 (request_id: 9db1839a):

text

15:25:32.760Z [INFO] [RecordFactory] Retrying to find record captured_at: 2026-04-27T14:09:36+00:00... (1/6)
15:25:32.760Z [INFO] [RecordFactory] Retrying to find record captured_at: 2026-04-27T14:09:36+00:00... (2/6)
15:25:34.761Z [INFO] [RecordFactory] Retrying to find record captured_at: 2026-04-27T14:09:36+00:00... (3/6)
15:25:34.761Z [INFO] [RecordFactory] Retrying to find record captured_at: 2026-04-27T14:09:36+00:00... (4/6)
15:25:36.762Z [INFO] [RecordFactory] Retrying to find record captured_at: 2026-04-27T14:09:36+00:00... (5/6)
15:25:38.763Z [ERROR] [RecordFactory] The count has reached the maximum wait count. captured_at: 2026-04-27T14:09:36+00:00
15:25:38.697Z [INFO] [400] POST /api/v1/captures (Api::V1::CapturesController#create) - 6255.15ms

Datadog 쿼리 — Record 생성 타임라인:

text

service:cupixworks-api "Record(6405)"

Record(6405) 생명주기:

text

15:25:31.552Z [INFO] [RecordFactory] Record not found with captured_at: 2026-04-27T13:50:47+00:00 on facility h7cit8
15:28:41.857Z [INFO] [RecordFactory] Record not found with captured_at: 2026-04-27T13:50:47+00:00 on facility h7cit8
15:28:43.861Z [INFO] [RecordFactory] Record(6405) created with captured_at: 2026-04-27 13:50:47 UTC
15:31:01.287Z [INFO] [RecordFactory] Record(6405) found with captured_at: 2026-04-27T14:09:36+00:00
15:32:34.198Z [INFO] [RecordFactory] Record(6405) found with captured_at: 2026-04-27T14:28:49+00:00

핵심 발견: Record(6405)는 15:28:43Z에야 생성되었지만, 실패한 두 요청은 15:25:32Z~15:25:46Z에 polling을 수행. Record 생성까지 약 3분의 간격이 있어 최대 재시도 시간(~12.6초)을 훨씬 초과.

Datadog 쿼리 — 동시간대 인프라 에러:

text

service:cupixworks-api status:error

동시간대 eu-central-1 인프라 에러 (48건):

text

Aws::Kinesis::Errors::InternalFailure
Aws::Kinesis::Errors::Http503Error
Connection reset by peer - SSL_connect

이 에러들은 15:27Z경에 집중 발생하여, eu-central-1 리전 전반의 인프라 불안정이 있었음을 시사.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	Record 생성 지연으로 인한 polling 타임아웃 — 첫 요청이 Record를 생성하는 데 ~3분이 걸려 후속 요청의 12.6초 polling 윈도우를 초과	Record(6405) 생성 시각(15:28:43Z)이 실패한 요청들의 polling 시각(15:25:32-46Z)보다 3분 뒤. 로그에서 재시도 1-6회 후 타임아웃 확인.	—	Confirmed
H2	Cache key 경합 — 동시 요청 간의 cache key 충돌로 인해 중복 생성 방지 로직이 오작동	cache key는 `captured_at`(날짜 단위) + `facility_key`로 구성되어, 같은 날 같은 facility의 모든 요청이 동일 cache key 사용.	로그에서 cache key는 정상적으로 존재하여 polling에 진입. cache 오작동이 아닌 실제 생성 지연이 원인.	Rejected
H3	AWS Kinesis 장애가 Record 생성 지연의 직접 원인	동시간대 eu-central-1에서 Kinesis InternalFailure/Http503Error 48건 발생. 인프라 불안정이 DB 작업 지연에 영향.	Kinesis 에러는 15:27Z경으로 RecordFactory 에러(15:25Z)보다 약간 늦음. Record 생성 과정에서 Kinesis를 직접 호출하는 코드 경로는 확인되지 않음. 간접적 영향(전반적 인프라 부하)은 가능.	Inconclusive
H4	재시도 횟수/타임아웃이 부족 — 정상 동작이지만 polling 윈도우가 Record 생성 시간을 감당하기에 너무 짧음	최대 재시도 6회(~12.6초)인데, Record 생성이 ~3분 걸린 케이스. 정상 환경에서는 Record가 즉시 생성되어 문제 없으나, 지연 시에는 불충분.	7일간 2건만 발생하여 극히 드문 케이스. 재시도 윈도우를 대폭 늘리면 API 응답시간이 비정상적으로 길어짐.	Rejected

Fix Recommendation#

즉시 조치 (Critical)#

에러 레벨 하향 검토: app/factories/record_factory.rb:54의 Cupix::Logger.error를 warn으로 하향하는 것을 검토. 이 에러는 일시적인 타이밍 문제로 클라이언트가 재시도하면 해결되는 패턴이며, 7일간 2건으로 매우 드물게 발생. 클라이언트(Dart 모바일 앱)가 400 응답 시 재시도하므로 사용자에게 실질적 영향이 제한적.
파일: app/factories/record_factory.rb:54

단기 개선 (1주 이내)#

Cache TTL과 polling 윈도우 불일치 해소: 현재 cache TTL은 1분(expires_in: 1.minutes, line 66)이지만 polling 윈도우는 ~12.6초. cache가 만료되면 다른 요청이 중복 생성을 시도할 수 있음. cache TTL을 polling 최대 시간과 일치시키거나, cache 만료 시 즉시 생성 로직으로 전환하는 방안 검토.
파일: app/factories/record_factory.rb:66

장기 개선 (재발 방지)#

DB 레벨 동시성 제어: cache 기반 락 대신 DB advisory lock 또는 INSERT ... ON CONFLICT (Record 테이블에 unique constraint 추가)를 사용하여, 동시 요청 시에도 안전하게 Record를 생성하거나 기존 Record를 반환하는 구조로 개선. 이렇게 하면 polling 루프 자체가 불필요해짐.
비동기 Record 생성: Record 생성이 오래 걸리는 경우를 대비하여, 생성을 백그라운드 작업으로 분리하고 클라이언트에 202 Accepted를 반환하는 방식도 고려 가능.

Monitoring#

기존 에러 모니터링으로 충분하나, 빈도 증가 시 알림 추가 권장:

text

service:cupixworks-api "maximum wait count" status:error

Record 생성 소요 시간 메트릭 추가 권장: RecordFactory 내 create! 전후에 타이밍 로그를 추가하여 생성 지연 패턴을 사전 감지.

Risk Assessment#

Risk level: low
예상 복잡도: trivial (에러 레벨 하향), standard (cache TTL 조정), critical (DB 레벨 동시성 제어 리팩토링)
근거: 7일간 2건 발생, 단일 사용자/facility에 한정, 클라이언트 재시도로 자연 복구됨. eu-central-1 인프라 일시 불안정이 배경 원인으로, 재발 가능성은 낮으나 동시성 제어 구조 자체는 개선 여지가 있음.