RCA: CreateCaptureIntelligenceJob#run | Mysql2::Error::TimeoutError: Lock wait timeout exceeded

Overview#

What Happened#

2026-08-05 04:56 KST, production cupixworks-worker (tesla)에서 editing publish 후속 처리 중 CreateCaptureIntelligenceJob#run이 Mysql2::Error::TimeoutError: Lock wait timeout exceeded로 1건 실패했다. Capture 748910의 editing 확정(editing_ready→editing_done) 이후 같은 captures row 748910 을 여러 worker/API 경로가 동시에 갱신하는 상황에서, job 의 queued_summary_state 상태 전이 UPDATE 가 InnoDB row lock 을 약 52초 대기하다 timeout 되었다. 에러는 rescue로 포착되어 job 은 false를 반환했고 프로세스 crash 는 없었으나, 해당 Capture 의 summary_state가 queued로 전이되지 못하는 기능적 누락이 남는다. 여기서 spacetime 1523661 은 lock 을 잡힌 row 가 아니라 Capture 가 속한 상위 그룹(captures.spacetime_id FK)이자 agent 로 전달되는 참조값이다 (아래 "spacetime 이 왜 엮이는가" 참조).

Quick Facts#

Affected Teams#

Timeline#

1. 2026-08-05 04:54:08 KST — editing_entity 1983936 (editing_id 1348459) 상태 ready→done, Capture 748910 editing_ready→editing_done (req b1c4986df503a12235690b83)
2. 2026-08-05 04:54:14–16 KST — after_done_editing_state 후속 처리: run_3d_reconstruction (job 1252197), CaptureInvoker#create_3d_reconstruction
3. 2026-08-05 04:54:18–20 KST — run_analysis 트리거, 별도 worker AnalyzePanoWorker#perform on 748910 (req 33bb84da...) 동시 시작
4. 2026-08-05 04:54:22 KST — CaptureInvoker#create_capture_intelligence job 1252198 생성, Capture#run_capture_intelligence 실행
5. 2026-08-05 04:55:02 KST — 또 다른 경로 Capture#update_associated_sitetracks (req 0e01edd1...) 및 #update_associated_deviations (req c2ce467b...) 가 같은 Capture 748910 갱신
6. 2026-08-05 04:55:18 KST — CreateCaptureIntelligenceJob#send_message SQS FIFO 전송 완료 (spacetime_id 1523661)
7. 2026-08-05 04:56:10 KST — CreateCaptureIntelligenceJob#run의 queued_summary_state UPDATE 가 lock 대기 ~52초 후 Lock wait timeout → rescue → job false 반환
8. 2026-08-05 04:56:11 / 04:57:03 KST — 같은 Capture 에 대한 API PUT /captures/748910/meta/prop [502] (동일 경합)
9. 2026-08-05 04:57:30–32 KST — 경합 해소, 이후 PUT /captures/748910 [200] 정상화

Error Log#

Datadog Logs

CreateCaptureIntelligenceJob#run | error: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

Impact#

• Service: cupixworks-worker (tesla)
• 발생 횟수: 1 (14일 창 내 유일 발생)
• 최초 발생: 2026-08-05 04:56 KST
• 최근 발생: 2026-08-05 04:56 KST

기능 영향은 제한적이다. send_message가 먼저 성공(04:55:18)해 SQS FIFO 큐에는 capture intelligence agent 작업이 이미 들어갔고, 실패한 것은 그 뒤의 queued_summary_state DB 전이뿐이다. 다만 이 전이 누락으로 Capture 748910 의 summary_state가 queued로 올라가지 못한다. 또한 같은 lock 경합이 API 측 PUT /api/v1/captures/748910/...를 두 차례 502 로 만들어 사용자 요청도 잠시 실패했다. 경합은 약 1분 내 자연 해소되었다.

Root Cause Summary#

editing publish 확정 후 tesla worker 는 하나의 트리거(after_done_editing_state)에서 3D reconstruction, analysis, capture intelligence 를 연쇄적으로 시작하며, 이들이 모두 같은 captures row 748910 를 짧은 시간 안에 반복 갱신한다 (spacetime 1523661 은 이 capture 의 상위 그룹 FK 이자 agent 참조값일 뿐 경합 row 가 아니다). 여기에 AnalyzePanoWorker, update_associated_sitetracks, update_associated_deviations 등 별도 worker 및 사용자 API 요청까지 동일 row 를 동시에 UPDATE 하면서 InnoDB row-lock 경합이 발생했다. CreateCaptureIntelligenceJob#run은 after_commit :run 콜백으로 자신의 트랜잭션에서 queued_summary_state 상태 전이(=captures row UPDATE)를 수행하는데, 선행 트랜잭션이 잡은 lock 이 풀리길 innodb_lock_wait_timeout(약 50초) 동안 기다리다 timeout 되었다. 근본 원인은 특정 코드 결함이 아니라 동시 쓰기 경합에 대한 복원력(retry) 부재다. tesla 는 인접 경로(assign_editing_to_editing_entity, with_deadlock_retry, TaskSyncWorker)에 이미 lock-wait/deadlock retry 를 적용하고 있으나, 이 job 의 상태 전이 경로에는 동일 wrapper 가 누락되어 있다.

Technical Analysis#

Code Path#

• Entry point: editing 확정 콜백 after_done_editing_state :run_capture_intelligence

after_done_editing_state :run_capture_intelligence, if: :run_capture_intelligence?
after_done_state :run_capture_intelligence, if: :run_capture_intelligence?

• 콜백이 job 을 생성 (capture_intelligence_sync.rb:66-70)

def run_capture_intelligence
  capture_invoker = CaptureInvoker.new(model: self, current_user: self.user, current_team: self.team)
  job = capture_invoker.create_capture_intelligence
  Cupix::Logger.info("'create_capture_intelligence' job(#{job.id}) run for capture #{self.id}", class: self.class.name, function: __method__)
end

• Job 생성 트랜잭션이 커밋되면 after_commit :run 이 실행됨 (job.rb:37). 즉 run은 job 생성과 별개 트랜잭션에서 동작한다.

after_commit :run, on: :create, if: :run_on_create?

• Failure point: run 이 send_message 후 queued_summary_state 상태 전이를 수행 (create_capture_intelligence_job.rb:27-35)

def run
  send_message
  self.jobable.queued_summary_state   # ← 여기서 captures row UPDATE 중 Lock wait timeout
rescue => e
  Cupix::Logger.error("CreateCaptureIntelligenceJob#run | error: #{e.message}", class: self.class.name, function: __method__)
  false
else
  true
end

• queued_summary_state는 state_machine 이벤트로, captures row 의 summary_state 컬럼을 :queued로 전이하며 (after_transition 로그 콜백만 실행, spacetime 등 다른 테이블 write 없음) 저장한다 (capture_intelligence_sync.rb:19-63). CaptureIntelligenceSync concern 은 Capture 만 include 하므로(capture.rb:73) 이 state machine 은 captures 테이블에만 존재한다.

event :queued do
  transition from: any, to: :queued
end

spacetime 이 왜 capture-intelligence job 과 엮이는가#

피드백 질문("job 생성과 spacetime 이 왜 엮여있는가")에 대한 답. spacetime 은 lock timeout 이 난 write 대상이 아니다. Capture belongs_to :spacetime 관계 때문에 세 지점에서 참조로만 등장한다.

• Spacetime 은 Capture 의 상위 그룹 컨테이너다. (team, workspace, facility, record, level) 5-튜플로 정의되고 has_many :captures 한다 (spacetime.rb:13-24). SpacetimeEntity concern 이 Capture 에 belongs_to :spacetime + captures.spacetime_id FK 를 붙이고, record_id/level_id 변경 시 Spacetime.find_or_create_by! 로 해당 그룹을 자동 연결한다 (spacetime_entity.rb:5-23). 즉 "이 capture 가 어느 층·기록 좌표에 속하는가"를 나타내는 상위 엔티티다.

belongs_to :spacetime, optional: true
before_save :set_spacetime, if: :need_to_change_spacetime?
# ...
def set_spacetime
  _spacetime = Spacetime.find_or_create_by!({ team_id:, workspace_id:, facility_id:, record_id:, level_id: })
  self.spacetime_id = _spacetime.id
end

• (1) 실행 자격 guard: capture intelligence 는 spacetime 에 소속된 capture 에만 의미가 있으므로, run_capture_intelligence? 는 spacetime_id.blank? 이면 skip 한다 (capture_intelligence_sync.rb:7). 이것이 "job 생성과 spacetime 이 엮이는" 첫 지점 — spacetime 없는 capture 는 애초에 job 이 생성되지 않는다.

{ check: ->(c) { c.spacetime_id.blank? }, reason: ->(_) { 'spacetime_id blank' } },

• (2) agent 페이로드 식별자: send_message 는 SQS 메시지에 spacetime_id: jobable.spacetime_id 를 실어 capture-intelligence-agent 에게 "어느 spacetime 의 summary 를 만드는지" 알려준다 (create_capture_intelligence_job.rb:37-43). agent 산출물(summary)이 capture 단위가 아니라 spacetime(층·기록 좌표) 단위로 집계되기 때문이다.

def send_message(message = {})
  super({
    id: jobable.id,
    spacetime_id: jobable.spacetime_id,
    type: Cupix::Tesla.launch_mode == 'CUPIXVISTA' ? 'cupixvista' : 'cupixworks'
  })
end

• (3) lock 대상은 spacetime 이 아니다: lock timeout 이 난 queued_summary_state UPDATE 는 captures.summary_state(schema captures 테이블 컬럼, db/schema.rb:1080)를 갱신한다. spacetimes 테이블에도 동명 summary_state 컬럼이 있으나(db/schema.rb:4125) 이는 SUMMARY_STATES=%w[none done error] 로 정적 검증만 되는 별개 컬럼이고(spacetime.rb:17,24) 이 job 의 전이 경로에서는 건드리지 않는다. 따라서 spacetime 1523661 은 참조/식별자일 뿐 경합 row 가 아니다.

정리하면 spacetime 이 "엮이는" 이유는 순전히 도메인 모델 구조 때문이다 — capture 는 spacetime 이라는 상위 좌표 그룹에 소속되고, capture intelligence 는 그 그룹 단위 기능이라 (실행 조건·agent 페이로드에서) spacetime_id 를 참조한다. lock 경합 자체는 captures row 748910 에서 발생하며 spacetime 과 무관하다.

기대 동작: send_message(SQS)와 queued_summary_state(DB) 가 순차 성공하여 summary_state 가 queued로 전이된다. 실제 동작: send_message는 성공(04:55:18)했으나, 뒤이은 상태 전이 UPDATE 가 동일 captures row 748910 을 잡고 있는 다른 트랜잭션의 lock 을 ~52초 대기하다 timeout(04:56:10). rescue => e가 이를 포착해 job 은 false를 반환하고 상태 전이는 롤백된다.

참고 — 동일 팀이 인접 경로에는 이미 retry 를 적용함 (발명 금지, 차용 대상):

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))
      # ... warn + sleep(delay) + retry

def create_tasks_with_lock_wait_retry(model_name, model_ids)
  # ...
rescue ActiveRecord::LockWaitTimeout => e
  if retries < LOCK_WAIT_MAX_RETRIES
    Cupix::Logger.warn("TaskSyncWorker lock wait timeout, retrying in #{2**retries}s ...")

Log Evidence#

Query 1 — 대상 에러 (전체 트레이스 재구성):

@request_id:b1c4986df503a12235690b83

동일 request_id 트레이스가 editing 확정 → 후속 job 연쇄 → lock timeout 순서를 그대로 보여준다:

[04:54:08 KST] info  update editing_entity state from ready to done. editing_entity id: 1983936 editing_id: 1348459
[04:54:14 KST] info  Capture#run_3d_reconstruction? start validation for 3D reconstruction. capture_id: 748910, editing_support: true
[04:54:16 KST] info  CaptureInvoker#create_3d_reconstruction Reconstruction job is created for capture 748910. job_id: 1252197
[04:54:22 KST] info  CaptureInvoker#create_capture_intelligence Capture intelligence job is created for capture 748910. job_id: 1252198
[04:55:18 KST] info  CreateCaptureIntelligenceJob#send_message Sending message to https://sqs.us-west-2.amazonaws.com/.../cupix-capture-intelligence-agent-production.fifo: {:id=>748910, :spacetime_id=>1523661, ...}
[04:56:10 KST] error CreateCaptureIntelligenceJob#run | error: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

send_message(04:55:18) → error(04:56:10) 간격이 약 52초로, innodb_lock_wait_timeout 기본치(~50초)와 일치한다 = row lock 대기 timeout 의 지문.

Query 2 — 동일 Capture row 동시 갱신 확인 (경합 증거):

(service:cupixworks-worker OR service:cupixworks-api) (748910 OR 1523661)

04:54–04:57 KST 창에서 서로 다른 request_id 의 여러 경로가 같은 Capture 748910 을 동시 갱신:

[04:54:20 KST] req=33bb84da... AnalyzePanoWorker#perform | begins on 748910
[04:55:02 KST] req=0e01edd1... Capture#update_associated_sitetracks Updating associated sitetracks for Capture 748910
[04:55:02 KST] req=c2ce467b... Capture#update_associated_deviations Updating associated deviations for Capture 748910
[04:56:11 KST] cupixworks-api [502] PUT /api/v1/captures/748910/meta/prop (Api::V1::CapturesController#update_meta_by_key)
[04:57:03 KST] cupixworks-api [502] PUT /api/v1/captures/748910/meta/prop (Api::V1::CapturesController#update_meta_by_key)
[04:57:30 KST] cupixworks-api [200] PUT /api/v1/captures/748910/meta/prop  (경합 해소)

API 측 502 두 건이 worker 의 lock timeout 과 같은 창에서 발생하고 그 직후 200 으로 회복된 것은, 동일 Capture row 에 대한 다중 writer 경합이 실제 원인임을 확증한다.

Query 3 — 발생 빈도:

service:cupixworks-worker status:error "CreateCaptureIntelligenceJob#run"

14일 창(2026-07-22 ~ 2026-08-05) 전체에서 1건. 산발적 저빈도 이벤트다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/jobs/create_capture_intelligence_job.rb:29 의 self.jobable.queued_summary_state 상태 전이를 lock-wait/deadlock retry wrapper 로 감싼다. 새 로직을 발명하지 말고 이미 검증된 인접 패턴을 차용한다:
  • app/models/concerns/finalization/editing_entity.rb:16-35 의 rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked + 지수 backoff + LOCK_RETRY_MAX_ATTEMPTS
  • app/workers/task_sync_worker.rb:41-55 의 create_tasks_with_lock_wait_retry
• 주의: send_message(SQS)는 retry 범위 밖에 두어야 한다. 이미 전송에 성공한 상태에서 전체 run 을 retry 하면 FIFO 메시지 중복 전송 위험이 있다. retry 는 queued_summary_state DB 전이에만 국한한다.

단기 개선 (1주 이내)#

• 현재 rescue => e가 lock timeout 을 error 레벨로 로깅하고 조용히 false를 반환하는데, retry 도입 후에도 소진되면 이 Capture 의 summary_state가 queued로 못 올라가 상태 불일치가 남는다. retry 소진 시 명시적으로 재시도 예약(예: 지연 worker 재큐) 또는 alert 를 남기도록 개선한다.
• API 측 동일 경합(PUT /api/v1/captures/{id}/... 502)은 이 job 과 원인이 같으므로, retry 도입 효과를 API 502 빈도로도 함께 모니터링한다.

장기 개선 (재발 방지)#

• editing publish 후속 처리(after_done_editing_state)가 같은 Capture row 를 3D reconstruction/analysis/capture intelligence + 부수 worker 로 짧은 시간에 반복 UPDATE 하는 구조 자체를 재검토한다. 상태 전이를 배치/직렬화하거나, Capture 갱신을 단일 트랜잭션 경계로 모아 경합 표면적을 줄인다 (editing_split_service.rb:769 의 "batched to avoid LockWaitTimeout" 접근과 동형).
• lock-wait/deadlock retry 를 개별 경로마다 흩뿌리는 대신 상태머신 전이 공통 지점(예: Statable 저장 경로)에 재사용 가능한 retry 유틸을 두는 것을 검토한다.

Monitoring#

• Worker 측 이 에러의 발생 추이:

service:cupixworks-worker status:error "CreateCaptureIntelligenceJob#run"

• 동일 근본원인(lock 경합)의 광역 추이 — worker + API 전반의 lock wait timeout:

(service:cupixworks-worker OR service:cupixworks-api) "Lock wait timeout exceeded"

• 같은 경합이 사용자 요청으로 새는지 (Capture 갱신 API 502):

service:cupixworks-api "captures" "/meta/prop" "[502]"

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard

14일 창 1건의 저빈도 이벤트이며 에러는 rescue 로 포착되어 프로세스 crash 는 없다. 다만 상태 전이 누락과 API 502 라는 실제 영향이 있고, 팀이 이미 채택한 retry 패턴을 그대로 차용하면 되므로 수정 위험은 낮다. FIFO 중복 전송을 피하기 위해 retry 범위를 DB 전이로 한정하는 것이 유일한 주의점이다.

Revision History#

Revision 1#

Feedback: "capture-intelligence-job 을 만드는거랑 spacetime 이랑 왜 엮여있는거야" — capture intelligence job 생성/실행 경로에 spacetime 이 왜 관여하는지, 그리고 lock timeout 과 spacetime 의 관계 설명 요청.

판정:

변경 사항:

• Overview > What Happened: "같은 Capture(spacetime 1523661) row" → "같은 captures row 748910" 로 정정 + spacetime 이 참조값임을 한 문장 추가.
• Technical Analysis > Code Path: queued_summary_state 설명을 "captures row 의 summary_state 컬럼 갱신, spacetime write 없음" 으로 정정.
• Technical Analysis > Code Path 하위에 신규 섹션 "spacetime 이 왜 capture-intelligence job 과 엮이는가" 추가 — belongs_to/has_many 관계, guard, agent 페이로드, lock 대상 구분을 code snippet(spacetime_entity.rb:5-22, capture_intelligence_sync.rb:7, create_capture_intelligence_job.rb:37-43)과 함께 설명.
• Root Cause Summary 의 "같은 Capture(spacetime) row 748910" → "같은 captures row 748910" + spacetime 은 경합 row 아님을 명시.
• Technical Analysis 의 "실제 동작" 문장의 "동일 Capture row" → "동일 captures row 748910".

추가 조사 내용:

• tesla repo: app/models/capture.rb (include 목록, belongs_to/has_many), app/models/spacetime.rb, app/models/concerns/spacetime_entity.rb, app/models/concerns/capture_intelligence_sync.rb, app/jobs/create_capture_intelligence_job.rb, app/models/job.rb#send_message, db/schema.rb (captures/spacetimes 테이블 summary_state 컬럼 위치 확인).