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#
- 19:56:28 UTC — Capture 687538에 대한 refinement job 1035726 생성 및 SQS 메시지 전송
- 19:56:38 UTC — ECS task stopped 이벤트 수신,
PUT /api/v1/jobs/1035726호출 - 19:57:50 UTC — Job 1035726 state
created → stopped전이,job_stopped_callback시작 - 19:58:40 UTC —
touch_reviews_after_save내 MySQL UPDATE 쿼리 실패 (콜백 시작 후 ~50초) - 19:58:40 UTC — 에러가
JobCallbackWorker의 rescue 블록에서 잡히고 로깅됨, HTTP 200 반환
Error Log#
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_stopped → error_refinement_state → before_transition to: :error → run_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:17의 around_save 콜백(touch_reviews_after_save)에서 실행된 MySQL UPDATE 쿼리가 ~50초간 lock 대기 후 타임아웃되어 실패했다.
Technical Analysis#
Code Path#
1. Entry point — Job 파라미터 업데이트가 stopped 상태 전이를 트리거:
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를 동기 실행:
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 호출:
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를 재실행:
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
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 상태로 전이:
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를 업데이트:
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 실패:
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에서 사용한 쿼리들:
service:cupixworks-api status:error "job_stopped_callback"
service:cupixworks-api "1035726"
service:cupixworks-api status:error (Mysql2 OR mysql2 OR "ActiveRecord::Deadlocked" OR "ActiveRecord::LockWaitTimeout")
Job 1035726 관련 로그 타임라인 (12건):
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_reviews는 around_save의 yield 이후에 호출되는데, 에러는 yield 시점(line 17)에서 발생 |
에러가 review 접근이 아닌 yield (Record 자체의 SQL UPDATE) 시점에서 발생 |
Rejected |
Fix Recommendation#
즉시 조치 (Critical)#
-
JobCallbackWorker의 에러 로깅 개선 —job_callback_worker.rb:14에서e.backtrace만 기록하고 있어 MySQL 에러 메시지(e.message,e.class)가 누락된다. 에러 메시지를 포함하도록 수정하여 향후 동일 문제 발생 시 정확한 MySQL 에러 유형을 파악할 수 있게 해야 한다. -
run_refinement_postprocessor내_job.running_state!호출 검토 —refinementable.rb:140에서 이미 stopped된 다른 job의 콜백 내에서create_capturejob을running상태로 전이하는 것이 의도된 동작인지 확인 필요. 이 전이가 중첩 트랜잭션의 직접적인 원인이다.
단기 개선 (1주 이내)#
-
perform_inline을perform_async로 변경 검토 —statable/job.rb:91에서JobCallbackWorker.perform_inline을 사용하여 콜백을 동기 실행하고 있다. 이를perform_async로 변경하면 콜백이 별도 Sidekiq job으로 실행되어 트랜잭션 중첩 문제를 근본적으로 해소할 수 있다. 단, 콜백 실행 순서와 실패 시 재시도 전략에 대한 검토가 필요하다. -
before_transition to: :error에서run_refinement_postprocessor호출을 비동기로 분리 —refinementable.rb:70의before_transition훅에서 다른 Job의 상태 전이를 트리거하는 것은 트랜잭션 중첩의 직접적인 원인이다. 이 작업을 별도 worker로 분리하면 lock 경합을 방지할 수 있다.
장기 개선 (재발 방지)#
-
State machine 콜백 내 중첩 전이 금지 컨벤션 — state machine의
before_transition/after_transition훅에서 다른 모델의 state machine 전이를 직접 트리거하는 패턴을 지양하고, 비동기 worker를 통해 분리하는 컨벤션을 수립해야 한다. -
ParentUpdatable#update_jobable_job_status!트랜잭션 격리 —parent_updatable.rb에서 여러 테이블(Capture, Record)을 개별update()호출로 수정하고 있다. 명시적 트랜잭션으로 감싸거나, lock 순서를 정의하여 일관성을 보장해야 한다.
Monitoring#
- MySQL lock wait timeout 모니터링:
service:cupixworks-api status:error ("Lock wait timeout" OR "innodb_lock_wait_timeout" OR "Mysql2::Error")
job_stopped_callback에러 모니터링:
service:cupixworks-api status:error "job_stopped_callback error"
- Job 콜백 처리 시간 이상 감지 (50초 이상 소요):
service:cupixworks-api "job_stopped_callback" @duration:>50000
Risk Assessment#
- Risk level: low (1건 발생, HTTP 응답은 정상, 데이터 불일치 가능성은 있으나 확인 필요)
- 예상 복잡도: standard (에러 로깅 개선은 trivial,
perform_inline→perform_async변경은 동작 변경이 수반되어 테스트 필요)