RCA: Api::V1::PanosController#check_mask_uploading (avg 66605ms, max 159799ms)

Overview#

What Happened#

2026-06-26 10:5110:53 KST 사이 cupixworks-api (ap-southeast-2, tenant cupix) 의 Api::V1::PanosController#check_mask_uploading 요청 4건이 평균 66.6초, 최대 159.8초의 비정상 지연을 보였다. 동일 시간/리전/테넌트에서 panos 테이블을 대상으로 한 Mysql2::Error::TimeoutError: Lock wait timeout exceeded (50087ms ≈ innodb_lock_wait_timeout 50초) 502 응답이 다수 발생하고 있었고, status board 도 본 cluster 를 parent incident 2026-06-26-svc-cupixworks-api--unknown-1 (총 7 cluster) 에 자동으로 묶었다. 본 cluster 의 trace 들은 결과적으로 200 응답을 받았으나, MaskableRepository#check_mask_uploading 내부의 panos UPDATE / state 전이가 InnoDB row-lock 경합에 묶여 50초 lock-wait timeout 13회 + 재시도 sleep 누적 형태로 늘어진 것으로 분석된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-26 10:25 KST — Parent incident 2026-06-26-svc-cupixworks-api--unknown-1 시작 (Api::V1::PanosController#update 41.5s latency, cluster 943fdcb4).
2. 2026-06-26 10:46 KST 이후 — panos 테이블 대상 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 502 응답 다수 (check_tile_uploading, check_mask_uploading, mask_upload_url). duration ≈ 50087ms = innodb_lock_wait_timeout 기본값 50s.
3. 2026-06-26 10:51:38 KST — 본 cluster 의 first_seen. check_mask_uploading 요청이 평균 66s 대로 지연되기 시작.
4. 2026-06-26 10:53:29 KST — PUT /api/v1/panos/14133757/check_mask_uploading 가 50s lock-wait timeout 으로 502 반환 (별도 cluster).
5. 2026-06-26 10:53:30 KST — 본 cluster last_seen (159799ms 트레이스 포함). 동시 cluster 들도 같은 패턴.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PanosController#check_mask_uploading",
  "service": "cupixworks-api",
  "occurrences": 4,
  "avg_ms": 66605,
  "max_ms": 159799,
  "sample_trace_id": "134794658443570874"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 4
• 최초 발생: 2026-06-26 10:51 KST
• 최근 발생: 2026-06-26 10:53 KST

Root Cause Summary#

본 cluster 는 단독 코드 결함이 아니라 parent incident 2026-06-26-svc-cupixworks-api--unknown-1 의 한 면이다. check_mask_uploading 액션은 MaskableRepository#check_mask_uploading 에서 @model.save! 및 @model.uploaded_mask_state! (state machine UPDATE) 로 panos row 를 쓰는 흐름을 가진다. 사건 시각 ap-southeast-2 production DB 의 panos 테이블에는 광범위한 InnoDB row-lock 경합이 발생 중이었고 (정확히 50087ms ≈ innodb_lock_wait_timeout 50s 에 끊긴 502 다수가 동일 시간/리전/테넌트에서 관측됨), 본 cluster 의 4 traces 는 같은 row 들에 대한 lock 대기로 50s timeout + 재시도/sleep loop 누적 형태로 66~159s 지연된 채 결국 200 으로 종료된 케이스다. 추가로 MaskableRepository#check_mask_uploading 내부에 존재하는 StateMachines::InvalidTransition 시 최대 5회 sleep(retries) (1+2+3+4+5=15s) 재시도 로직이 최악 시 50s lock-wait + 15s sleep 패턴을 한 요청 안에서 증폭시킨다.

Technical Analysis#

Code Path#

엔드포인트 → controller concern → repository concern → S3 / DB 의 흐름.

def check_mask_uploading
  mask = repository_instance.check_mask_uploading(params[:mask_type])

  render_api Renderable.new({
    contents: mask,
    serializer: MaskSerializer
  })
end

저장/상태 전이는 repository concern 에서 수행한다. lock 경합 시 50s 로 끊기는 핵심 두 지점이 @model.save! 와 @model.uploaded_mask_state! (state machine 의 UPDATE) 다:

def check_mask_uploading(mask_type)
  _mask_type = mask_type.presence || 'custom'
  mask = @model.masks.find_by_mask_type(_mask_type)

  raise Cupix::Errors::NotFound.new(code: 'ARG10002', reason: "Mask not found. mask_type: #{mask_type}") if mask.nil?

  if mask.mask_uploaded?(mask_revision: mask.mask_upload_revision)
    mask.uploaded
    retries = 0

    if _mask_type == 'custom'
      @model.mask = mask
      @model.current_mask_url = mask.mask_url
      @model.save!                                # ← panos row UPDATE (lock 1)
      # ...
    end

    begin
      @model.uploaded_mask_state!                 # ← panos state 전이 (lock 2)
    rescue StateMachines::InvalidTransition
      if (retries += 1) <= 5 && @model.mask_state_uploading?
        # ...
        sleep(retries)                            # ← 1+2+3+4+5 = 15s budget
        retry
      end
    end
  else
    mask.missing
    @model.missing_mask_state!                    # ← panos state 전이
    raise Cupix::Errors::InvalidState.new(code: 'STAT10000', reason: 'Mask does not uploaded')
  end

  mask
end

S3 HEAD 호출 자체는 standard AWS SDK 의 Aws::S3::Object#exists? 이며 보통 ms 단위로 끝난다:

def mask_uploaded?(params = {})
  mask_object(params).exists?
end

def mask_object(params = {})
  Cupix::StorageService.object(
    storage_option: storage_option,
    bucket_name: hosting_bucket_name,
    key: mask_object_key(params)
  )
end

• Entry point: app/controllers/concerns/maskable_controller.rb:7
• 1차 lock 지점: app/repositories/concerns/maskable_repository.rb:17 (@model.save!)
• 2차 lock 지점: app/repositories/concerns/maskable_repository.rb:28 (@model.uploaded_mask_state!)
• 재시도/sleep 증폭 지점: app/repositories/concerns/maskable_repository.rb:30-40 (최대 1+2+3+4+5=15s 의 sleep(retries))

기대 동작: 정상 시간대 (예: 10:50:42 KST 의 PUT /api/v1/panos/14133460/check_mask_uploading 200) 처럼 access log 한 줄로 완료 — 100ms 수준. 실제 동작: 4 traces 가 66605159799ms 지연. 50s lock-wait timeout 의 13배 + retry sleep 누적 형태에 부합. 같은 윈도우의 1건은 50087ms 에 끊기며 502 LockWaitTimeout 으로 실패 (별도 cluster, 같은 parent incident).

Log Evidence#

같은 시간/리전/테넌트에서 발생한 Lock wait timeout 을 좁혀 조회.

service:cupixworks-api "Lock wait timeout" "check_mask_uploading"
시간 범위: 2026-06-26T01:25:00Z ~ 2026-06-26T02:00:00Z

본 cluster 윈도우(first_seen ~ last_seen 포함) 안의 502 LockWaitTimeout:

{
  "timestamp": "2026-06-26 10:53:29 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/panos/14133757/check_mask_uploading (Api::V1::PanosController#check_mask_uploading)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

같은 parent incident 의 sibling RCA (d22ba254-b364-411b-801f-af7799b40331) 가 수집한 panos 테이블 lock 경합 로그 (정확히 50087ms 에 끊김 → innodb_lock_wait_timeout 50s 일치):

2026-06-26 10:46:39 [502] PUT /api/v1/panos/14131474/check_tile_uploading  ActiveRecord::LockWaitTimeout
2026-06-26 10:46:43 [502] PUT /api/v1/panos/14132644/check_tile_uploading  ActiveRecord::LockWaitTimeout
2026-06-26 10:47:28 [502] PUT /api/v1/panos/14132652/check_tile_uploading  ActiveRecord::LockWaitTimeout
2026-06-26 10:47:34 [502] PUT /api/v1/panos/14131474/check_tile_uploading  ActiveRecord::LockWaitTimeout
2026-06-26 10:48:41 [502] PUT /api/v1/panos/14131939/check_tile_uploading  ActiveRecord::LockWaitTimeout
2026-06-26 10:53:28 [502] POST /api/v1/panos/14133747/mask_upload_url      ActiveRecord::LockWaitTimeout
2026-06-26 10:53:29 [502] PUT /api/v1/panos/14133757/check_mask_uploading  ActiveRecord::LockWaitTimeout

정상 시간대 같은 엔드포인트는 access log 한 줄로 완료 (수십~수백 ms):

2026-06-26 10:50:42 [200] PUT /api/v1/panos/14133460/check_mask_uploading
2026-06-26 10:51:10 [200] PUT /api/v1/panos/14133487/check_mask_uploading
2026-06-26 10:51:10 [200] PUT /api/v1/panos/14133481/check_mask_uploading

avg 66605ms, max 159799ms 의 패턴은 단일 50s lock-wait 보다 길어 (1) 50s timeout 후 retry (state machine 재시도 sleep 15s budget + 두 번째 lock 대기) 또는 (2) 50s lock-wait 이 같은 요청 안에서 2~3회 누적된 형태로 해석된다. 단일 코드 경로에서 보장된 wait time (50s × N + sleep ≤ 15s) 의 산술 범위 안에 본 cluster 의 모든 trace duration 이 들어간다.

status board 도 본 cluster 를 2026-06-26-svc-cupixworks-api--unknown-1 에 묶었으며 같은 윈도우의 다른 6 cluster (Api::V1::PanosController#update, Admin::CapturesController#index, WorkspacesController#index, AssetsController#download, ...) 도 ap-southeast-2 / tenant cupix 의 동일 latency 폭증 패턴을 공유한다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 본 cluster 는 단독 코드 결함이 아니라 parent incident 2026-06-26-svc-cupixworks-api--unknown-1 의 부수 피해다. 코드 변경 불필요. 같은 parent incident 의 핵심 cluster (Api::V1::PanosController#update 943fdcb4, check_tile_uploading LockWaitTimeout cluster 등) 의 lock 경합 원인 분석에 합류.
• DB lock 경합의 직접 원인 추적 지점:
  • Api::V1::PanosController#update, #check_tile_uploading, #check_mask_uploading, #mask_upload_url 의 transaction 경계 (PanoRepository, MaskableRepository, TilableRepository).
  • MaskableRepository#check_mask_uploading 의 @model.save! + @model.uploaded_mask_state! 가 단일 transaction 내에 다중 panos UPDATE 를 묶고 있는지 확인 (app/repositories/concerns/maskable_repository.rb:17,28).
  • 같은 capture/cluster 의 mask/tile upload 후처리가 동시에 다발하면서 같은 row 의 lock 을 잡는 패턴 확인.

단기 개선 (1주 이내)#

• MaskableRepository#check_mask_uploading 의 state machine 재시도 sleep 정책 (sleep(retries) 최대 15s) 을 lock 경합 시나리오까지 가산되는 것을 고려하여 짧은 fail-fast 모드 (예: 총 sleep budget 3s, retry 2회) 로 조정 검토. lock 경합 시 다음 50s timeout 까지 같은 요청이 점유하지 않게 해 사용자 인지 latency 와 DB connection 점유 시간을 모두 줄임.
• check_mask_uploading 의 write 경로를 짧은 transaction 으로 분리: @model.save! 의 UPDATE 컬럼 범위를 축소 (mask_id, current_mask_url 만 갱신하는 partial update), state 전이도 별도 transaction.
• ap-southeast-2 production DB 의 connection pool 가용성 / pool_wait Datadog dashboard 추가 — lock 경합 시 connection 회수 지연 모니터링.

장기 개선 (재발 방지)#

• panos write 경로(update, check_*_uploading, *_upload_url) 의 transaction 범위 축소: 단일 transaction 안에 다중 row UPDATE / 외부 호출 (S3 HEAD 등) 이 혼재되어 있다면 분리.
• innodb_lock_wait_timeout 단축 (현재 50s 추정) — read-heavy API 경로에 영향이 크므로 30s 이하로 검토하고, 동시에 long-running write 를 줄이는 작업과 병행. (sibling RCA 와 동일 권고)
• 동일 pano 에 대한 mask/tile 후처리 호출의 client-side 직렬화 또는 server-side advisory lock (예: Redis lock) 으로 같은 pano row 의 동시 UPDATE 충돌 감소.
• region 별 endpoint p99 trace duration 알림 (현재 ap-southeast-2 만 튀는 패턴 조기 감지).

Monitoring#

avg:trace.rack.request.duration{service:cupixworks-api,env:production,resource_name:api::v1::panoscontroller#check_mask_uploading}

max:trace.rack.request.duration{service:cupixworks-api,env:production,resource_name:api::v1::panoscontroller#check_mask_uploading}

sum:trace.rack.request.duration.by_resource_service.errors{service:cupixworks-api,env:production,region:ap-southeast-2}.as_count()

sum:mysql.innodb.row_lock_waits{service:cupixworks-api,env:production,region:ap-southeast-2}.as_rate()

max:mysql.innodb.row_lock_time{service:cupixworks-api,env:production,region:ap-southeast-2}

추가 권장:

• ActiveRecord::LockWaitTimeout Datadog Logs 기반 metric (region / resource_name 별):
  textCopy

  logs("service:cupixworks-api @error.class:ActiveRecord::LockWaitTimeout env:production").index("*").rollup("count").by("region","resource_name")
  

• panos 쓰기 4 endpoint (update, check_tile_uploading, check_mask_uploading, mask_upload_url) 의 p99 latency 를 동일 timeseries widget 에 묶어 동시 spike 패턴 감지.

Risk Assessment#

• Risk level: medium — 4건의 trace 자체 영향은 한정적이나, 같은 parent incident 의 6 cluster (모두 ap-southeast-2/tenant cupix) 와 동시에 발생한 DB 광범위 영향의 일부.
• 예상 복잡도: standard — 코드 결함은 없고, parent incident (panos write 경로 lock 분석) 와 연계 작업 필요. retry-sleep 정책 조정은 trivial, transaction 범위 축소는 standard.