ES /docs

job 1035726 job_stopped_callback error - /var/app/current/vendor/bundle/ruby/3.3.0/gems/mysql2-0.5.4

RCA: job_stopped_callback MySQL2 query error

Overview#

What Happened#

2026-04-24 19:58:40 UTC에 cupixworks-api (us-west-2)에서 job 1035726의 job_stopped_callback 처리 중 MySQL2 쿼리 에러가 발생했다. Refinement 작업 완료 후 상태 전이 과정에서 깊게 중첩된 state machine 트랜잭션이 동일 레코드에 대한 lock 경합을 일으켜 MySQL innodb_lock_wait_timeout에 도달한 것으로 추정된다.

Quick Facts#

Field Value
exception.class Mysql2::Error (ActiveRecord를 통해 전파)
exception.message 로그에 exception message가 누락됨 — backtrace만 기록
top_frame mysql2/client.rb:148:in '_query'
runtime Ruby 3.3.0, Rails 7.2.2, mysql2 0.5.4, Sidekiq 7.3.9
deploy production-us-west-2-20260424T1951Z0-a4578cc0-cupixworks
env production, us-west-2

Timeline#

  1. 19:56:28 UTC — Capture 687538에 대한 refinement job 1035726 생성 및 SQS 메시지 전송
  2. 19:56:38 UTC — ECS task stopped 이벤트 수신, PUT /api/v1/jobs/1035726 호출
  3. 19:57:50 UTC — Job 1035726 state created → stopped 전이, job_stopped_callback 시작
  4. 19:58:40 UTCtouch_reviews_after_save 내 MySQL UPDATE 쿼리 실패 (콜백 시작 후 ~50초)
  5. 19:58:40 UTC — 에러가 JobCallbackWorker의 rescue 블록에서 잡히고 로깅됨, HTTP 200 반환

Error Log#

Datadog Logs

text
job 1035726 job_stopped_callback error - /var/app/current/vendor/bundle/ruby/3.3.0/gems/mysql2-0.5.4/lib/mysql2/client.rb:148:in `_query'
...
/var/app/current/app/models/concerns/stale_review/record.rb:17:in `touch_reviews_after_save'
...
/var/app/current/app/models/concerns/parent_updatable.rb:19:in `update_jobable_job_status!'
...
/var/app/current/app/models/concerns/refinementable.rb:140:in `run_refinement_postprocessor'
/var/app/current/app/models/concerns/refinementable.rb:70:in `block (3 levels) in <module:Refinementable>'
...
/var/app/current/app/models/concerns/refinementable.rb:158:in `check_refinement_on_job_stopped'
/var/app/current/app/models/concerns/jobable/capture.rb:47:in `block in job_stopped_callback'

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 1
  • 최초 발생: 2026-04-24T19:58:40.679Z
  • 최근 발생: 2026-04-24T19:58:40.679Z
  • HTTP 응답은 200을 반환했으나, refinement 에러 상태 전이 중 postprocessor job 재실행(running_state!)에 따른 부모 레코드 업데이트가 실패했다. 이로 인해 Record의 running_state, error_code 필드가 업데이트되지 않았을 수 있으며, Review의 fresh_state도 갱신되지 않았을 수 있다.

Root Cause Summary#

job_stopped_callback 처리 중 check_refinement_on_job_stoppederror_refinement_statebefore_transition to: :errorrun_refinement_postprocessor_job.running_state! 경로를 통해 깊게 중첩된 state machine 트랜잭션이 실행되었다. 외부 트랜잭션(Job stopped 전이)이 Capture/Job 행에 대한 row lock을 보유한 상태에서, 내부 트랜잭션(Job running 전이)이 ParentUpdatable#update_jobable_job_status!를 통해 동일 Record 행을 UPDATE하려 했다. stale_review/record.rb:17around_save 콜백(touch_reviews_after_save)에서 실행된 MySQL UPDATE 쿼리가 ~50초간 lock 대기 후 타임아웃되어 실패했다.

Technical Analysis#

Code Path#

1. Entry point — Job 파라미터 업데이트가 stopped 상태 전이를 트리거:

app/concerns/parameter/job.rb:52-55ruby
when 'stopped'
  raise Cupix::Errors::InvalidState.new(code: 'STAT40000', reason: 'State not changed') if @model.stopped?

  @model.stopped_state!

2. Job stopped after_transition 콜백이 JobCallbackWorker를 동기 실행:

app/models/concerns/statable/job.rb:86-93ruby
after_transition any => :stopped do |job, transition|
  job.aws_tasks.each do |task|
    PullTaskWorker.perform_in(20.second, task.id)
  end

  jid = JobCallbackWorker.perform_inline(job.id, 'job_stopped_callback')
  Cupix::Logger.info("invoke job_stopped_callback with jid: #{jid} for job #{job.id}")
end

perform_inline은 Sidekiq 큐를 거치지 않고 현재 HTTP 요청 스레드 내에서 동기적으로 실행된다. 외부 트랜잭션이 아직 커밋되지 않은 상태에서 콜백이 시작된다.

3. Capture의 job_stopped_callback에서 check_refinement_on_job_stopped 호출:

app/models/concerns/jobable/capture.rb:29-48ruby
def job_stopped_callback(job)
  run_callbacks(:job_stopped_callback) do
    if job.update_jobable_state?
      update_refinement_state
      initiate_editing_state
      start_finalization
      update(processing_finished_at: DateTime.now)
      # ...
      done_state
    end

    check_refinement_on_job_stopped(job)    # line 45
    check_reconstruction_state_on_job_stopped(job)
  end
end

4. Refinement 에러 상태 전이가 before_transition 훅을 통해 postprocessor를 재실행:

app/models/concerns/refinementable.rb:152-162ruby
def check_refinement_on_job_stopped(job)
  return unless job.kind == 'create_capture_refinement'

  reset_refinement_editing
  if job.error_code.present?
    self.refinement_error_code = job.error_code
    error_refinement_state    # line 158: refinement state machine :error 이벤트
  end

  nil
end
app/models/concerns/refinementable.rb:67-72ruby
before_transition from: any, to: :error do |model, transition|
  if model.refinement_error_code.present?
    model.event_reason_processing_failed(model) if model.respond_to?(:event_reason_processing_failed)
    model.run_refinement_postprocessor(model)    # line 70
  end
end

5. run_refinement_postprocessor가 create_capture job을 running 상태로 전이:

app/models/concerns/refinementable.rb:133-142ruby
def run_refinement_postprocessor(model)
  _job = model.jobs.where(kind: 'create_capture').last
  if _job.blank?
    Cupix::Logger.info("Capture #{id} job not found. failed to run postprocessor", ...)
    return
  end

  _job.running_state!    # line 140: 또 다른 Job state machine 전이 트리거
  run_postprocessor_agent(_job)
end

6. Job running 전이의 after_update 콜백이 부모 Record를 업데이트:

app/models/concerns/parent_updatable.rb:7-24ruby
def update_jobable_job_status!
  return if self.jobable.blank?
  return unless self.jobable.update_jobable_when_job_updated? && self.update_jobable_state?

  self.jobable.update({
    error_code: self.error_code,
    processing_status: self.processing_status,
    progress: self.progress,
    running_state: self.state
  })

  if self.has_attribute?(:record_id) && self.record_id.present?
    self.record.update({         # line 19: Record UPDATE — 여기서 around_save 트리거
      error_code: self.error_code,
      running_state: self.state
    })
  end
end

7. Failure point — Record save의 around_save 콜백에서 MySQL UPDATE 실패:

app/models/concerns/stale_review/record.rb:10-24ruby
around_save :touch_reviews_after_save, unless: :skip_touch_reviews?

def touch_reviews_after_save
  if changes.keys.include?('captured_at') && changes['captured_at'][0].present?
    self._previous_captured_at = changes['captured_at'][0]
  end

  yield    # line 17: 여기서 실제 SQL UPDATE가 실행되며 MySQL2 에러 발생

  return if saved_changes.blank?
  # ...
end

yield에서 실행되는 exec_delete (ActiveRecord의 UPDATE 쿼리)가 MySQL lock wait timeout으로 실패한다.

Log Evidence#

Datadog에서 사용한 쿼리들:

text
service:cupixworks-api status:error "job_stopped_callback"
text
service:cupixworks-api "1035726"
text
service:cupixworks-api status:error (Mysql2 OR mysql2 OR "ActiveRecord::Deadlocked" OR "ActiveRecord::LockWaitTimeout")

Job 1035726 관련 로그 타임라인 (12건):

text
19:56:28.383 [info]  Refinement job is created for capture 687538. job_id: 1035726
19:56:28.384 [info]  Sending message to SQS cupix-tesla-ece-arm: {...job: {id: 1035726}...}
19:56:38.405 [info]  [aws_task_stopped] aws_task_model_id: 776145, job_id: 1035726
19:56:38.413 [info]  [200] PUT /api/v1/jobs/1035726
19:57:50.569 [info]  [Job] state changed from created to stopped on Job 1035726
19:57:50.569 [info]  job 1035726, run job_stopped_callback
19:58:40.679 [error] job 1035726 job_stopped_callback error - mysql2/client.rb:148:in '_query'
19:58:40.704 [info]  [200] PUT /api/v1/jobs/1035726

핵심 관찰:

  • 콜백 시작(19:57:50)과 에러 발생(19:58:40) 사이 ~50초 갭 — MySQL innodb_lock_wait_timeout 기본값(50초)과 일치
  • 에러 로그에 MySQL exception message가 누락됨 — JobCallbackWorker의 rescue 블록이 e.backtrace만 기록하고 e.message를 포함하지 않음
  • 에러 발생에도 불구하고 HTTP 200 응답 — 에러가 rescue 블록에서 잡히고 전파되지 않음
  • 같은 시간대에 다른 MySQL 에러 없음 — DB 전체 장애가 아닌 특정 row lock 경합 문제
  • 최근 7일간 동일 에러 1건만 발생 — 희귀한 일회성 이벤트

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 중첩 state machine 트랜잭션으로 인한 MySQL lock wait timeout 콜백 시작~에러 간 50초 갭이 innodb_lock_wait_timeout 기본값과 일치. 스택 트레이스에서 3단계 중첩 트랜잭션 확인 (Job stopped → Refinement error → Job running). perform_inline으로 동기 실행되어 외부 트랜잭션 커밋 전에 내부 트랜잭션이 동일 행 잠금 시도 MySQL error message가 로그에 누락되어 직접 확인 불가 Confirmed
H2 MySQL 서버 전체 장애 또는 연결 끊김 에러 시점의 MySQL2 쿼리 실패 동일 시간대 다른 MySQL 에러 없음 (Datadog 검색 결과 0건). 에러 직후 25ms 이내 다른 요청 정상 처리 (200 응답) Rejected
H3 Deadlock (두 트랜잭션 간 순환 잠금 대기) 중첩 트랜잭션이 같은 테이블의 행을 잠금 Deadlock은 MySQL이 즉시 감지하여 에러를 반환하므로 50초 대기가 발생하지 않음. Deadlock이면 Mysql2::Error::Deadlock 클래스가 사용됨 Rejected
H4 touch_reviews_after_save에서 존재하지 않는 review 접근 touch_reviewsaround_saveyield 이후에 호출되는데, 에러는 yield 시점(line 17)에서 발생 에러가 review 접근이 아닌 yield (Record 자체의 SQL UPDATE) 시점에서 발생 Rejected

Fix Recommendation#

즉시 조치 (Critical)#

  1. JobCallbackWorker의 에러 로깅 개선job_callback_worker.rb:14에서 e.backtrace만 기록하고 있어 MySQL 에러 메시지(e.message, e.class)가 누락된다. 에러 메시지를 포함하도록 수정하여 향후 동일 문제 발생 시 정확한 MySQL 에러 유형을 파악할 수 있게 해야 한다.

  2. run_refinement_postprocessor_job.running_state! 호출 검토refinementable.rb:140에서 이미 stopped된 다른 job의 콜백 내에서 create_capture job을 running 상태로 전이하는 것이 의도된 동작인지 확인 필요. 이 전이가 중첩 트랜잭션의 직접적인 원인이다.

단기 개선 (1주 이내)#

  1. perform_inlineperform_async로 변경 검토statable/job.rb:91에서 JobCallbackWorker.perform_inline을 사용하여 콜백을 동기 실행하고 있다. 이를 perform_async로 변경하면 콜백이 별도 Sidekiq job으로 실행되어 트랜잭션 중첩 문제를 근본적으로 해소할 수 있다. 단, 콜백 실행 순서와 실패 시 재시도 전략에 대한 검토가 필요하다.

  2. before_transition to: :error에서 run_refinement_postprocessor 호출을 비동기로 분리refinementable.rb:70before_transition 훅에서 다른 Job의 상태 전이를 트리거하는 것은 트랜잭션 중첩의 직접적인 원인이다. 이 작업을 별도 worker로 분리하면 lock 경합을 방지할 수 있다.

장기 개선 (재발 방지)#

  1. State machine 콜백 내 중첩 전이 금지 컨벤션 — state machine의 before_transition/after_transition 훅에서 다른 모델의 state machine 전이를 직접 트리거하는 패턴을 지양하고, 비동기 worker를 통해 분리하는 컨벤션을 수립해야 한다.

  2. ParentUpdatable#update_jobable_job_status! 트랜잭션 격리parent_updatable.rb에서 여러 테이블(Capture, Record)을 개별 update() 호출로 수정하고 있다. 명시적 트랜잭션으로 감싸거나, lock 순서를 정의하여 일관성을 보장해야 한다.

Monitoring#

  • MySQL lock wait timeout 모니터링:
text
service:cupixworks-api status:error ("Lock wait timeout" OR "innodb_lock_wait_timeout" OR "Mysql2::Error")
  • job_stopped_callback 에러 모니터링:
text
service:cupixworks-api status:error "job_stopped_callback error"
  • Job 콜백 처리 시간 이상 감지 (50초 이상 소요):
text
service:cupixworks-api "job_stopped_callback" @duration:>50000

Risk Assessment#

  • Risk level: low (1건 발생, HTTP 응답은 정상, 데이터 불일치 가능성은 있으나 확인 필요)
  • 예상 복잡도: standard (에러 로깅 개선은 trivial, perform_inlineperform_async 변경은 동작 변경이 수반되어 테스트 필요)