RCA: flush_geo_coordinate Mysql2::Error::TimeoutError (Lock wait timeout)

Overview#

What Happened#

2026-06-18 17:16 KST, cupixvista-api-worker (production us-west-2, tenant cupix)에서 Cupix::Cron::Record.finalize_delayed_geo_coordinate 가 Record 18851 의 지연된 geo coordinate flush를 처리하다 Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction 으로 실패했다. flush 시작(flush_geo_coordinate - begin)부터 에러까지 약 56초가 경과했고, cron 자체 측정 duration은 51초로 MySQL 기본 innodb_lock_wait_timeout 50초와 일치한다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-18 17:15 KST 직전 — 이전 flush 또는 다른 트랜잭션이 Record 18851 행에 쓰기 락을 보유 중. (직접 로그는 없음 — uncertain — needs verification)
2. 2026-06-18 17:15:25 KST — [Cron][Record] Flushing 1 delayed geo coordinates - record_ids: 18851 로그 출력. 같은 시각 flush_geo_coordinate - begin 로그 출력 (Record 18851).
3. 2026-06-18 17:15Z deploy — production-us-west-2-20260618T0815Z0-... 버전 배포가 동일 시간대에 발생 (deploy version 태그 기준).
4. 2026-06-18 17:16:21 KST — flush_geo_coordinate - error - message: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction 발생.
5. 2026-06-18 17:16:21 KST — cron이 동일 시각에 Flushing delayed geo coordinate: 18851 - duration for flushing: 51 sec 로그 출력 (51초 = innodb_lock_wait_timeout 기본값과 일치).

Error Log#

Datadog Logs

flush_geo_coordinate - error - message: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

Impact#

• Service: cupixvista-api-worker
• 발생 횟수: 1
• 최초 발생: 2026-06-18 17:16 KST
• 최근 발생: 2026-06-18 17:16 KST

Root Cause Summary#

Cupix::Cron::Record.finalize_delayed_geo_coordinate 가 Record 18851 에 대해 record.flush_geo_coordinate 를 동기 호출하여, S3 streaming upload(panos batch 순회)와 마지막 update(geo_coordinate_url_updated_at: DateTime.now) 를 실행했다. flush가 진행되는 동안 동일 Record 행을 점유한 다른 트랜잭션 때문에 마지막 UPDATE가 InnoDB row lock 을 획득하지 못했고, 51초 후 innodb_lock_wait_timeout(기본 50초)에 도달해 Mysql2::Error::TimeoutError 가 발생했다. flush_geo_coordinate 의 rescue StandardError 블록이 에러를 잡아 캐시 락(unlock_flushing_geo_coordinate)은 풀고 false 를 리턴했지만, S3 객체는 이미 업로드되었음에도 geo_coordinate_url_updated_at 갱신과 _flush_delayed_geo_coordinate(Redis 키 삭제), fresh_fresh_state! 는 실행되지 않아 후속 상태가 부분적으로 inconsistent 한 채 종료되었다.

Technical Analysis#

Code Path#

• Entry point: lib/cupix/cron/record.rb:16 (finalize_delayed_geo_coordinate)
• 동기 flush 호출: lib/cupix/cron/record.rb:33
• Concern entry: app/models/concerns/record_geo_coordinate.rb:37 (flush_geo_coordinate)
• S3 streaming + DB UPDATE: app/models/concerns/record_geo_coordinate.rb:45-83
• Failure point: app/models/concerns/record_geo_coordinate.rb:83 — update(geo_coordinate_url_updated_at: DateTime.now) 가 row lock 획득 실패
• 에러 처리: app/models/concerns/record_geo_coordinate.rb:90-94 (rescue StandardError)

Cron은 Redis 에 쌓인 지연 flush 키를 모아 동기적으로 flush_geo_coordinate 를 실행한다. Sidekiq worker(FlushRecordGeoCoordinateWorker) 와 달리 본 cron 경로는 timeout 보호 장치나 retry 가 없다.

def finalize_delayed_geo_coordinate
  flush_geo_coordinate_keys = []
  Rails.cache.redis_instance.scan_each(match: 'FlushGeoCoordinate::Record::*', count: 1000) do |key|
    flush_geo_coordinate_keys << key
  end
  cache_mvalues = Rails.cache.read_multi(*flush_geo_coordinate_keys)
  record_ids = cache_mvalues.values.pluck(:record_id)
  Cupix::Logger.info("[Cron][Record] Flushing #{flush_geo_coordinate_keys.count} delayed geo coordinates - record_ids: #{record_ids.join(',')}")

  if cache_mvalues.present?
    cache_mvalues.each do |key, value|
      record_id = value[:record_id]
      enqueued_at = value[:enqueued_at]
      record = ::Record.find(record_id)

      if record.present?
        start_time = DateTime.now.to_i
        record.flush_geo_coordinate
        Cupix::Logger.info("[Cron][Record] Flushing delayed geo coordinate: #{record_id} - duration from enqueued_at: #{enqueued_at - DateTime.now.to_i} sec, duration for flushing: #{DateTime.now.to_i - start_time} sec")
      end

      Rails.cache.redis.del(key)
    end
  end
end

flush_geo_coordinate 는 S3 streaming upload 가 끝난 뒤에 Record 행을 UPDATE 한다. S3 upload 자체가 수십 초 걸릴 수 있고, 이후 UPDATE가 다른 트랜잭션이 잡고 있던 row lock 을 기다리다 timeout 에 걸린다.

def flush_geo_coordinate(accept_delay: false)
  lock_flushing_geo_coordinate

  _delayed_flush_geo_coordinate and return if accept_delay

  Cupix::Logger.info('flush_geo_coordinate - begin', class: self.class.name, function: __method__, module: 'RecordGeoCoordinate', record: { id: self.id })
  start_time = DateTime.now.to_i

  geo_coordinate_s3_object.upload_stream(
    content_type: 'application/json',
    cache_control: "max-age=#{1.year.to_i}",
    acl: 'bucket-owner-full-control'
  ) do |write_stream|
    # ... panos batch 순회 / S3 streaming write ...
  end

  update(geo_coordinate_url_updated_at: DateTime.now)  # ← 여기서 lock wait timeout

  Cupix::Logger.info("flush_geo_coordinate - finished - duration: #{DateTime.now.to_i - start_time} seconds", ...)

  _flush_delayed_geo_coordinate
  fresh_fresh_state!
rescue StandardError => e
  unlock_flushing_geo_coordinate
  Cupix::Logger.error("flush_geo_coordinate - error - message: #{e.message}", class: self.class.name, function: __method__, module: 'RecordGeoCoordinate', record: { id: self.id })
  false
else
  unlock_flushing_geo_coordinate
end

기대 동작: S3 upload 후 짧은 단일 row UPDATE 가 즉시 commit. 실제 동작: 다른 트랜잭션이 같은 Record 행에 lock 을 보유하고 있어 UPDATE 가 50초 동안 대기하다 Mysql2::Error::TimeoutError 로 abort 된다. 이때 S3 객체는 이미 업로드된 상태이므로 row 갱신과 S3 사이 inconsistency 가 발생한다.

Log Evidence#

Datadog query:

service:cupixvista-api-worker @class:Record @function:flush_geo_coordinate

Time window: 2026-06-18T08:14:00Z – 2026-06-18T08:17:00Z

Key sequence (all from host ip-10-1-82-141.us-west-2.compute.internal, pid 2499570, tenant cupix, record.id 18851):

2026-06-18T08:15:25.839Z  info   [Cron][Record] Flushing 1 delayed geo coordinates - record_ids: 18851
2026-06-18T08:15:25.839Z  info   flush_geo_coordinate - begin
2026-06-18T08:16:21.843Z  error  flush_geo_coordinate - error - message: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction
2026-06-18T08:16:21.843Z  info   [Cron][Record] Flushing delayed geo coordinate: 18851 - duration from enqueued_at: -4876196-06-15T08:13:46+00:00 sec, duration for flushing: 51 sec

Raw error log attributes (Datadog):

{
  "service": "cupixvista-api-worker",
  "level": "error",
  "module": "RecordGeoCoordinate",
  "class": "Record",
  "function": "flush_geo_coordinate",
  "record": { "id": 18851 },
  "tenant": "cupix",
  "environment": "production",
  "dd": {
    "version": "production-us-west-2-20260618T0815Z0-0938bde6-cupixvista"
  },
  "host": { "name": "ip-10-1-82-141.us-west-2.compute.internal" },
  "pid": 2499570,
  "@timestamp": "2026-06-18T08:16:21.843Z",
  "message": "flush_geo_coordinate - error - message: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction"
}

duration for flushing: 51 sec 는 cron 의 self-measured duration 이고 MySQL 기본 innodb_lock_wait_timeout 50초와 일치한다 — UPDATE가 거의 정확히 timeout 한도에 걸린 것을 의미한다.

duration from enqueued_at: -4876196-06-15T08:13:46+00:00 sec 는 cron 코드의 부수적 버그(enqueued_at - DateTime.now.to_i, DateTime 객체에서 정수를 빼서 epoch 0 기준 차이가 출력됨)이며 본 인시던트와는 무관 — 본 RCA 의 root cause 와 분리된 별개 결함.

배포 버전 태그(production-us-west-2-20260618T0815Z0-...)가 같은 시간대에 찍혔다는 점은 동일 시간 다른 worker / API 인스턴스가 Record 18851 에 대해 트랜잭션을 잡고 있었을 가능성에 대한 정황이지만 — 동시 점유자에 대한 직접 로그는 본 검색 범위에서 확인되지 않음. uncertain — needs verification.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 추가 발생 모니터링: 본 클러스터는 7일간 1건이므로 즉각적 코드 변경보다 재발 추적 우선. Datadog monitor 추가 (아래 Monitoring 섹션 참조).
• Record 18851 의 현재 상태 검증: S3 객체는 업로드되었지만 geo_coordinate_url_updated_at 이 갱신되지 않았을 가능성 → 다음 cron 사이클에서 재시도되었는지(FlushGeoCoordinate::Record::18851 캐시 키 잔존 여부) 확인. (uncertain — needs verification, Kibana/DB 직접 조회 필요)

단기 개선 (1주 이내)#

• lib/cupix/cron/record.rb:33 의 동기 호출을 Sidekiq enqueue 로 전환 검토 (FlushRecordGeoCoordinateWorker.perform_async(record_id)). worker 는 retry 1회와 안전한 unlock_flushing_geo_coordinate 처리가 이미 존재해 cron 동기 실행보다 견고하다.
• record_geo_coordinate.rb:83 의 마지막 UPDATE 를 별도 짧은 트랜잭션/별도 connection 으로 분리해 S3 streaming 동안 long-running connection 이 묶이지 않도록 한다. 또는 update_columns(...) 사용 검토 — callback/transaction 부담을 줄여 lock 보유 시간 단축.
• rescue StandardError 블록(record_geo_coordinate.rb:90) 이 geo_coordinate_url_updated_at 미갱신 / _flush_delayed_geo_coordinate 미실행 상태로 종료할 때, S3 와 DB 간 inconsistency 를 명시적으로 로그하거나 다음 사이클에 재시도 가능하도록 캐시 키 보존 정책을 점검.

장기 개선 (재발 방지)#

• flush_geo_coordinate 의 long-running streaming upload + DB UPDATE 패턴 재설계: S3 키에 versioned suffix 를 두고 DB UPDATE 가 lightweight 하게 떨어지도록 분리, 또는 geo_coordinate_url_updated_at 을 별도 lightweight write path 로 갱신.
• Record 행에 대한 long lock holder 를 탐지하기 위한 InnoDB lock metrics (Datadog DB monitoring) 도입.
• innodb_lock_wait_timeout 보다 짧은 application-side timeout (MAX_EXECUTION_TIME) 적용 검토 — cron 이 50초 동안 worker 슬롯을 점유하지 않도록.

Monitoring#

Datadog monitor / dashboard 쿼리 (timeseries widget 에 그대로 사용 가능):

logs("service:cupixvista-api-worker status:error \"flush_geo_coordinate - error\" \"Lock wait timeout\"").index("*").rollup("count").by("env").last("1d")

logs("service:cupixvista-api-worker @class:Record @function:flush_geo_coordinate status:error").index("*").rollup("count").by("env").last("1d")

logs("service:cupixvista-api-worker \"[Cron][Record] Flushing delayed geo coordinate\"").index("*").rollup("count").by("env").last("1d")

추가로 권장:

• MySQL Innodb_row_lock_waits / Innodb_row_lock_time_avg 메트릭 패널.
• flush_geo_coordinate - finished - duration: N seconds 의 N 분포 (P95, P99) — duration 급증이 lock wait 의 선행 지표가 될 수 있음 (별도 log facet 필요, uncertain — needs facet setup).

Risk Assessment#

• Risk level: low (7일간 1건, S3 업로드는 성공해 사용자 측 즉각 영향은 제한적이나 DB 상태가 stale 로 남을 위험 있음)
• 예상 복잡도: standard (cron → Sidekiq 전환 또는 UPDATE 분리는 기존 worker/lock 패턴 재사용으로 가능)