FacilityPermission with id 571060 not found after 6 retries

RCA: FacilityPermission not found after 6 retries

Overview#

What Happened#

2026-05-07 16:42:34~16:42:54 UTC 사이에 cupixworks-worker의 SavePartialJsonToFileWorker가 FacilityPermission ID 571060, 571062, 571071, 571073을 찾지 못하는 에러가 5회 발생했다. 각 worker는 최대 6회 exponential backoff retry (총 ~6.3초) 후 실패했다. 이는 after_commit on: :create 콜백으로 enqueue된 DataWareHouse partial JSON 생성 worker가 실행 시점에 해당 레코드가 이미 삭제된 상태였기 때문이다.

Quick Facts#

Field	Value
exception.class	(No exception raised — worker logs error and returns false)
exception.message	`FacilityPermission with id 571060 not found after 6 retries`
top_frame	`app/workers/save_partial_json_to_file_worker.rb:57`
env	production, us-west-2

Timeline#

2026-05-07T16:42:28Z — SavePartialJsonToFileWorker 시작, FacilityPermission 571060에 대한 첫 retry
2026-05-07T16:42:34Z — 6회 retry 실패 후 error 로그 기록 (ID 571060)
2026-05-07T16:42:40Z — ID 571062 동일 에러 발생 (2건)
2026-05-07T16:42:54Z — ID 571071, 571073 동일 에러 발생
2026-05-08 — Error-sweeper 클러스터 수집 및 RCA 수행

Error Log#

Datadog Logs

text

FacilityPermission with id 571060 not found after 6 retries

Impact#

Service: cupixworks-worker
발생 횟수: 5
최초 발생: 2026-05-07T16:42:34.046Z
최근 발생: 2026-05-07T16:42:54.058Z
비즈니스 영향: DataWareHouse partial JSON 파일이 생성되지 않아 데이터 파이프라인에서 해당 FacilityPermission의 (created) 이벤트가 누락된다. 그러나 해당 레코드는 이미 삭제된 상태이므로, 최종 데이터 상태에는 영향이 없다 (이후 (destroyed) 이벤트가 별도로 직접 처리됨).

Root Cause Summary#

FacilityPermission 레코드가 생성된 후 after_commit on: :create 콜백이 SavePartialJsonToFileWorker를 enqueue하지만, worker가 실행되기 전에 해당 레코드가 삭제되는 race condition이 root cause이다. FacilityPermission은 하위 permission(ReviewPermission, AnnotationLayerPermission 등)의 before_create 콜백에서 자동 생성되는데, 이 FacilityPermission이 WorkspacePermission의 dependent: :destroy 또는 FacilityPermission#cleanup_parent_access_only_permissions 등에 의해 즉시 삭제될 수 있다. Worker의 6회 retry (총 ~6.3초)가 모두 실패한 것은 레코드가 일시적 지연이 아닌 영구적 삭제 상태임을 의미한다.

Technical Analysis#

Code Path#

Entry point: app/models/concerns/data_ware_house/partial_json.rb:6 — after_commit :save_partial_json_to_file_as_created, on: :create
Enqueue: app/models/concerns/data_ware_house/partial_json.rb:70 — SavePartialJsonToFileWorker.perform_async
Worker start: app/workers/save_partial_json_to_file_worker.rb:7 — def perform(class_name, id, options_json)
Retry loop: app/workers/save_partial_json_to_file_worker.rb:41-54
Failure point: app/workers/save_partial_json_to_file_worker.rb:56-59

app/models/concerns/data_ware_house/partial_json.rb:6-9ruby

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

save_partial_json_to_file_as_created는 worker를 enqueue하지만, save_partial_json_to_file_as_destroyed는 직접 generate_and_save_partial_json을 호출한다:

app/models/concerns/data_ware_house/partial_json.rb:39-48ruby

def save_partial_json_to_file_as_created
  if $FORWARD_DATA_CHANGES != true
    Cupix::Logger.debug('Data changes forwarding is disabled', class: self.class, module: 'DataWareHouse', function: 'save_partial_json_to_file_as_created')
    return nil
  end

  Cupix::Logger.debug('Changed data will be forwarded in worker', class: self.class, module: 'DataWareHouse', function: 'save_partial_json_to_file_as_created', id: self.id)

  save_partial_json_to_file_in_worker(operation: '(created)', all_data: true, timestamp: current_timestamp)
end

Worker의 retry 로직:

app/workers/save_partial_json_to_file_worker.rb:41-59ruby

$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", class: self.class, function: 'perform')
    sleep(delay)
    next
  else
    break
  end
end

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

FacilityPermission은 WorkspacePermission에 dependent: :destroy로 연결되어 있어, WorkspacePermission 삭제 시 cascade로 삭제된다:

app/models/workspace_permission.rb:12ruby

has_many :facility_permissions, dependent: :destroy

하위 permission의 before_create에서 자동 생성되는 패턴:

app/models/review_permission.rb:19-31ruby

def create_facility_permission
  facility_permission = ::FacilityPermission.find_by(facility_id: review.facility_id, accessor: accessor)

  if facility_permission.nil?
    facility_permission = ::FacilityPermission.create!(
      facility_id: review.facility_id,
      accessor: accessor,
      permission: 1
    )
  end

  self.facility_permission = facility_permission
end

Log Evidence#

Datadog 검색 쿼리:

text

service:cupixworks-worker "FacilityPermission" "571060"
Time: 2026-05-07T15:42:00Z to 2026-05-07T17:42:00Z

ID 571060에 대한 완전한 retry 시퀀스:

json

{"timestamp": "2026-05-08 01:42:28 KST", "status": "warn", "message": "Retry 1 - FacilityPermission with id 571060 not found, retrying in 0.1 seconds", "class": "SavePartialJsonToFileWorker"}
{"timestamp": "2026-05-08 01:42:28 KST", "status": "warn", "message": "Retry 2 - FacilityPermission with id 571060 not found, retrying in 0.2 seconds", "class": "SavePartialJsonToFileWorker"}
{"timestamp": "2026-05-08 01:42:28 KST", "status": "warn", "message": "Retry 3 - FacilityPermission with id 571060 not found, retrying in 0.4 seconds", "class": "SavePartialJsonToFileWorker"}
{"timestamp": "2026-05-08 01:42:28 KST", "status": "warn", "message": "Retry 4 - FacilityPermission with id 571060 not found, retrying in 0.8 seconds", "class": "SavePartialJsonToFileWorker"}
{"timestamp": "2026-05-08 01:42:30 KST", "status": "warn", "message": "Retry 5 - FacilityPermission with id 571060 not found, retrying in 1.6 seconds", "class": "SavePartialJsonToFileWorker"}
{"timestamp": "2026-05-08 01:42:30 KST", "status": "warn", "message": "Retry 6 - FacilityPermission with id 571060 not found, retrying in 3.2 seconds", "class": "SavePartialJsonToFileWorker"}
{"timestamp": "2026-05-08 01:42:34 KST", "status": "error", "message": "FacilityPermission with id 571060 not found after 6 retries", "class": "SavePartialJsonToFileWorker"}

동일 시간대에 FacilityPermission destroy 관련 cleanup 활동이 User(43677)에 대해 확인됨:

text

service:cupixworks-worker "[Permission]" "destroy" OR "Cleanup"
Time: 2026-05-07T16:30:00Z to 2026-05-07T16:50:00Z

json

{"timestamp": "2026-05-08 01:39:16 KST", "status": "info", "message": "[Permission][Cleanup] FacilityPermission destroyed. Checking parent permissions for accessor User(43677)"}
{"timestamp": "2026-05-08 01:37:48 KST", "status": "info", "message": "[Permission][Cleanup] FacilityPermission destroyed. Checking parent permissions for accessor User(43677)"}
{"timestamp": "2026-05-08 01:36:57 KST", "status": "info", "message": "[Permission][Cleanup] FacilityPermission destroyed. Checking parent permissions for accessor User(45866)"}

동시에 User 31969에 대한 Facility 20509 permission flush 활동:

text

service:cupixworks-api "permissions" status:info
Time: 2026-05-07T16:40:00Z to 2026-05-07T16:43:00Z

json

{"timestamp": "2026-05-08 01:42:50 KST", "status": "info", "message": "Flush cached permissions By User for User 31969 on Facility 20509"}
{"timestamp": "2026-05-08 01:42:52 KST", "status": "info", "message": "Flush cached permissions By User for User 31969 on Review 70554"}
{"timestamp": "2026-05-08 01:42:52 KST", "status": "info", "message": "Flush cached permissions By User for User 31969 on AnnotationLayer 44073"}
{"timestamp": "2026-05-08 01:42:52 KST", "status": "info", "message": "Flush cached permissions By User for User 31969 on Level 83378"}

이 패턴은 permission restructuring이 활발히 진행되는 시간대에 에러가 발생했음을 보여준다.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	FacilityPermission이 생성 후 즉시 삭제됨 (create-then-destroy race condition)	6회 retry 모두 실패 (영구 삭제 확인), 동일 시간대 Permission Cleanup 로그 다수 존재, `WorkspacePermission`의 `dependent: :destroy` 및 `FacilityPermission#cleanup_parent_access_only_permissions` 코드 경로 확인	해당 IDs의 직접적인 삭제 로그 미확인 (debug 레벨이라 미저장 가능)	Confirmed
H2	DB replica lag으로 인한 일시적 read miss	Worker가 retry 포함 ~6.3초간 조회 실패 — replica lag은 통상 수백ms 이내	6회 모두 실패한 점은 단순 lag과 불일치, 레코드가 실제 삭제된 것으로 판단	Rejected
H3	Transaction rollback으로 `after_commit`이 잘못 발동됨	—	`after_commit`은 외부 transaction이 정상 commit된 후에만 실행됨 (Rails guarantee). Rollback 시 `after_commit`은 발동하지 않음	Rejected

Fix Recommendation#

즉시 조치 (Critical)#

app/workers/save_partial_json_to_file_worker.rb:56-59
레코드를 찾을 수 없는 경우 error 대신 warn 레벨로 로그를 낮춘다. 이미 삭제된 레코드에 대한 (created) 이벤트 누락은 데이터 파이프라인에 실질적 영향이 없다 — (destroyed) 이벤트가 동기적으로 이미 처리되었기 때문.
에러가 아닌 정상적 운영 시나리오(permission lifecycle에서 create→destroy가 빠르게 일어나는 것은 예상 가능한 동작)이므로 severity를 낮추는 것이 적절하다.

단기 개선 (1주 이내)#

save_partial_json_to_file_as_created에서 worker를 enqueue할 때, 레코드의 모든 필요 데이터를 worker argument로 전달하는 방식을 검토한다. 이렇게 하면 worker가 DB를 다시 조회할 필요가 없어 race condition 자체가 사라진다.
또는, worker에서 레코드를 찾을 수 없을 때 (destroyed) 이벤트가 이미 처리되었는지 확인하는 로직을 추가하여 불필요한 retry를 방지한다.

장기 개선 (재발 방지)#

DataWareHouse 이벤트 전송 아키텍처를 재검토. after_commit 기반 비동기 처리는 레코드 lifecycle이 짧은 경우 구조적으로 race condition에 취약하다. Change Data Capture (CDC) 또는 transactional outbox 패턴으로의 전환을 고려한다.

Monitoring#

로그 레벨 변경 후: service:cupixworks-worker status:warn "not found after" "retries" 쿼리로 빈도 추적
DataWareHouse partial JSON 생성 실패율 메트릭 추가 고려:

text

service:cupixworks-worker "not found after" "retries" | stats count by @class_name

Risk Assessment#

Risk level: low
예상 복잡도: trivial (로그 레벨 변경만으로 noise 제거 가능)
데이터 정합성 영향: 없음 (삭제된 레코드의 (created) 이벤트 누락은 최종 상태에 영향 없음)