RCA: CreateSitetrackEditingEntitiesWorker Mysql2::Error::TimeoutError on sitetrack_id 21336

Overview#

What Happened#

2026-07-16 22:31 KST, cupixworks-worker 의 CreateSitetrackEditingEntitiesWorker#perform 이 sitetrack_id=21336 처리 중 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 로 실패했다. 20초 간격으로 동일 sitetrack 에 대해 두 개의 워커가 동시에 시작(22:14:58, 22:15:18)했고, 두 번째 워커가 첫 번째 워커가 보유한 InnoDB row lock 을 획득하지 못한 채 MySQL innodb_lock_wait_timeout 에 걸린 사례이다. 첫 번째 워커는 이후 22:49:47 에 정상 종료되어 실제 편집 엔티티 생성은 완료되었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-16 22:14:58 KST — Worker A: start creating editing entities on sitetrack_id: 21336
2. 2026-07-16 22:15:18 KST — Worker B: 동일 sitetrack 대상으로 두 번째 perform 시작 (20초 후)
3. 2026-07-16 22:31:19 KST — Worker B: Mysql2::Error::TimeoutError: Lock wait timeout exceeded 로 rescue 진입, 에러 로그 기록 (start 로부터 ~16분)
4. 2026-07-16 22:49:47 KST — Worker A: end creating editing entities on sitetrack_id: 21336 정상 종료 (start 로부터 ~34분)

Error Log#

Datadog Logs

error on sitetrack_id: 21336 - Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

Impact#

• Service: cupixworks-worker
• 발생 횟수: 1
• 최초 발생: 2026-07-16 22:31 KST
• 최근 발생: 2026-07-16 22:31 KST

Blast radius 는 sitetrack_id=21336 단일 인스턴스로 국한된다. 병렬로 실행된 Worker A 가 22:49:47 에 성공적으로 편집 엔티티를 생성했으므로 최종 결과 관점에서 데이터 결손은 없다. 다만 실패한 Worker B 는 Sidekiq 의 retry: 1 정책(worker 파일 3번 라인)에 의해 1회 재시도된다.

Root Cause Summary#

동일 sitetrack_id 에 대해 CreateSitetrackEditingEntitiesWorker#perform 이 20초 간격으로 두 번 enqueue 되어 병렬 실행되었고, 두 번째 워커가 첫 번째 워커의 장기 트랜잭션이 보유한 InnoDB row lock 을 대기하다 MySQL innodb_lock_wait_timeout 에 도달해 Mysql2::Error::TimeoutError 를 던졌다. Worker 는 Redis 기반의 애플리케이션 레벨 lock(editing_assign:<facility>:<category>, editing_assign_task:<task_id>) 으로 동시성을 직렬화하도록 설계되어 있으나, sitetrack 단위(facility_id, task_id 밖의 컬럼 업데이트) 를 감싸는 lock 이 없고 Redis lock 은 ASSIGN_LOCK_WAIT_TIMEOUT = 900s 후 fail-open 되어 lock 없이 진행할 수 있다. 또한 _do_assign_editing_to_editing_entity 내부의 assign_editing_to_editing_entity 는 ActiveRecord::LockWaitTimeout / Deadlocked 만 retry 하며, worker perform 상위에서 발생한 raw Mysql2::Error::TimeoutError (예: ready_state! 상태 전이 콜백이나 _stamp_editing_id_on_elements 의 update_all 배치) 는 이 재시도 경로를 타지 않고 최상위 rescue StandardError 에서 로그만 남긴 채 소멸한다.

Technical Analysis#

Code Path#

• Entry point: app/workers/create_sitetrack_editing_entities_worker.rb:26 (perform(sitetrack_id))
• Redis 락 획득: app/workers/create_sitetrack_editing_entities_worker.rb:58-60, :113-140
• Task-scoped 락 획득: app/workers/create_sitetrack_editing_entities_worker.rb:65, :158-190
• 편집 엔티티 생성/할당: app/workers/create_sitetrack_editing_entities_worker.rb:70-73 → app/models/concerns/finalization/editing_entity.rb:16-36 (assign_editing_to_editing_entity + retry)
• Failure point (rescue): app/workers/create_sitetrack_editing_entities_worker.rb:90-91

Worker 는 병렬 실행에 대비해 두 층의 Redis lock 을 사용한다.

  ASSIGN_LOCK_TTL = 900 # seconds (15 minutes)
  ASSIGN_LOCK_WAIT_TIMEOUT = 900 # seconds (15 minutes)
  ASSIGN_LOCK_POLL_INTERVAL = 1 # second

  # Task-scoped lock: serializes editing assignment for a single task_id to close
  # the candidate-visibility race window that remains inside facility/category lock.
  TASK_LOCK_TTL = 120 # seconds
  TASK_LOCK_WAIT_TIMEOUT = 10 # seconds
  TASK_LOCK_POLL_INTERVAL = 0.5 # seconds
  TASK_LOCK_KEY_PREFIX = 'editing_assign_task:'.freeze

facility/category lock 은 sitetrack.target_id → facility_id + task.category_id 조합이므로 동일 sitetrack 자체(같은 facility/category 를 공유)에 대해서는 두 워커가 같은 키를 다투게 된다. 그러나 lock 획득 대기 상한(ASSIGN_LOCK_WAIT_TIMEOUT = 900s)이 지나면 fail-open 하도록 되어 있다.

    lock_keys.each do |key|
      deadline = Time.current + ASSIGN_LOCK_WAIT_TIMEOUT
      loop do
        if Rails.cache.redis_instance.set(key, token, nx: true, ex: ASSIGN_LOCK_TTL)
          acquired << key
          break
        end
        if Time.current >= deadline
          Cupix::Logger.warn('editing_assign lock wait timeout, proceeding without this lock',
                             class: self.class.name, function: __method__,
                             sitetrack: { id: sitetrack_id }, lock_key: key)
          break
        end
        sleep ASSIGN_LOCK_POLL_INTERVAL
      end
    end

Worker A 의 총 실행 시간은 22:14:58 → 22:49:47 로 약 34분이었기 때문에, ASSIGN_LOCK_TTL 900초(15분) 는 A 가 아직 처리 중일 때 이미 만료되어 있었다. Worker B (22:15:18 시작) 는 A 의 lock 이 TTL 만료로 사라진 뒤 자기 자신의 락을 새로 획득하고 처리를 진행했을 것으로 추정된다(Redis lock 은 SET NX 이므로 만료 후 재취득이 가능). 그 시점부터 두 워커가 같은 sitetrack 의 ElementTrace/Editing/EditingEntity 로우를 동시에 갱신하려 하면 애플리케이션 락은 무의미해지고, MySQL 레벨의 row lock 이 유일한 직렬화 수단이 된다.

핵심적으로, 편집 엔티티 할당 내부는 이미 ActiveRecord::LockWaitTimeout 를 재시도하도록 방어되어 있다.

      def assign_editing_to_editing_entity
        retries = 0
        begin
          _do_assign_editing_to_editing_entity
        rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked => e
          retries += 1
          if retries <= LOCK_RETRY_MAX_ATTEMPTS
            delay = LOCK_RETRY_BASE_DELAY * (2**(retries - 1))
            Cupix::Logger.warn("Lock timeout on editing assign, retry #{retries}/#{LOCK_RETRY_MAX_ATTEMPTS}",
                               class: self.class.name, function: __method__,
                               entity: { id: entity&.id, type: entity_type }, delay: delay)
            sleep(delay)
            retry
          else
            Cupix::Logger.error('Lock timeout on editing assign, max retries exceeded',
                                class: self.class.name, function: __method__,
                                entity: { id: entity&.id, type: entity_type })
            raise
          end
        end
      end

하지만 관측된 에러 클래스는 ActiveRecord::LockWaitTimeout 이 아니라 raw Mysql2::Error::TimeoutError 이고, 로그 위치도 rescue ActiveRecord::LockWaitTimeout 분기의 "Lock timeout on editing assign, retry ..." 메시지가 아닌 perform 최상위의 "error on sitetrack_id: ..." 이다(같은 시간대 Datadog 검색에서 retry 로그는 발견되지 않음). 이는 timeout 이 _do_assign_editing_to_editing_entity 외부, 즉 다음 중 하나에서 발생했음을 의미한다.

1. Task 루프 안에서 assign 을 감싸는 상태 전이 (line 71-72 assign_editing_to_editing_entity 자체가 after_ready_state 콜백에서 트리거되므로, ready_state! 호출 시 콜백 체인 안에서 발생 가능).
2. _stamp_editing_id_on_elements 내부의 ElementTrace/Element 배치 update_all (app/models/concerns/finalization/editing_entity.rb:432-434) — 이는 assign_editing_to_editing_entity 의 _do_... 안이지만, retry rescue 는 ActiveRecord::LockWaitTimeout 만 잡는다. 만약 하위 어댑터 계층에서 wrap 되지 않고 raw Mysql2::Error::TimeoutError 로 올라온 경우(드물지만 특정 배치/스레드 상황) 는 우회한다.
3. Task 루프 앞뒤의 task.create_editing_entity(...) (line 70) 등 새로운 EditingEntity 생성 시 인덱스 락 대기.

        editing_ids = Set.new
        uniq_task_ids.each do |task_id|
          task_lock = _acquire_task_lock(task_id, sitetrack_id)
          begin
            task = ::Task.find_by_id(task_id)
            level_id = ::Workarea.find_by_id(task.workarea_id).level_id

            editing_entity = task.create_editing_entity(sitetrack.target_id, task.category_id, task.workarea_id, level_id, element_count[task_id])
            editing_entity.assign_editing_to_editing_entity
            editing_entity.ready_state!
            editing_ids << editing_entity.editing_id if editing_entity.editing_id.present?

기대 동작: 두 워커가 동일 sitetrack 을 처리하더라도 Redis lock 이 직렬화하고, 락 없이 진행하는 fail-open 경로에서는 내부 ActiveRecord::LockWaitTimeout retry 가 흡수해 최상위 에러로 노출되지 않아야 한다. 실제 동작: Worker B 는 _do_assign_editing_to_editing_entity 외부에서 raw MySQL 락 타임아웃을 만나 retry 를 우회했고, perform 의 최상위 rescue StandardError 에서 소멸했다. Worker A 는 정상적으로 완료됐다.

Log Evidence#

Datadog query (검색 스크립트로 재현 가능):

service:cupixworks-worker "sitetrack_id: 21336"

service:cupixworks-worker "Lock wait timeout exceeded"

핵심 로그 원문 (KST 로 변환한 시각):

{"timestamp": "2026-07-16 22:14:58", "status": "info", "message": "start creating editing entities on sitetrack_id: 21336", "class": "CreateSitetrackEditingEntitiesWorker", "function": "perform"}
{"timestamp": "2026-07-16 22:15:18", "status": "info", "message": "start creating editing entities on sitetrack_id: 21336", "class": "CreateSitetrackEditingEntitiesWorker", "function": "perform"}
{"timestamp": "2026-07-16 22:31:19", "status": "error", "message": "error on sitetrack_id: 21336 - Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction", "class": "CreateSitetrackEditingEntitiesWorker", "function": "perform"}
{"timestamp": "2026-07-16 22:49:47", "status": "info", "message": "end creating editing entities on sitetrack_id: 21336", "class": "CreateSitetrackEditingEntitiesWorker", "function": "perform"}

에러 발생 시각(22:31:19) 은 Worker B start(22:15:18) 로부터 약 16분 후이다. 이는 MySQL 기본 innodb_lock_wait_timeout=50s 와 맞지 않아, 다수의 짧은 락 대기가 반복 후 최종 실패했거나(내부 retry 3회 x 지수 backoff LOCK_RETRY_BASE_DELAY=10s → 10s+20s+40s = 70s 로도 부족), 실제로는 lock 지연이 아니라 Worker A 의 대량 데이터 처리에 의해 Worker B 가 여러 단계에서 반복적으로 대기했음을 시사한다.

동일한 sitetrack 이 상위 스케줄러에서 반복 감지된 흔적 (check_pending_sitetrack 이 5분 간격으로 "Sitetrack 21336 has 1 processing captures" 를 21:40 까지 로깅) 은 있으나, 이 스케줄러가 직접 워커를 enqueue 했는지, 아니면 별도 트리거(예: 캡처 완료 이벤트 콜백) 로부터도 enqueue 되어 20초 간격의 중복 실행이 발생했는지는 이번 조사 범위에서 확정하지 못했다 — needs verification (enqueue 사이트 grep 필요).

관련 warn 로그 — 다른 시간대에 발생한 task_assign lock wait timeout, proceeding without this lock (동일 워커의 task-scoped fail-open) 이 24시간 동안 다수 관측되었다.

{"timestamp": "2026-07-16 22:01:24", "status": "warn", "message": "task_assign lock wait timeout, proceeding without this lock", "class": "CreateSitetrackEditingEntitiesWorker", "function": "_acquire_task_lock"}
{"timestamp": "2026-07-16 23:02:45", "status": "warn", "message": "task_assign lock wait timeout, proceeding without this lock", "class": "CreateSitetrackEditingEntitiesWorker", "function": "_acquire_task_lock"}

이는 Redis lock 이 이미 만성적으로 fail-open 경로를 타고 있음을 보여준다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• CreateSitetrackEditingEntitiesWorker#perform 상단에 sitetrack_id 스코프의 idempotency 게이트 추가 검토 — app/workers/create_sitetrack_editing_entities_worker.rb:26-27 지점에서 SET NX EX 형태의 sitetrack 단위 Redis lock 을 짧은 TTL(예: 60분) 로 즉시 획득하고, 획득 실패 시 조용히 반환(경고 로그만) 하도록 한다. 현재는 facility/category 조합 단위 락만 있어 동일 sitetrack 재진입을 완전히 막지 못한다. Sitetrack 은 처리 단위의 자연스러운 소유자이므로 이 층에서 중복 실행 자체를 차단하는 것이 근본 처방이다.
• rescue StandardError 를 세분화 — app/workers/create_sitetrack_editing_entities_worker.rb:90-91 에서 Mysql2::Error::TimeoutError, ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked 를 별도로 rescue 하여 warn 레벨 로 강등(중복 실행 상황은 예상되는 운영 시나리오이며 데이터 손실이 아님). 그 밖의 예외만 error 로 유지한다. 스코프를 좁혀 throttling/AWS outage/permission failure 는 여전히 error 로 남도록 유지한다.

단기 개선 (1주 이내)#

• 중복 enqueue 를 발생시키는 상위 트리거 확인 — check_pending_sitetrack 스케줄러(5분 간격) 및 캡처 완료 이벤트에서 각각 워커가 enqueue 되는지 grep 하여, 두 경로가 중복 실행을 만드는지 확정한다. 확정되면 상위 트리거 측에 Sidekiq unique job(sidekiq-unique-jobs gem) 또는 조건부 enqueue 를 도입해 큐 진입 시점에 중복을 제거한다.
• ASSIGN_LOCK_TTL 과 실제 처리 시간의 gap 재검토 — Worker A 는 34분 실행됐는데 lock TTL 은 15분이다. TTL 을 상향(예: 60분) 하거나 정기적 lock renewal(heartbeat) 을 추가해 처리 중 lock 이 사라지는 문제를 근본적으로 제거한다. TTL 상향 시 크래시/재시작으로 인한 orphan lock 대비책도 함께 설계한다.

장기 개선 (재발 방지)#

• Sitetrack 처리 상태를 DB 컬럼(예: sitetracks.processing_state, processing_started_at) 으로 승격 — Redis lock 은 캐시 저장소로 정확성 대신 성능을 우선한다. 재처리 방지의 진실 원천을 DB 상태로 옮기면 워커 재시작/네트워크 파티션에서도 idempotency 가 보장된다. check_pending_sitetrack 로직도 이 상태를 참조하도록 통합한다.
• 장시간 워커의 분해(chunking) — 34분 처리는 Sidekiq 워커로는 과도하다. sitetrack 을 task 단위 여러 서브 워커로 fan-out 하고 결과를 aggregation 하는 구조로 리팩터하면, 개별 트랜잭션 lifetime 이 짧아져 InnoDB row lock 경합 자체가 완화된다.

Monitoring#

Datadog dashboard 위젯 (timeseries) 용 쿼리:

count:cupixworks-worker.log{status:error @class:CreateSitetrackEditingEntitiesWorker "Lock wait timeout"}.as_count()

count:cupixworks-worker.log{status:warn @class:CreateSitetrackEditingEntitiesWorker "lock wait timeout, proceeding without this lock"}.as_count()

count:cupixworks-worker.log{@class:CreateSitetrackEditingEntitiesWorker @function:perform "start creating editing entities"}.as_count()

권장 알림:

• CreateSitetrackEditingEntitiesWorker 의 error 카운트가 15분에 3건 초과 시 알림.
• 동일 @sitetrack.id 에 대해 start creating editing entities 로그가 5분 내 2회 이상 발생하면 warn (중복 enqueue 조기 감지).
• editing_assign lock wait timeout, proceeding without this lock warn 이 1시간 20건 초과 시 알림(fail-open 경로 만성화 감지).

Risk Assessment#

• Risk level: medium — 이번 단일 사건의 사용자 영향은 병렬 워커가 성공했기 때문에 없으나, 동일 시간대 fail-open warn 로그가 지속적으로 발생하고 있어 락 설계가 이미 스트레스를 받고 있음을 시사한다. 특정 대규모 sitetrack 에서 두 워커가 모두 실패하는 시나리오가 발생하면 편집 파이프라인이 정체될 수 있다.
• 예상 복잡도: standard — sitetrack 스코프 idempotency 게이트 도입과 rescue 세분화는 국소적이고 검증 가능하다. TTL 상향/heartbeat 는 오퍼레이션 영향이 있으므로 별도 티켓으로 관리 권장.