RCA: PullTaskWorker::perform | Lock wait timeout exceeded

Overview#

What Happened#

2026-04-23 08:17:57Z에 cupixworks-worker 서비스의 PullTaskWorker가 AwsTask ID 771599에 대해 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 에러를 발생시켰다. 동일 task에 대해 두 개의 PullTaskWorker 인스턴스가 08:15:15Z에 동시에 실행되어, 한쪽이 MySQL row lock을 획득한 상태에서 다른 쪽이 lock 대기 시간을 초과하여 실패한 것이다.

Quick Facts#

Timeline#

1. 08:04:27Z — ECS task 771599 pull 시작 (pull_started_at)
2. 08:09:01Z — Cron 배치에서 task 771599 상태 PENDING → RUNNING 업데이트
3. 08:09:07Z — Cupix::Cron::AwsTask.pull_pending가 15개 task 동시 pull (771599 포함)
4. 08:13:39Z — PullTaskWorker 1차 실행 완료 (정상, saved_changes 없음)
5. 08:14:04Z — ECS task 중지 (EssentialContainerExited)
6. 08:15:15Z — PullTaskWorker 2건이 동일 task 771599에 대해 동시 실행 (request_id: fba7f9c9..., f5345c24...)
7. 08:15:15Z — request A가 RUNNING → STOPPED 상태 변경 + save 시작 (after_save callback 포함)
8. 08:17:19Z — request A 정상 완료
9. 08:17:57Z — request B Lock wait timeout으로 실패 (약 2분 42초 대기)
10. 08:17:57Z — Error Sweeper 감지

Error Log#

Datadog Logs

PullTaskWorker::perform | error on 771599 - Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

Impact#

• Service: cupixworks-worker
• 발생 횟수: 1
• 최초 발생: 2026-04-23T08:17:57.533Z
• 최근 발생: 2026-04-23T08:17:57.533Z

단일 task(771599)에 대한 단발성 에러이다. PullTaskWorker가 rescue StandardError로 에러를 잡으므로 Sidekiq retry가 트리거되지 않으며, 이 에러 발생 시점에 request A가 이미 정상 완료하여 task 상태가 STOPPED로 반영되었기 때문에 데이터 손실은 없다. 다만 동일 시간대에 Record#flush_geo_coordinate에서도 Lock wait timeout이 2건 발생하여 DB 전반에 lock 경합이 존재했음을 시사한다.

Root Cause Summary#

동일 AwsTask(ID 771599)에 대해 두 개의 PullTaskWorker가 동시에 스케줄링되어 실행되었다. Cron job(Cupix::Cron::AwsTask.pull_pending)과 Job state machine의 after_transition any => :stopped 콜백이 각각 독립적으로 PullTaskWorker를 enqueue하면서, 같은 task에 대한 중복 실행이 발생했다. 첫 번째 worker가 pull! → fetch! → save → after_save 콜백 체인을 실행하면서 MySQL row lock을 장시간 보유했고(ECS API 호출 + run_task_stopped_callbacks의 추가 쿼리), 두 번째 worker가 같은 row에 대해 save를 시도하다가 innodb_lock_wait_timeout(기본 50초)을 초과하여 Mysql2::Error::TimeoutError가 발생했다.

Technical Analysis#

Code Path#

• Entry point: app/workers/pull_task_worker.rb:5 — perform(id) 메서드

def perform(id)
  Cupix::Logger.info("PullTaskWorker::perform | begins on #{id}", class: self.class.name, function: __method__)
  task = ::AwsTask.find_by_id(id)
  return if task.nil?

  task.pull!

  Cupix::Logger.info("PullTaskWorker::perform | done on #{id}", class: self.class.name, function: __method__, task: { task_id: task.task_id })
rescue StandardError => e
  Cupix::Logger.error("PullTaskWorker::perform | error on #{id} - #{e.message}", class: self.class.name, function: __method__, task: { task_id: task.task_id })
end

Worker는 retry: 1로 설정되어 있으나, rescue StandardError가 에러를 잡아서 로그만 남기므로 실제 retry가 발동하지 않는다.

• Lock 획득 지점: app/models/aws_task.rb:46-49 — pull! 메서드

def pull!
  self.fetch!
  self.save
end

fetch!가 ECS API를 호출하여 task 상태를 메모리에 로드하고, save가 DB에 쓸 때 MySQL이 row-level lock을 획득한다.

• Lock 장시간 보유 원인: app/models/aws_task.rb:28-30 — after_save 콜백

after_save do |task|
  job.run_task_stopped_callbacks(task.task_id) if task_stopped?
end

task_stopped?가 true이면 run_task_stopped_callbacks가 실행되며, 이 콜백이 추가 DB 쿼리를 수행한다:

def run_task_stopped_callbacks(task_id = nil)
  return if task_id.blank?

  task = aws_tasks.find_by(task_id: task_id)  # aws_tasks 테이블 조회
  # ...
  action = actions.eager_load(:command).find_by(commands: { name: command_name })  # actions + commands 조인 쿼리

  if action.present? && !action.state_completed?
    if self.stopped?
      action.abandoned_state
    else
      action.completed_state  # action 상태 변경 → 추가 UPDATE
    end
  end

  if self.jobable_type == 'Capture'
    UploadCpcLogWorker.perform_in(3.second, self.id)
  end
end

save 트랜잭션 내에서 after_save 콜백이 실행되므로, run_task_stopped_callbacks의 모든 쿼리가 동일 트랜잭션 안에서 수행된다. 이 기간 동안 row lock이 유지된다.

• 중복 스케줄링 원인 1: config/schedule.rb:31 — Cron이 2분마다 pull_pending 실행

every 2.minutes do
  # runner 'Cupix::Cron::AwsTask.pull_all'
  runner 'Cupix::Cron::AwsTask.pull_pending'
  runner 'Cupix::Cron::AwsTask.pull_blank'
end

def self.pull_pending
  res = AwsTask.pending.each(&:pull)
  Cupix::Logger.info("Task pulling with pending scope : #{res.pluck(:id)}", class: self.name, function: __method__, module: 'Cupix::Cron')
end

Cron job은 해당 task가 이미 다른 worker에 의해 처리 중인지 확인하지 않고, 직접 pull을 호출한다.

• 중복 스케줄링 원인 2: app/models/concerns/statable/job.rb:86-89 — Job 상태 전이 시 PullTaskWorker enqueue

after_transition any => :stopped do |job, transition|
  job.aws_tasks.each do |task|
    PullTaskWorker.perform_in(20.second, task.id)
  end
end

Job이 stopped 상태로 전이하면 모든 task에 대해 PullTaskWorker를 20초 후 실행하도록 enqueue한다. Cron polling과 이 콜백이 겹치면 동일 task에 대한 중복 실행이 발생한다.

• Failure point: app/workers/pull_task_worker.rb:14 — rescue StandardError에서 에러 캐치

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-worker status:error PullTaskWorker
(time range: 2026-04-23T07:17:00Z to 2026-04-23T08:47:00Z)

service:cupixworks-worker 771599
(time range: 2026-04-23T07:17:00Z to 2026-04-23T08:47:00Z)

service:cupixworks-worker "Lock wait timeout"
(time range: 2026-04-23T07:00:00Z to 2026-04-23T09:00:00Z)

동시 실행 증거 — 08:15:15.501Z에 두 개의 PullTaskWorker가 동일 task 771599에 대해 시작:

[08:15:15.501Z] [INFO] PullTaskWorker::perform | begins on 771599
  request_id: fba7f9c9820600b96234330a, pid: 3665477

[08:15:15.501Z] [INFO] PullTaskWorker::perform | begins on 771599
  request_id: f5345c2418bffb99e45bd466, pid: 3665477

Request A 정상 완료:

[08:15:15.501Z] [INFO] [aws_task_stopped] aws_task_model_id: 771599
  saved_changes: last_status: RUNNING->STOPPED, desired_status: RUNNING->STOPPED,
  stopped_reason: "Essential container in task exited", stop_code: "EssentialContainerExited"
  request_id: fba7f9c9820600b96234330a

[08:17:19.527Z] [INFO] PullTaskWorker::perform | done on 771599
  request_id: fba7f9c9820600b96234330a
  task.task_id: arn:aws:ecs:us-west-2:002596530511:task/cupix-tesla-ece/058e2bb528df4c58871f4542492eb8b3

Request B Lock timeout 실패:

[08:17:57.533Z] [ERROR] PullTaskWorker::perform | error on 771599 - Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction
  request_id: f5345c2418bffb99e45bd466
  task.task_id: arn:aws:ecs:us-west-2:002596530511:task/cupix-tesla-ece/058e2bb528df4c58871f4542492eb8b3

Request A가 08:15:15Z에 시작하여 08:17:19Z에 완료(약 2분 4초 소요). Request B는 08:15:15Z에 시작하여 08:17:57Z에 실패(약 2분 42초 대기). Request A의 save + after_save 콜백 체인이 row lock을 보유하는 동안 Request B가 동일 row에 save를 시도하여 timeout이 발생했다.

동일 시간대 다른 Lock timeout 에러:

[08:15:15.500Z] [ERROR] flush_geo_coordinate - error - message: Mysql2::Error::TimeoutError: Lock wait timeout exceeded
  class: Record, module: RecordGeoCoordinate, record.id: 124764

[08:34:17.839Z] [ERROR] flush_geo_coordinate - error - message: Mysql2::Error::TimeoutError: Lock wait timeout exceeded
  class: Record, module: RecordGeoCoordinate, record.id: 126108

동일 시간대에 Record#flush_geo_coordinate에서도 lock timeout이 발생하여 DB 전반적인 lock 경합이 있었음을 확인.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/aws_task.rb:46-49의 pull! 메서드에 pessimistic locking 추가. with_lock 또는 lock!을 사용하여 동시 접근 시 명시적으로 lock을 획득하고, lock 획득 후 fetchable? 상태를 재확인하여 이미 STOPPED된 task에 대한 불필요한 ECS API 호출을 방지.
• app/workers/pull_task_worker.rb:14에서 Mysql2::Error::TimeoutError를 별도로 rescue하여 Sidekiq retry가 가능하도록 처리. 현재는 rescue StandardError로 모든 에러를 잡아서 retry가 무력화되어 있음.

단기 개선 (1주 이내)#

• Sidekiq unique job 메커니즘 도입 (예: sidekiq-unique-jobs gem)하여 동일 task ID에 대한 중복 enqueue를 방지. PullTaskWorker와 StopTaskWorker 모두에 적용.
• app/models/aws_task.rb:28-30의 after_save 콜백을 after_commit으로 변경하여 트랜잭션이 커밋된 후에 콜백이 실행되도록 하면 lock 보유 시간을 단축할 수 있음. 단, run_task_stopped_callbacks가 트랜잭션 내에서 실행되어야 하는 요구사항이 없는지 확인 필요.

장기 개선 (재발 방지)#

• Cron job(Cupix::Cron::AwsTask.pull_pending)이 직접 pull을 호출하는 대신 PullTaskWorker를 enqueue하도록 변경하고, unique job 제약으로 중복을 방지하는 구조로 전환.
• pull! 메서드 내에서 ECS API 호출(fetch!)과 DB 저장(save)을 분리하여, DB lock 보유 시간을 최소화. ECS 응답을 먼저 받은 후 짧은 트랜잭션으로 업데이트하는 패턴 적용.

Monitoring#

• Lock wait timeout 에러 빈도를 추적하는 Datadog 모니터 설정:

service:cupixworks-worker "Lock wait timeout"

• PullTaskWorker 중복 실행 감지를 위한 로그 기반 메트릭:

service:cupixworks-worker PullTaskWorker "begins on" | stats count by @message group by 5m

• MySQL innodb_row_lock_waits 메트릭 모니터링으로 전반적 lock 경합 추세 파악.

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 단발성 에러이며 request A가 이미 정상 완료하여 데이터 손실 없음. 다만 Cron과 state transition 콜백의 중복 스케줄링 패턴은 구조적으로 재발 가능하므로 unique job 도입이 권장됨.