RCA: ActiveRecord::LockWaitTimeout in SQA editing release

Overview#

이 클러스터는 cupixworks-mysql2 어댑터 이름으로 수집됐지만, 실제 발생 지점은 cupixworks-worker(tesla)의 Cupix::EditingSplitService.release_single_editing 이다. SQA(siteinsights) editing 을 split 후 :waiting 에서 :ready 로 올리는 과정에서 with_lock(SELECT ... FOR UPDATE) 이 병행 split/stamp/merge 와 경합해 lock wait timeout 이 난다. 이 예외는 코드에서 rescue 되어 backoff 재시도로 이어지며, 재시도 예산 소진 시 5분 주기 cron 이 다시 회수한다.

What Happened#

2026-08-04 최근 발생분에서 SQA editing release 워커가 Editing 행 잠금을 얻지 못해 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 로 실패했다. 워커는 이를 lock_contention 사유로 rescue 하고 backoff 재시도하며, 2회 시도 후 "Release abandoned" error 로그를 남기고 멈춘다. 멈춘 editing 은 5분 주기 release_stuck_split_editings cron 이 다시 release 큐에 넣어 회수하므로 데이터는 유실되지 않는다.

Quick Facts#

Affected Teams#

Timeline#

1. 2025-11-15 12:38 KST — Error Tracking 이슈 최초 감지 (Representative Error 는 bare Mysql2::Error::TimeoutError).
2. 2026-08-04 14:48 KST — editing 82176 lock_contention 로 2회 시도 후 abandoned.
3. 2026-08-04 15:08 KST — editing 82187 lock_contention 로 2회 시도 후 abandoned.
4. 2026-08-04 15:57 KST — 클러스터 last_seen.
5. 2026-08-04 이후 — Editing released to :ready after split info 로그로 회수 확인 (자동 복구).

Error Log#

Datadog Logs

Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

실제 최근(last_seen 근방) 발생 메시지는 Representative Error 와 다르다. Error Tracking 이 여러 변형(lock_contention, unexpected_error, empty_shell_deferred)을 한 이슈로 묶고 오래된 bare 메시지를 Representative 로 고정했다. 분석은 아래 최근 메시지 기준으로 수행했다.

Release abandoned for editing 82187 (lock_contention) after 2 attempts: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

Impact#

• Service: cupixworks-mysql2 (실제 발생: cupixworks-worker / tesla)
• 발생 횟수: 299 (여러 변형 합산)
• 최초 발생: 2025-11-15 12:38 KST
• 최근 발생: 2026-08-04 15:57 KST

Root Cause Summary#

SQA(siteinsights) editing 을 split 한 뒤 Cupix::EditingSplitService.release_single_editing 이 해당 Editing 행에 with_lock(SELECT ... FOR UPDATE) 을 걸고 :waiting → :ready 상태 전이를 원자적으로 수행한다. 같은 Editing 행을 건드리는 병행 split reconcile / stamp consolidation / merge 경로와 경합하면 InnoDB 가 innodb_lock_wait_timeout 을 초과해 Mysql2::Error::TimeoutError 를 던진다. 이 예외는 rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked 로 잡혀 _reschedule_release 가 backoff 재시도로 재큐한다. ReleaseSplitEditingWorker::MAX_TOTAL_ATTEMPTS = 3 이라 attempt 2 에서 "Release abandoned" error 로그를 남기고 fast 재시도 체인을 종료한다. 이는 종착점이 아니며, 5분 주기 release_stuck_split_editings cron 이 :waiting 에 남은 editing 을 attempt 0 으로 다시 release 큐에 넣어 회수한다. 즉 이 error 로그는 일시적 lock 경합에 대한 설계된 backstop 이며, 최근 TSLA-13736 작업이 재시도 폭주("retry storm")를 이미 제거했다.

Technical Analysis#

Code Path#

• Entry point: ReleaseSplitEditingWorker#perform → Cupix::EditingSplitService.release_single_editing
• Lock 획득 및 상태 전이: app/services/cupix/editing_split_service.rb:221 (Phase 1 row lock), :297 (Phase 3 row lock)
• Failure point: app/services/cupix/editing_split_service.rb:318 (rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked)
• Terminal error 로그: app/services/cupix/editing_split_service.rb:595 (_reschedule_release)

Phase 3 에서 gate 재확인 후 ready_state! 를 호출한다. 이 블록 전체가 with_lock 안에서 실행되어 병행 경로와 경합한다.

        editing.with_lock do
          editing.reload
          return unless editing.cycle_state_created?
          return unless editing.state_waiting?

          count = ::ElementTrace.joins(:element)
                                .where(editing_id: editing.id, purpose: PURPOSE_STATUS_UPDATE)
                                .unarchived
                                .merge(::Element.unarchived)
                                .distinct.count(:element_id)
          return if count.zero?
          return if count > MAX_ELEMENTS_PER_EDITING

          editing.ready_state!
          Cupix::Logger.info('Editing released to :ready after split',
                             class: name, function: __method__,
                             editing_id: editing.id, element_count: count, attempt: attempt)
        end

lock wait timeout 은 아래에서 lock_contention 사유로 rescue 되어 재큐된다.

      rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked => e
        _reschedule_release(
          editing,
          attempt,
          e,
          reason: 'lock_contention',
          source_editing_ids: source_editing_ids
        )

_reschedule_release 는 attempt 가 한계에 도달하면 error 로그를 남기고 종료한다. 주석이 이 로그가 종착점이 아님(cron 이 attempt 0 으로 다시 release)을 명시한다.

      def _reschedule_release(editing, attempt, error, reason:, source_editing_ids: nil)
        source_editing_ids = Array(source_editing_ids).compact.uniq
        next_attempt = attempt + 1
        if next_attempt >= ReleaseSplitEditingWorker::MAX_TOTAL_ATTEMPTS
          Cupix::Logger.error("Release abandoned for editing #{editing&.id} (#{reason}) after #{attempt} attempts: #{error.message}",
                              class: name, function: __method__,
                              editing_id: editing&.id, attempt: attempt,
                              reason: reason, source_editing_ids: source_editing_ids)
          return
        end

        delay = [30 * (2**attempt), 300].min.seconds

MAX_TOTAL_ATTEMPTS = 3 이므로 attempt 2 (next_attempt 3) 에서 "after 2 attempts" 로그가 나온다. 이는 로그 문구 "after 2 attempts" 와 일치한다.

cron safety net 은 :waiting 에서 10분 이상 정체된 editing 을 다시 release 큐에 넣는다.

            else
              # Hand the hardened release path to Sidekiq instead of running it inline:
              # ReleaseSplitEditingWorker.enqueue also applies the per-editing claim, so a
              # slow release cannot be re-armed by the next tick while it is still running.
              enqueued = ::ReleaseSplitEditingWorker.enqueue(editing.id).present?
              enqueued ? stats[:release_enqueued] += 1 : stats[:suppressed] += 1
            end

기대 동작: lock 경합은 transient 이므로 재시도/cron 으로 회수되어 editing 이 :ready 에 도달한다. 실제 동작: 로그상 회수가 정상 작동 중이며(아래 Log Evidence 참조) editing 유실 증거는 없다.

Log Evidence#

사용한 Datadog 쿼리:

status:error "lock_contention"

status:warn "Retrying release for editing"

service:cupixworks-worker "Editing released to :ready"

최근 lock_contention error 발생 (last_seen 근방):

2026-08-04 15:08:34  error  Release abandoned for editing 82187 (lock_contention) after 2 attempts: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction
2026-08-04 14:48:59  error  Release abandoned for editing 82176 (lock_contention) after 2 attempts: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction
2026-08-04 15:54:02  error  Release abandoned for editing 82179 (lock_contention) after 2 attempts: Mysql2::Error: Deadlock found when trying to get lock; try restarting transaction

동일 이슈에 묶인 다른 변형 (Representative Error 와 무관):

2026-08-04 16:47:13  error  Release abandoned for editing 37892 (unexpected_error) after 2 attempts: Elasticsearch bulk partial failure on elements
2026-08-04 16:47:09  error  Release abandoned for editing 82162 (empty_shell_deferred) after 2 attempts: empty shell is not safe to delete yet

자동 재시도 및 회수 증거 (같은 시간대):

2026-08-04 16:46:17  warn  Retrying release for editing 37905 (unexpected_error) in 60s: ...
2026-08-04 16:45:37  info  Editing released to :ready after split   (function: release_single_editing)
2026-08-04 16:25:56  info  Editing released to :ready after split   (function: release_single_editing)

Editing released to :ready after split info 로그가 반복적으로 나타나 재시도/cron 회수 경로가 실제로 editing 을 성공적으로 승격시키고 있음을 확인했다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 별도 코드 변경 불필요. 최근 발생하는 lock_contention (및 unexpected_error, empty_shell_deferred) 사유의 "Release abandoned" 는 설계된 backstop 이고 cron 이 회수하므로 데이터 무결성 문제 없음.

단기 개선 (1주 이내)#

• _reschedule_release 의 terminal 로그 레벨 재검토 (app/services/cupix/editing_split_service.rb:595). abandoned 가 종착점이 아니라 cron 이 회수한다는 점을 코드 주석이 이미 명시하므로, lock_contention 처럼 transient 이고 self-healing 인 사유에 대해서는 error 대신 warn 이 Error Tracking noise 를 줄인다. unexpected_error(Elasticsearch bulk partial failure) 는 별도 근본 원인이 있을 수 있으므로 error 유지 여부를 분리 판단할 것.
• Error Tracking 이슈 그룹핑 재검토: 하나의 이슈에 lock_contention / unexpected_error / empty_shell_deferred 가 섞여 Representative Error 가 stale 하다. 사유별로 분리하면 진짜 회귀 신호를 놓치지 않는다.

장기 개선 (재발 방지)#

• lock 경합 빈도가 상승 추세라면 SQA split 경로의 lock 획득 순서/범위를 재점검 (TSLA-13736 이 이미 lock scope 를 좁힘). 회수까지 걸리는 지연을 SLO 로 모니터링해 cron 의존이 지연을 키우지 않는지 확인.

Monitoring#

lock_contention abandoned 발생 추이:

sum:trace.rails.request.errors{service:cupixworks-worker} by {resource_name}.as_count()

editing release 성공(회수) 대비 abandoned 비율을 로그 기반으로 추적하려면 아래 log-based metric 을 신설해 timeseries widget 에 올린다:

sum:logs.editing_release.abandoned{reason:lock_contention}.as_count()

sum:logs.editing_release.ready{service:cupixworks-worker}.as_count()

두 metric 이 상수적으로 균형을 이루면(abandoned 후 ready 로 회수) self-healing 이 정상이라는 신호다. abandoned 가 ready 를 지속 초과하면 회귀로 판단해 알림한다.

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial (로그 레벨 downgrade 는 1줄 수준, 코드 로직 변경 없음)

Noise Verdict#

noise — lock_contention 으로 인한 "Release abandoned" 는 일시적 row lock 경합에 대한 설계된 backstop 이며 5분 cron 이 editing 을 자동 회수(released to :ready 로그로 확인)하므로, 코드 수정이 필요 없는 로그 노이즈다.