RCA: Api::V1::ApiController#status (avg 322376ms, max 322376ms)

Overview#

What Happened#

2026-07-01 10:43 KST에 cupixworks-api의 헬스체크 endpoint /status 처리에 약 322초(5분 22초)가 걸린 span이 관측되었다. 동일 시간대에 같은 서비스에서 다수의 write endpoint가 Mysql2::Error::TimeoutError: Lock wait timeout exceeded로 502를 반환하고 있어, 이 latency spike는 DB row-lock 경합 및 커넥션 풀 대기로 인한 서비스 전반의 slowdown의 한 단면이다. 상태 보드도 같은 시각에 2026-07-01-svc-cupixworks-api--unknown-1 인시던트를 열고 5개 클러스터를 묶었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-01 10:43 KST — Api::V1::ApiController#status span 322s 관측 (첫/최종 발생, trace 7290272645204243029)
2. 2026-07-01 10:43–10:49 KST — 같은 서비스에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 다발 발생 (PanosController#stitched|check_uploading|check_tile_uploading|mask_upload_url, JobsController#complete_action|update, EditingsController#update, CapturesController#update_meta_by_key)
3. 2026-07-01 10:43 KST — 상태 보드가 2026-07-01-svc-cupixworks-api--unknown-1 인시던트 오픈 (5개 클러스터: 이 클러스터 + #bulk 등)
4. 2026-07-01 최근 3h — max:trace.rack.request.duration{service:cupixworks-api} 피크 최대 2880s (48분) 관측 — 서비스 전반적인 slowdown

Error Log#

Datadog Logs

resource_name: Api::V1::ApiController#status
service: cupixworks-api
occurrences: 1
avg_ms: 322376
max_ms: 322376
sample_trace_id: 7290272645204243029

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (latency span)
• 최초 발생: 2026-07-01 10:43 KST
• 최근 발생: 2026-07-01 10:43 KST
• 상태 보드: 2026-07-01-svc-cupixworks-api--unknown-1 (open, 5 clusters). 지난 7일 내 같은 scope로 9건의 유사 인시던트 resolved — 재발 패턴.

Root Cause Summary#

/status 헬스체크는 매 요청마다 MySQL(User.last)과 Elasticsearch(User.search)를 직접 호출한다. 사고 시각 인근에 cupixworks-api 전반에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded가 폭주(주로 PanosController 업로드 관련 write 경로)했고, 이로 인해 MySQL row lock 대기 + 커넥션 풀 소진이 발생했다. 헬스체크 엔드포인트는 별도 fast path 없이 같은 커넥션 풀을 공유하기 때문에, User.last SELECT 자체가 커넥션 획득 또는 lock 해제를 기다리며 322초 동안 블록되었다. 즉 root cause는 #status 엔드포인트가 아니라 upstream write 경합이고, #status 자체는 그 slowdown을 반영/증폭한 피해자이자 취약한 health-check 설계이다.

Technical Analysis#

Code Path#

• Entry point: config/routes.rb:7 — get 'status', controller: 'api/v1/api', action: :status
• Action: app/controllers/concerns/status_controller.rb:9-50 — MySQL과 Elasticsearch 양쪽에 실제 쿼리 수행
• Failure point: app/controllers/concerns/status_controller.rb:13 (User.last) — MySQL 커넥션/lock 대기에 걸림

def status
  begin
    @status.merge!(JSON.parse(File.open('./cupix.json', 'r').read))

    user_from_db = User.last
    user_from_elasticsearch = User.search({
      size: 1,
      query: {
        bool: {
          must: [
            {
              term: {
                id: user_from_db.id
              }
            }
          ]
        }
      }
    })

    raise Cupix::Errors::BadGateway.new(code: 'BG10002', reason: 'Error on Elasticsearch') if user_from_elasticsearch.blank?
  rescue Cupix::Errors::BadGateway => e
    @status.merge!({
      code: 502,
      status: 'unhealthy',
      reason: e.reason
    })
  rescue StandardError => e
    @status.merge!({
      code: 503,
      status: 'unhealthy',
      reason: e.message
    })

기대 동작: 헬스체크는 밀리초 단위로 응답해 상위 로드밸런서가 인스턴스 생존을 판단할 수 있어야 한다. 실제 동작: User.last가 커넥션 풀 대기 및/또는 MySQL 서버 측 lock/queue 대기에 걸려 322초 동안 반환하지 못했다. 상위에서 timeout으로 강제 종료되기 전에는 rescue StandardError도 트리거되지 않아 unhealthy로도 마킹되지 않는다.

관련 route/모델 참조:

get 'status', controller: 'api/v1/api', action: :status
get 'status/elasticsearch', controller: 'api/v1/api', action: :elasticsearch_status

include Searchable::User

User 모델은 Searchable::User concern을 통해 Elasticsearch에 인덱스되며 (app/models/concerns/searchable/user.rb), User.search가 실제 ES 쿼리를 수행한다. 즉 /status는 항상 실제 인프라(DB + ES)에 두 번 왕복한다.

Log Evidence#

Datadog query 1 — /status 요청 로그 (10:40–10:45 KST 구간)

service:cupixworks-api "/status"

시간 범위: 2026-07-01T01:40:00Z ~ 2026-07-01T01:45:00Z. [200] GET /status (Api::V1::ApiController#status) info 로그가 다수 관측됨 — 최종적으로는 200을 반환했지만, 이 클러스터의 특정 요청은 span 기준 322초가 걸렸다.

Datadog query 2 — 같은 시간대 서비스 전반의 error/warn (root cause 신호)

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

시간 범위: 2026-07-01T01:40:00Z ~ 2026-07-01T01:50:00Z. 대표 로그:

{
  "timestamp": "2026-07-01 10:49:46",
  "status": "info",
  "message": "[502] PUT /api/v1/panos/90874056/stitched (Api::V1::PanosController#stitched)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

{
  "timestamp": "2026-07-01 10:49:13",
  "status": "info",
  "message": "[502] PUT /api/v1/jobs/1165311/actions/postprocessor/complete (Api::V1::JobsController#complete_action)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

동일한 lock-wait timeout이 PanosController#check_uploading, #check_tile_uploading, #mask_upload_url, #stitched, JobsController#update, EditingsController#update, CapturesController#update_meta_by_key 등 여러 write endpoint에서 관측됨 — 특정 endpoint의 문제가 아니라 DB layer 전반의 경합.

Datadog metric — 서비스 전반 latency

max:trace.rack.request.duration{service:cupixworks-api}

최근 3h(사고 포함) 구간의 값(초 단위, 대표 발췌):

... 108.96, 99.44, 89.92, 97.19, 121.25, 123.97, 157.06, 246.02, 367.09, 410.14, 262.19 ...
... 262.19, 138.53, 128.01, 118.49 ...
peaks: 1965.15, 1058.78, 983.09, 795.82, 2880.42, 2401.09, 1921.76, 1442.43

정상 baseline(수 초)에 비해 수 백~수 천 배 증가. #status 322s는 이 광범위한 slowdown 안의 한 표본.

상태 보드 컨텍스트

scope: svc:cupixworks-api::unknown
active: 2026-07-01-svc-cupixworks-api--unknown-1 (open, 5 clusters)
recent (last 7d): 9 resolved incidents on the same scope
  - 2026-06-30 (8 clusters), 2026-06-27, 2026-06-26 (x4), 2026-06-25, 2026-06-24 (x2)

같은 svc:cupixworks-api::unknown scope에서 최근 7일간 9회 반복 — 만성적 재발.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 파일: app/controllers/concerns/status_controller.rb:9-50
  • 헬스체크 응답에 aggressive timeout을 부여한다. User.last와 User.search 각각에 짧은 타임아웃(예: 각 1–2초)을 두고, 초과 시 rescue로 넘어가 503 unhealthy + reason을 반환. 현재는 timeout 없이 무한 대기하여 322초 span이 발생.
  • MySQL 세션 타임아웃은 ActiveRecord level의 statement_timeout(PG의 경우) 또는 MySQL의 MAX_EXECUTION_TIME hint / Timeout.timeout(...) 래핑을 검토. Rails/Mysql2 조합에서는 Timeout.timeout 안에서 raw ActiveRecord::Base.connection.execute 사용은 위험(커넥션 leak)하므로, 앱 코드 대신 pool/connection level timeout(connect_timeout, read_timeout, write_timeout in database.yml) 조정을 우선 고려.
• 파일: 로드밸런서/K8s liveness/readiness probe 정책
  • /status(무거운 헬스체크) 대신 DB/ES에 손대지 않는 shallow liveness endpoint로 probe를 전환하고, /status는 사람이 보는 deep-check 용도로 남긴다. 현재 구조는 인프라 결함이 헬스체크 실패로 전파돼 인스턴스가 도미노 재기동될 위험이 있다. (이 리팩터의 정확한 라우팅은 인프라 담당과 협의 필요 — uncertain, needs verification)

단기 개선 (1주 이내)#

• root cause인 Mysql2::Error::TimeoutError: Lock wait timeout exceeded의 실제 트랜잭션 소스 조사. 사고 시각 로그에서 가장 자주 502를 낸 컨트롤러:
  • PanosController#stitched, #check_uploading, #check_tile_uploading, #mask_upload_url
  • JobsController#complete_action, #update
  • EditingsController#update, CapturesController#update_meta_by_key → 이들 write 경로가 어떤 row에 얼마나 오래 락을 잡는지 트랜잭션 스코프를 검토하고, 큰 트랜잭션은 분할하거나 pessimistic lock 범위를 좁힌다. (이 클러스터의 근본 원인이지만 별도 클러스터/이슈로 다루는 것이 적절 — 같은 svc:cupixworks-api::unknown scope의 다른 클러스터와 함께.)
• shallow health-check endpoint(/livez 등) 추가. DB/ES를 건드리지 않고 프로세스 생존만 검증.
• deep health-check(/status)는 별도 커넥션 풀 또는 read replica 사용 검토.

장기 개선 (재발 방지)#

• 같은 scope(svc:cupixworks-api::unknown)에서 지난 7일간 9회 재발한 만성 패턴. Pano 업로드/Job 처리 파이프라인의 트랜잭션 설계 리뷰가 필요. 특히 stitched, check_uploading, mask_upload_url 계열 write 요청의 락 홀딩 시간과 동시성 프로파일을 문서화하고, 필요 시 큐잉/rate limit 또는 async 이관을 검토.
• APM 리소스별 알림: resource_name:api::v1::apicontroller#status avg latency > 1s가 5분 지속 시 alert. 현재는 latency span만 error-sweeper에 잡혀 사후 인지되고 있다.
• MySQL InnoDB row-lock 지표(innodb_row_lock_current_waits, innodb_row_lock_time) 대시보드/알림 구축.

Monitoring#

• #status endpoint latency (초 단위, request 단위):

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::apicontroller#status}

• 서비스 전반 latency 스파이크:

max:trace.rack.request.duration{service:cupixworks-api}

• MySQL lock-wait timeout 발생률 (log-based, error-sweeper 감시용):

service:cupixworks-api "Lock wait timeout exceeded"

• 위 로그 쿼리로부터 로그 카운트 위젯을 만들 때는 timeseries widget에 그대로 쓸 수 있는 log-count query(예: Datadog log analytics count measure)로 등록. monitor-only pipe/stats 문법(| stats, count by(...))은 timeseries widget에서 빈 그래프를 렌더하므로 사용 금지.
• #status throughput 및 성공률(200 비율):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::apicontroller#status}.as_rate()

• Pano/Job write 경로 502 비율:

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::panoscontroller#stitched}.as_rate()

• 리소스명 정확한 태그 값은 Datadog에서 확인 필요(대소문자·형식) — uncertain, needs verification. 사용 전 service:cupixworks-api 위젯에서 group_by resource_name으로 실제 값 확인.

Risk Assessment#

• Risk level: high — 서비스 전반의 latency가 30분 넘게 지속되고, 헬스체크까지 5분 이상 지연되어 로드밸런서가 인스턴스를 unhealthy로 마킹하면 도미노 재기동 위험. 같은 scope로 7일간 9회 재발.
• 예상 복잡도: standard (/status 자체의 timeout/shallow endpoint 도입)에서 critical (Pano/Job 트랜잭션 설계 리팩터). 즉시 조치는 standard, 근본 조치는 critical.