RCA: Mysql2::Error::TimeoutError: Lock wait timeout exceeded

Overview#

What Happened#

cupixworks-api (tesla) 의 다수 write 엔드포인트(주로 PUT /api/v1/element_traces bulk)에서 MySQL InnoDB Lock wait timeout exceeded 가 발생한다. 요청은 약 50초(InnoDB innodb_lock_wait_timeout 기본값)동안 row lock 을 기다린 뒤 ActiveRecord::LockWaitTimeout 을 던지고 HTTP 502 (BG10000) 로 매핑된다. Sitetrack post-processing 이 같은 facility 의 ElementTrace row 를 동시에 대량 갱신하면서 자기 자신과 lock 경합을 일으키는 것이 주 원인이다. 16개월간 38건으로 저빈도이며 대부분 qa/regression 테스트 트래픽이다.

Quick Facts#

Affected Teams#

Timeline#

1. 2025-04-13 09:17 KST — 최초 발생 (first_seen).
2. 2026-07-30 ~ 08-04 — element_traces#bulk 502 burst 반복 (facility qinlxf, Sitetrack 처리 중).
3. 2026-08-03 15:02 KST — 최근 발생 (last_seen, cluster 기준).
4. 2026-08-04 13:40~13:46 KST — retention 창 내 최신 burst 관측 (요청당 50s db, 45건 연속).

Error Log#

Datadog Logs

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

Impact#

• Service: cupixworks-api
• 발생 횟수: 38
• 최초 발생: 2025-04-13 09:17 KST
• 최근 발생: 2026-08-03 15:02 KST

Root Cause Summary#

ActiveRecord::LockWaitTimeout 은 InnoDB row lock 경합이 innodb_lock_wait_timeout(~50s)을 초과할 때 발생한다. Sitetrack post-processing 이 활성화된 facility 에서 cupix-sitetrack-postprocessor-agent 가 PUT /api/v1/element_traces (bulk create/update/delete) 를 한 transaction 으로 실행하는 동시에, 같은 처리 파이프라인의 background 경로(Cupix::EditingSplitService 의 ElementTrace.update_all(editing_id:), TaskSyncWorker 등)가 동일한 ElementTrace row 를 갱신한다. 두 write 가 같은 row 를 서로 다른 순서로 잠그면서 bulk transaction 이 50초를 대기하다 timeout → server_error_controller.rb:18 에서 502 (BG10000) 로 매핑된다. 이 502 매핑은 팀이 의도적으로 만든 transient 처리(503 그룹에서 502 그룹으로 명시적으로 이동, :32 주석 참조)이지만, synchronous bulk 경로에는 다른 write 경로들이 이미 갖춘 lock-wait retry 가 빠져 있어 경합이 그대로 502 로 표면화된다. 근본 결함은 downstream 장애가 아니라 tesla 내부의 self-contention 과 retry 누락이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/element_traces_controller.rb:6 (include BulkableController) → bulk
• Bulk 실행: app/controllers/concerns/bulkable_controller.rb:25-45 — repository_instance.bulk(...) / factory_instance.bulk(...) 를 transaction 내에서 실행

  def bulk
    _bulked_ids = []
    _invalid_items = []
    case params[:bulk_action]
    when 'create'
      _bulked_ids, _invalid_items = factory_instance.bulk(params, current_user: @current_user, current_team: @current_team, partial_mode: true)
    when 'update', 'delete'
      _bulked_ids, _invalid_items = repository_instance.bulk(params, current_user: @current_user, current_team: @current_team, partial_mode: true)

• Lock 경합 상대(background writer): app/services/cupix/editing_split_service.rb:769-784 — 같은 facility 의 ElementTrace row 를 update_all 로 대량 갱신. 주석 자체가 LockWaitTimeout 을 피하려 batch 처리하고 있음을 명시.

      # Update ElementTrace and Element editing_id (batched to avoid LockWaitTimeout)
      et_ids = ::ElementTrace.where(task_id: task_ids, editing_id: editing.id).pluck(:id)
      et_affected_total = 0
      if et_ids.any?
        et_ids.each_slice(REASSIGN_BATCH_SIZE) do |batch|
          et_affected_total += ::ElementTrace.where(id: batch).update_all(editing_id: new_editing.id)
        end
      end

• Failure point → 502 mapping: app/controllers/concerns/server_error_controller.rb:18-20. ActiveRecord::LockWaitTimeout 은 팀이 503 그룹(:32 에 주석 처리된 라인)에서 명시적으로 502 그룹으로 이동시킨 상태다.

    rescue_from ActiveRecord::LockWaitTimeout,
                Errno::ENOMEM,
                RuntimeError, with: :badgateway_on_system_502_error

    def badgateway_on_system_502_error(exception)
      raise_error(502, exception, code: 'BG10000', type: Cupix::Errors::BadGateway, reason: 'BadGateway', message: exception.message)
    end

• 대조: background write 경로는 이미 lock-wait retry 를 갖고 있다 — synchronous bulk 경로에만 누락.

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

    rescue ActiveRecord::LockWaitTimeout => e
      if retries < LOCK_WAIT_MAX_RETRIES
        ...
        sleep(2**retries)
        retries += 1
        retry
      else
        raise e
      end

• 기대 동작: 일시적 lock 경합은 재시도로 흡수되어야 한다(worker 경로처럼).
• 실제 동작: element_traces#bulk transaction 은 재시도 없이 50초 대기 후 그대로 502 로 실패하고, postprocessor agent 가 재요청하면서 burst 로 반복된다.

Log Evidence#

Datadog query (retention 창 내):

service:cupixworks-api "Lock wait timeout exceeded"

status code / error class 분포 (now-14d, 50건 표본):

[502] 41  (class ActiveRecord::LockWaitTimeout)
[400]  7  (class Cupix::Errors::Parameter — "Lock wait timeout" 문자열만 포함, 별개)
[500]  2  (class Cupix::Errors::System)

엔드포인트 분포 (502 건):

17  PUT /api/v1/element_traces (Api::V1::ElementTracesController#bulk)
 8  PUT /api/v1/panos/{id} (PanosController#update)
 7  PUT /api/v1/jobs/{id} (JobsController#update)
 3  PUT /api/v1/panos/{id}/check_tile_uploading
 3  PUT /api/v1/panos/{id}/check_mask_uploading
 3  PUT /api/v1/captures/{id} (CapturesController#update)
 ... (levels/create, admin/editings/trash, assets/update 등 소수)

대표 로그 원문 (element_traces bulk, ~50s DB 대기 후 502):

{
  "message": "[502] PUT /api/v1/element_traces (Api::V1::ElementTracesController#bulk)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  },
  "duration": 50238.51,
  "db": 50166.15,
  "controller": "Api::V1::ElementTracesController",
  "action": "bulk",
  "user_agent": "cupix-sitetrack-postprocessor-agent",
  "team": { "domain": "algtest", "id": 3 },
  "params": { "facility_key": "qinlxf" },
  "environment": "qa",
  "http": { "status_code": 502, "method": "PUT" }
}

burst 타임스탬프 (element_traces, facility qinlxf, KST):

2026-08-04 13:40:45, 13:41:33, 13:45:06, 13:45:54, 13:46:54
2026-08-03 17:43:45 ~ 17:46:23 (4연속)
2026-07-31 16:54:47 ~ 16:57:23 (4연속)

→ 각 요청 ~50s db, 같은 facility 에서 연속 재시도되는 burst 패턴.

동일 facility 에서 Sitetrack 처리가 활성이었음 (같은 window):

Sitetrack(ID: 1272) processing started/completed with Capture ID 8587 (facility qinlxf, algtest/regression)

Hypotheses Considered#

Representative 불일치 note: cluster representative 는 Cupix::Errors::System 이지만 retention 창의 실제 지배 발생은 ActiveRecord::LockWaitTimeout → 502 (41/50) 이다. 최신 발생 기준으로 502 경로를 root cause 로 분석했다.

Fix Recommendation#

즉시 조치 (Critical)#

• 없음(장애 아님). LockWaitTimeout → 502 매핑은 의도된 transient 처리이며 사용자 데이터 손상/영구 실패는 없다.

단기 개선 (1주 이내)#

• element_traces#bulk(및 BulkableController#bulk / BulkableRepository#bulk) 의 write transaction 에 기존 in-repo lock-wait retry 패턴을 재사용하여 감싼다. 새로 발명하지 말 것 — app/workers/task_sync_worker.rb:41-63 의 create_tasks_with_lock_wait_retry 또는 app/models/concerns/finalization/editing_entity.rb:16-36 의 LOCK_RETRY_MAX_ATTEMPTS=3 + exp backoff 를 그대로 차용. bulk 는 멱등이 아닐 수 있으므로 partial_mode 재시도 시 이미 커밋된 항목 중복 방지를 확인.
• postprocessor agent 파이프라인에서 같은 facility 의 element_trace 대량 write 를 직렬화(advisory lock / 큐 단일화)하여 self-contention 원천 감소를 검토. editing_split_service 는 이미 REASSIGN_BATCH_SIZE batch 로 lock 보유 시간을 줄이고 있으므로 bulk 쪽도 batch 크기 / 트랜잭션 범위 축소를 검토.

장기 개선 (재발 방지)#

• InnoDB row lock 순서를 통일(항상 id 오름차순 lock)하여 경합 자체를 줄인다.
• LockWaitTimeout 재시도 로직을 공통 concern(with_lock_wait_retry) 으로 추출해 synchronous / worker 경로가 동일 구현을 공유하도록 통일.

Monitoring#

• element_traces bulk 502 발생 추이:

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:put_/api/v1/element_traces}.as_count()

• api 전체 502 응답 추이(경합 급증 감지):

sum:trace.rack.request.hits{service:cupixworks-api,http.status_code:502}.as_count()

Risk Assessment#

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

Noise Verdict#

bug — 팀이 이미 worker 경로(task_sync_worker.rb:53, finalization/editing_entity.rb:20)에서 채택한 lock-wait retry 가 synchronous element_traces#bulk 경로에만 누락되어 self-contention 이 502 로 표면화되는 실제 resilience 결함이므로 코드 수정(기존 retry 패턴 재사용)이 필요하다.