ES /docs

FacilityType with id 298 not found after 6 retries

RCA: FacilityType with id 298 not found after 6 retries

Overview#

What Happened#

2026-04-21 18:18:47Z ~ 18:19:05Z 사이에 cupixworks-workerSavePartialJsonToFileWorker가 FacilityType ID 298, 299, 300을 찾지 못해 6회 retry 후 error를 발생시켰다. 총 4건의 error와 24건의 warn retry 로그가 기록되었으며, 세 개의 연속된 FacilityType ID가 동시에 실패한 것으로 보아 사용자의 FacilityType 일괄 삭제 작업 중 race condition이 발생한 것으로 판단된다.

Quick Facts#

Field Value
exception.message FacilityType with id 298 not found after 6 retries
top_frame app/workers/save_partial_json_to_file_worker.rb:57
runtime Ruby (Sidekiq worker)
deploy production-us-west-2-20260421T0540Z0-299add63-cupixworks
env production, us-west-2

Timeline#

  1. 18:18:47.850Z — FacilityType 298, 299에 대한 첫 retry 시작 (Job 43456ba6..., 5bfba891...)
  2. 18:18:55.859Z — FacilityType 298 첫 번째 Job 6회 retry 후 error 기록; FacilityType 298 두 번째 Job 시작 (470beec3...)
  3. 18:18:59.864Z — FacilityType 300에 대한 retry 시작 (Job cc0ccfb4...)
  4. 18:19:01.868Z — FacilityType 298 두 번째 Job error
  5. 18:19:05.869Z — FacilityType 300 최종 error — 모든 에러 종료
  6. 2026-04-22 — Error Sweeper에서 감지, RCA 분석 수행

Error Log#

Datadog Logs

text
FacilityType with id 298 not found after 6 retries

Impact#

  • Service: cupixworks-worker
  • 발생 횟수: 4 (FacilityType 298 x2, 299 x1, 300 x1)
  • 최초 발생: 2026-04-21T18:18:55.859Z
  • 최근 발생: 2026-04-21T18:19:05.869Z
  • 사용자 영향: Data warehouse로의 FacilityType 변경 데이터 전달 실패. 삭제된 레코드의 변경 이벤트이므로 실질적 데이터 손실은 없으나, data warehouse의 FacilityType 상태가 일시적으로 동기화되지 않을 수 있음.

Root Cause Summary#

SavePartialJsonToFileWorker에서 FacilityType 레코드를 조회할 때 발생하는 race condition이 근본 원인이다. FacilityType이 .touch (update callback으로 인해 after_commit on: :update 발동)되어 SavePartialJsonToFileWorker가 Sidekiq 큐에 enqueue된 후, 해당 FacilityType이 destroy!로 삭제되면 worker가 dequeue되어 실행될 때 레코드를 찾을 수 없다. FacilityType 298, 299, 300이 동시에 실패한 점은 FacilityTypeRepository#deletecascade_delete_children 로직에 의한 일괄 삭제를 강하게 시사한다. Worker의 6회 exponential backoff retry (총 ~6.3초)는 이미 삭제된 레코드를 복구할 수 없으므로 모두 실패한다.

Technical Analysis#

Code Path#

1. Entry point — FacilityType 삭제 요청

FacilityTypeRepository#delete가 호출되면 먼저 하위 FacilityType을 재귀적으로 삭제한다:

app/repositories/facility_type_repository.rb:26-41ruby
def delete
  cascade_delete_children(@model)

  facilities_scope = ::Facility.where(facility_type_id: @model.id, team_id: @current_team&.id)
  facility_ids = facilities_scope.pluck(:id)
  if facility_ids.present?
    if @model.main_type?
      facilities_scope.update_all(facility_type_id: nil, updated_at: Time.current)
    else
      facilities_scope.update_all(facility_type_id: @model.ancestry, updated_at: Time.current)
    end
    ::Facility.bulk_operation!(facility_ids, 'update')
  end

  super  # BaseRepository#delete → model.destroy!
end

하위 타입 삭제 시 cascade_delete_children이 각 child에 대해 perform_delete!를 호출한다:

app/repositories/facility_type_repository.rb:313-326ruby
def cascade_delete_children(facility_type)
  facility_type.sub_types.each do |child|
    cascade_delete_children(child)

    facilities_scope = ::Facility.where(facility_type_id: child.id, team_id: @current_team&.id)
    facility_ids = facilities_scope.pluck(:id)
    if facility_ids.present?
      facilities_scope.update_all(facility_type_id: child.ancestry, updated_at: Time.current)
      ::Facility.bulk_operation!(facility_ids, 'update')
    end

    child.perform_delete!  # → ApplicationRecord#perform_delete! → destroy!
  end
end

2. destroy!가 트리거하는 after_commit 콜백

FacilityType은 DataWareHouse::FacilityType을 include하며, 이는 DataWareHouse::PartialJsonafter_commit 콜백을 등록한다:

app/models/concerns/data_ware_house/partial_json.rb:5-8ruby
included do
  after_commit :save_partial_json_to_file_as_created, on: :create
  after_commit :save_partial_json_to_file_as_updated, on: :update, if: :not_new_record?
  after_commit :save_partial_json_to_file_as_destroyed, on: :destroy
end

destroy 이벤트는 save_partial_json_to_file_as_destroyed를 호출하며, 이는 동기적으로 (worker 없이) 파일을 직접 생성한다:

app/models/concerns/data_ware_house/partial_json.rb:51-61ruby
def save_partial_json_to_file_as_destroyed
  if $FORWARD_DATA_CHANGES != true
    Cupix::Logger.debug('Data changes forwarding is disabled', ...)
    return nil
  end

  Cupix::Logger.debug('Changed data will be forwarded in worker', ...)
  generate_and_save_partial_json('(destroyed)', all_data: false)
end

3. Race condition 발생 지점

update 이벤트의 콜백은 비동기 worker를 enqueue한다:

app/models/concerns/data_ware_house/partial_json.rb:63-71ruby
def save_partial_json_to_file_in_worker(operation: '(updated)', all_data: false, changes: nil, timestamp: nil)
  if !all_data && changes.blank? && operation == '(updated)'
    Cupix::Logger.debug('No changes detected, skipping partial JSON generation', ...)
    return nil
  end

  SavePartialJsonToFileWorker.perform_async(self.class.name, self.id, ...)
end

FacilityType에 .touch가 호출되면 (Facility#touch_facility_type_with_ancestors 등을 통해) after_commit on: :update 콜백이 발동되어 worker가 enqueue된다. 이후 FacilityType이 삭제되면:

app/workers/save_partial_json_to_file_worker.rb:39-60ruby
model = nil

$MAX_RETRIES.times do |retries|
  model = model_class.find_by_id(id)

  if model.nil?
    delay = 0.1 * (2**retries)
    Cupix::Logger.warn("Retry #{retries + 1} - #{class_name} with id #{id} not found, retrying in #{delay} seconds", ...)
    sleep(delay)
    next
  else
    break
  end
end

if model.nil?
  Cupix::Logger.error("#{class_name} with id #{id} not found after #{$MAX_RETRIES} retries", ...)
  return false
end

4. find_by_id의 INNER JOIN 문제

Worker에서 사용하는 find_by_iddefault_joins를 통해 teams 테이블과 INNER JOIN한다:

lib/cupix/abstract/base.rb:19-21ruby
def find_by_id(id)
  default_joins(current_class).find_by(id: id)
end
app/repositories/facility_type_repository.rb:122-124ruby
def self.default_joins(record)
  record.joins(:team).select('facility_types.*, teams.id AS team_id')
end

실행되는 SQL:

sql
SELECT facility_types.*, teams.id AS team_id
FROM facility_types
INNER JOIN teams ON facility_types.team_id = teams.id
WHERE facility_types.id = 298

레코드가 삭제된 후에는 당연히 nil을 반환한다. 또한 team이 삭제된 경우에도 INNER JOIN으로 인해 nil을 반환할 수 있다.

5. 실행 흐름 요약

text
Facility 생성/수정/삭제
  → Facility#reindex_facility_types
    → FacilityType#touch (update 이벤트)
      → after_commit on: :update
        → SavePartialJsonToFileWorker.perform_async('FacilityType', 298)

[Sidekiq 큐에서 대기 중]

FacilityType 삭제 요청
  → FacilityTypeRepository#delete
    → cascade_delete_children → child.perform_delete! → destroy!
    → @model.destroy!
      → after_commit on: :destroy → 동기적 파일 생성 (정상)
      → DB에서 레코드 삭제 완료

[Worker dequeue]
  → FacilityType.find_by_id(298) → nil (이미 삭제됨)
  → 6회 retry 후 error 로그

Log Evidence#

사용한 Datadog 쿼리:

text
service:cupixworks-worker "FacilityType" "298"

시간 범위: 2026-04-21T17:18:00Z ~ 2026-04-21T18:49:00Z

Job 1 (request_id: 43456ba6ab3ba311cf635539) — FacilityType 298:

text
18:18:47.850Z [warn]  Retry 1 - FacilityType with id 298 not found, retrying in 0.1 seconds
18:18:47.851Z [warn]  Retry 2 - FacilityType with id 298 not found, retrying in 0.2 seconds
18:18:47.851Z [warn]  Retry 3 - FacilityType with id 298 not found, retrying in 0.4 seconds
18:18:49.852Z [warn]  Retry 4 - FacilityType with id 298 not found, retrying in 0.8 seconds
18:18:49.853Z [warn]  Retry 5 - FacilityType with id 298 not found, retrying in 1.6 seconds
18:18:51.856Z [warn]  Retry 6 - FacilityType with id 298 not found, retrying in 3.2 seconds
18:18:55.859Z [error] FacilityType with id 298 not found after 6 retries

Job 2 (request_id: 470beec3159927c5063d3a6f) — FacilityType 298 (재시도):

text
18:18:55.859Z [warn]  Retry 1 - FacilityType with id 298 not found, retrying in 0.1 seconds
18:18:55.860Z [warn]  Retry 2 - FacilityType with id 298 not found, retrying in 0.2 seconds
18:18:55.860Z [warn]  Retry 3 - FacilityType with id 298 not found, retrying in 0.4 seconds
18:18:57.861Z [warn]  Retry 4 - FacilityType with id 298 not found, retrying in 0.8 seconds
18:18:57.862Z [warn]  Retry 5 - FacilityType with id 298 not found, retrying in 1.6 seconds
18:18:59.865Z [warn]  Retry 6 - FacilityType with id 298 not found, retrying in 3.2 seconds
18:19:01.868Z [error] FacilityType with id 298 not found after 6 retries

동시간대 관련 에러 (같은 패턴):

text
service:cupixworks-worker status:error "FacilityType"
text
18:18:55.859Z [error] FacilityType with id 298 not found after 6 retries  (SavePartialJsonToFileWorker#perform)
18:18:55.859Z [error] FacilityType with id 299 not found after 6 retries  (SavePartialJsonToFileWorker#perform)
18:19:01.868Z [error] FacilityType with id 298 not found after 6 retries  (SavePartialJsonToFileWorker#perform)
18:19:05.869Z [error] FacilityType with id 300 not found after 6 retries  (SavePartialJsonToFileWorker#perform)

연속된 ID (298, 299, 300)가 동시에 실패한 것은 cascade_delete_children에 의한 일괄 삭제를 강하게 시사한다.

동시간대 다른 에러:

text
service:cupixworks-worker status:error

동일 시간대에 42건의 thumbnail 503 에러, 8건의 geo-coordinate TCP 연결 실패도 발생했으나, FacilityType 에러와는 직접적 관련이 없다.

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 FacilityType이 .touchdestroy!로 삭제되어 worker가 조회 실패하는 race condition 연속 ID 298/299/300 동시 실패 → cascade_delete_children 일괄 삭제 패턴 일치; after_commit on: :update가 worker를 비동기로 enqueue하는 코드 확인 (partial_json.rb:70); worker의 6회 retry 모두 nil 반환 (로그 확인) Confirmed
H2 FacilityType 레코드 자체는 존재하지만 team 삭제로 INNER JOIN이 nil 반환 find_by_idjoins(:team) 사용 (facility_type_repository.rb:122-124); INNER JOIN은 team 없으면 nil 반환 FacilityType은 validates :team_id, presence: true이므로 team_id 없이 생성 불가; 3개 ID 동시 실패는 team 삭제보다 FacilityType 직접 삭제가 더 개연성 높음; team 삭제 시 더 광범위한 에러가 예상됨 Rejected
H3 DB replication lag으로 인한 일시적 조회 실패 retry 로직이 존재하여 replication lag 대응을 의도한 것으로 보임 6.3초 동안 6회 모두 실패 — replication lag이 6초 이상 지속되는 것은 극히 드묾; 298/299/300 연속 ID 실패는 replication lag 패턴과 불일치 Rejected

Fix Recommendation#

즉시 조치 (Critical)#

SavePartialJsonToFileWorker에서 이미 삭제된 레코드에 대한 조회 실패를 error가 아닌 warn으로 처리해야 한다. 레코드 삭제 후 해당 레코드의 update worker가 실패하는 것은 정상적인 운영 시나리오이며, destroy 이벤트는 save_partial_json_to_file_as_destroyed에서 이미 동기적으로 처리되므로 data warehouse 동기화에 실제 영향이 없다.

  • 수정 파일: app/workers/save_partial_json_to_file_worker.rb:56-59
  • 방향: Cupix::Logger.errorCupix::Logger.warn으로 변경. 레코드를 찾을 수 없는 경우 error 대신 warn으로 로깅하여 불필요한 error 노이즈를 제거.

단기 개선 (1주 이내)#

Worker enqueue 전에 레코드가 destroy 상태인지 확인하는 guard를 추가하거나, after_commit on: :destroy 콜백에서 pending worker job을 무효화하는 메커니즘을 도입. 예를 들어 worker에서 operation이 (updated)인데 레코드가 없으면 조용히 skip하는 로직 (destroy 콜백이 이미 파일을 생성했으므로).

장기 개선 (재발 방지)#

DataWareHouse::PartialJson의 update 콜백이 비동기 worker를 사용하는 반면 destroy 콜백은 동기적으로 처리하는 비대칭 구조를 검토. 가능한 접근:

  • Update 콜백도 동기적으로 처리하여 race condition 원천 제거 (성능 영향 고려 필요)
  • 또는 worker에 operation 타입을 전달하여, 레코드 미발견 시 destroy 이벤트가 이미 처리되었음을 인지하고 graceful하게 종료

Monitoring#

  • FacilityType not found error가 warn으로 변경된 후에도 지속적으로 모니터링:
text
service:cupixworks-worker "not found after" "retries" status:warn
  • 비정상적으로 빈번한 발생 감지:
text
service:cupixworks-worker "not found after" "retries" status:error

Risk Assessment#

  • Risk level: low
  • 예상 복잡도: trivial
  • 근거: 삭제된 FacilityType의 update worker 실패는 data warehouse에 실질적 영향이 없음 (destroy 이벤트가 이미 동기적으로 처리됨). error → warn 변경만으로 노이즈 제거 가능.