RCA: GET 502 on /api/v1/sessions (50.5–50.8s, ALB 502 from row-lock timeout)

Overview#

What Happened#

2026-06-17 04:42 KST 무렵 production-us-west-2 의 cupixworks-api 에서 인증 미들웨어가 모든 요청마다 발급하는 UPDATE users SET first_sign_in_at = ? 쿼리가 동일한 user row 에 대한 row lock 대기로 50초간 hang 되어 InnoDB lock wait timeout (~50s) 에 걸렸다. Puma 가 응답을 만들지 못한 사이 Elastic Beanstalk/ALB 가 idle/upstream timeout 으로 502 를 반환했고, APM 은 이 요청들을 resource_name: GET 502 로 묶었다. 같은 사용자 세션에서 병렬로 떠난 두 건의 GET /api/v1/sessions?fields= 가 서로 같은 row 를 잠그며 동시에 timeout 됐다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-17 04:42:29 KST — host i-0a026d499fb305739 에서 GET /api/v1/sessions?fields= 시작 (trace 1083198673863158736).
2. 2026-06-17 04:42:37 KST — host i-09eb846280d67ac02 에서 두 번째 GET /api/v1/sessions?fields= 시작 (trace 3060560276632410961). 동일 user row 에 BEGIN + UPDATE 진입.
3. 2026-06-17 04:42:37 KST (+0ms) — 두 트랜잭션 모두 같은 row 의 X-lock 을 요청. 첫 트랜잭션이 잡고 두 번째가 대기 시작.
4. 2026-06-17 04:43:28 KST (~50.5s 뒤) — 두 UPDATE 모두 InnoDB innodb_lock_wait_timeout (50s) 으로 종료, ROLLBACK. Puma 는 5xx 응답 직전이지만 이미 ALB 가 502 로 응답을 끊어 resource_name: GET 502 로 분류됨.
5. 2026-06-17 04:43:28 KST 직후 — 후속 요청은 정상 (/api/v1/sessions 200 로그가 04:42:39 KST 부터 다수 관찰).

Error Log#

Datadog Logs

Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (ActiveRecord::LockWaitTimeout)
  from mysql2-0.5.4/lib/mysql2/client.rb:148:in `_query'
  …
  from activerecord-7.2.2/lib/active_record/persistence.rb:579:in `update!'
  from /var/app/current/lib/cupix/auth/verification.rb:129:in `verify_authenticated_request!'
  from /var/app/current/app/controllers/concerns/verification_controller.rb:19:in `authenticate!'
  …
  from puma-6.5.0/lib/puma/thread_pool.rb:166:in `block in spawn_thread'

{
  "resource_name": "GET 502",
  "service": "cupixworks-api",
  "trace_id": "3060560276632410961",
  "http.url": "/api/v1/sessions?fields",
  "http.route": "/api/v1/sessions",
  "http.status_code": "502",
  "duration_ms": 50505.92,
  "host": "i-09eb846280d67ac02",
  "x-request-id": "63d32891-bf04-4b37-9091-5228e7f31bd7"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2 (이 클러스터 윈도우 기준)
• 최초 발생: 2026-06-17 04:42 KST
• 최근 발생: 2026-06-17 04:42 KST
• Blast radius: 단일 사용자 세션에서는 직접 영향 (요청 hang → 50s 후 502). 그러나 lock 을 잡고 있던 트랜잭션이 release 될 때까지 같은 user row 에 대한 모든 인증 트래픽이 직렬화되며, 50s 동안 Puma worker 가 점유되어 동일 인스턴스의 다른 모든 사용자에게 latency 전파 가능 (Puma worker pool exhaustion risk).

Root Cause Summary#

Cupix::Auth::Verification#verify_authenticated_request! 가 매 인증 요청마다 user.first_sign_in_at 이 nil 이면 user.update!(first_sign_in_at: DateTime.now) 을 실행한다 (lib/cupix/auth/verification.rb:125, lib/cupix/auth/issuers/cupixworks.rb:83). first_sign_in_at 컬럼은 db/migrate/20251020001503_add_first_sign_in_at_to_user.rb 로 추가됐고 backfill 없이 nullable 로 도입되었으므로 기존 사용자는 모두 NULL 이다. 결과적으로 SPA/클라이언트가 한 사용자 토큰으로 동시에 N 개의 API 호출을 보내면 N 개의 Puma 스레드가 모두 같은 users row 에 대해 별도 트랜잭션에서 BEGIN → UPDATE users SET first_sign_in_at=… 을 시도하고, 첫 트랜잭션 외에는 InnoDB row X-lock 대기 큐에 들어가 50s innodb_lock_wait_timeout 까지 소진한 뒤 ROLLBACK. 그 사이 ALB 가 upstream timeout 으로 502 를 응답한다. 본질적으로 "first-sign-in 한 번만 기록"이라는 1회성 작업을 모든 요청에서 동기적·트랜잭셔널하게 시도하는 코드 + 광범위하게 NULL 인 컬럼 상태가 결합돼 사실상 per-user serialization point 가 됐다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/sessions_controller.rb:4 (Api::V1::SessionsController#show) — route GET /api/v1/sessions (config/routes.rb:1166).
• Before-action chain: Api::V1::ApiController includes VerificationController (app/controllers/api/v1/api_controller.rb:2), which registers before_action :authenticate! (app/controllers/concerns/verification_controller.rb:8).
• authenticate! calls Cupix::Auth::Verification#verify_authenticated_request!.
• Failure point: lib/cupix/auth/verification.rb:125 — user.update!(first_sign_in_at: DateTime.now). 동일한 코드가 lib/cupix/auth/issuers/cupixworks.rb:83 에도 존재.

included do
  before_action :set_auth_method
  before_action :authenticate!, except: %i[status elasticsearch_status]
end

def authenticate!
  if @cupix_auth_method == 'COGNITO'
    begin
      verification = Cupix::Auth::Verification.new(request: request)
      response = verification.verify_authenticated_request!

unless @verified == true
  Cupix::Logger.error('Verification failed', class: 'Verification', function: __method__, module: 'Cupix::Auth', access_token: @access_token, user_response: user_response)
end

user.update!(first_sign_in_at: DateTime.now) if user.first_sign_in_at.nil?

Cupix::Auth::VerificationResponse.new(
  email: user_response.email,
  user: user,
  team: user.team,
  session: user.default_session
)

else
  @current_user = session.user
  @current_team = session.team
  @scope_in_access_token = Cupix::Auth::Scope.get_from_access_token(access_token)
  @scope_in_session = Cupix::Auth::Scope.get_from_session(session)
  @current_user.update!(first_sign_in_at: DateTime.now) if @current_user.first_sign_in_at.nil?

  Cupix::Auth::VerificationResponse.new(
    email: @current_user.email,
    user: @current_user,
    team: @current_team,
    session: session
  )
end

class AddFirstSignInAtToUser < ActiveRecord::Migration[7.2]
  def change
    add_column :users, :first_sign_in_at, :datetime
  end
end

마이그레이션은 backfill 없이 컬럼만 추가했기 때문에 기존 사용자는 전부 first_sign_in_at IS NULL → 매 요청마다 if user.first_sign_in_at.nil? 가 true → 매 요청이 BEGIN/UPDATE/COMMIT 트랜잭션을 발생시킨다.

기대 동작 vs 실제 동작:

• 기대: "최초 로그인 시각 한 번만 기록" 의도이므로, 같은 user 에 대해 첫 성공 후에는 더 이상 UPDATE 가 발생하면 안 됨. 그리고 이 동작은 인증 hot path 에서 동기적으로 일어나서는 안 됨.
• 실제: 백필이 없어 모든 기존 user 가 NULL 상태로 시작. 클라이언트가 같은 토큰으로 N 개 요청을 동시에 발사하면 N 개의 트랜잭션이 같은 row X-lock 을 다투고, 첫 트랜잭션이 commit 되기 전 (예: Cognito 호출 등 인증 hot path 의 다른 동기 작업이 같은 트랜잭션 안에 있는 게 아니더라도 1ms 이상이면) 나머지가 lock-wait 큐에 줄을 선다. 한 번이라도 long transaction (예: GC pause, slow query 등) 이 끼면 50s innodb_lock_wait_timeout 까지 누적되어 502 가 폭발한다.

Log Evidence#

Datadog APM query (cluster 파일에서 인용)

service:cupixworks-api resource_name:"GET 502" env:production @duration:>500ms
시간 범위: 1781635320000–1781642580000 (Unix ms)

Trace 3060560276632410961 (host i-09eb846280d67ac02, request_id 63d32891-bf04-4b37-9091-5228e7f31bd7):

2026-06-16T19:42:37.664Z  rack.request           50505.92 ms  status=error  GET 502  /api/v1/sessions?fields
2026-06-16T19:42:37.665Z  rails.cache GET            8.25 ms  ok
2026-06-16T19:42:37.673Z  redis.command GET          0.42 ms  ok
2026-06-16T19:42:37.675Z  SELECT users LEFT JOIN teams …    1.31 ms  ok   (parent=root)
2026-06-16T19:42:37.679Z  BEGIN                       0.38 ms  ok   (parent=…26799472)
2026-06-16T19:42:37.679Z  SELECT users WHERE email=… 1.54 ms  ok   (uniqueness validation)
2026-06-16T19:42:37.687Z  UPDATE users SET updated_at=?, first_sign_in_at=? WHERE id=?
                                                  50480.54 ms  status=error  ← LockWaitTimeout
2026-06-16T19:43:28.168Z  ROLLBACK                    0.36 ms  ok

쿼리 텍스트가 UPDATE users SET users.updated_at = ? users.first_sign_in_at = ? WHERE users.id = ? 임에 주목. dirty-tracking 으로 updated_at + first_sign_in_at 만 업데이트되고, 다른 컬럼 (state, encrypted_password 등) 은 손대지 않음 → 다른 워크로드와의 cross-row 충돌은 아님. 같은 row 의 다른 트랜잭션과의 충돌이다.

Stack trace (type: ActiveRecord::LockWaitTimeout, span 3132416404990206696):

/var/app/current/lib/cupix/auth/verification.rb:129:in `verify_authenticated_request!'
/var/app/current/app/controllers/concerns/verification_controller.rb:19:in `authenticate!'
…
puma-6.5.0/lib/puma/thread_pool.rb:166:in `block in spawn_thread'

배포본의 라인 번호 :129 와 현재 main 의 :125 는 같은 expression (deploy SHA 9443a6d8 기준 ~4 줄 차이).

두 번째 trace 1083198673863158736 (host i-0a026d499fb305739): 동일한 패턴, 50.81s, 같은 fingerprint aa7d02120a0bcf31. 두 host 가 서로 다른 EC2 이지만 같은 RDS 를 공유하므로 row-lock 경합이 cross-host 로 일어났음을 의미한다.

누락된 로그:

service:cupixworks-api status:error
시간 범위: 2026-06-16T19:30:00Z ~ 2026-06-16T19:55:00Z
→ 0 hits.

service:cupixworks-api host:i-09eb846280d67ac02
시간 범위: 2026-06-16T19:40:00Z ~ 2026-06-16T19:50:00Z
→ 0 hits.

요청이 응답을 보내지 못한 채 ALB 에서 잘렸기 때문에 lograge access log 자체가 발생하지 않았다 — 평소에는 [200] GET /api/v1/sessions 가 다수 찍히지만 (예: 04:52:39–04:52:53 KST 에 10건 200 관찰) 이 두 건은 어떤 status code 도 application log 에 남기지 않았다. 이것이 클러스터가 Datadog 로그가 아닌 APM trace (latency cluster) 로만 검출된 이유.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

1. first_sign_in_at 백필 — db/migrate/20251020001503_add_first_sign_in_at_to_user.rb 가 backfill 없이 컬럼만 추가했다. UPDATE users SET first_sign_in_at = COALESCE(first_sign_in_at, current_sign_in_at, last_sign_in_at, created_at) WHERE first_sign_in_at IS NULL 같은 batched backfill 을 즉시 실행해 nil? 분기를 false 로 만들면 hot path 의 UPDATE 자체가 사라져 contention 도 사라진다. 운영적으로 대용량 row 면 chunk + sleep 패턴 필요.
2. 인증 hot path 의 동기 UPDATE 제거 — lib/cupix/auth/verification.rb:125 와 lib/cupix/auth/issuers/cupixworks.rb:83 의 user.update!(first_sign_in_at: DateTime.now) if user.first_sign_in_at.nil? 두 군데를 인라인 UPDATE 대신 비동기 (Sidekiq job) 또는 best-effort UPDATE 로 옮긴다. 인증 자체는 row-lock 경합과 무관해야 한다. ActiveJob 으로 UpdateFirstSignInAtJob.perform_later(user_id) 같은 형태가 적절. 백필이 끝나면 이 분기 자체가 dead path 가 되므로 유지비도 낮다.

단기 개선 (1주 이내)#

1. update_columns + idempotent guard 로 변경 — 백필 전에 임시 완화책으로, update! (callback/validation/transaction 동반) 대신 User.where(id: user.id, first_sign_in_at: nil).update_all(first_sign_in_at: DateTime.now) 로 바꾸면 (a) state_machine/AR transaction 을 우회해 BEGIN/COMMIT 한 번이 사라지고 (b) WHERE first_sign_in_at IS NULL 이 첫 트랜잭션 commit 후에는 매칭되지 않아 후속 요청이 빈 결과로 즉시 반환된다. lock-wait 시간을 ms 단위로 줄임. (단, 인증 hot path 에서 DB write 가 여전히 일어나므로 위 즉시조치 (2) 가 본질적 해법.)
2. innodb_lock_wait_timeout 단축 + lock_wait_timeout 분류 — 50s 는 너무 길어 한 번 contention 이 발생하면 그대로 ALB 502 화 된다. RDS parameter group 에서 글로벌 5–10s 로 조정하거나, Rails 측에서 hot path 트랜잭션 시작 시 SET innodb_lock_wait_timeout = 5 적용. 짧게 잡으면 502 대신 명시적인 5xx 에러 로그가 남아 가시성도 개선.
3. /api/v1/sessions hot-path 에서 클라이언트 fan-out 검토 — URL 이 ?fields= (값 없음) 이고 동시에 다발이라 SPA bootstrap 로직이 의심된다. 클라이언트가 같은 세션에 대해 sessions 호출을 dedupe (in-flight cache) 하면 부하 자체가 감소.

장기 개선 (재발 방지)#

1. 컨벤션: backfill 없는 nullable 컬럼은 인증 hot path 에서 분기 조건으로 사용 금지. Migration template / lint 로 "마이그레이션 추가 시 backfill 계획 필수" 체크. 본 사고는 "한 번만 쓰기" 로 보이는 코드가 backfill 부재로 사실상 모든 요청에서 쓰기를 일으킨 패턴.
2. 인증 미들웨어에서 DB write 금지 원칙. authenticate! 같은 hot path 는 read-only 여야 하며, 부수적인 timestamp/usage 기록은 비동기 큐에 위임. 코드 리뷰 체크리스트에 추가.
3. APM latency 알림. resource_name:GET 502 또는 @duration:>30s 트래픽이 1분에 N건 이상이면 알림. 본 사고는 사용자에 의해 발견되기 전에 자동 검출 가능했음.

Monitoring#

추가할 메트릭/알림 — 아래 쿼리들은 Datadog dashboard timeseries widget 에 그대로 들어감 (monitor-only 문법 사용 금지).

1. cupixworks-api 의 GET 502 (혹은 ALB upstream timeout) 발생률

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:GET 502}.as_count()

2. 인증 경로의 row-lock timeout 빈도 (mysql2 instrumentation 의 error 카운트, users 테이블 한정은 facet 으로 좁힘)

sum:trace.mysql2.query.errors{service:cupixworks-api,resource_name:UPDATE users}.as_count()

3. /api/v1/sessions p99 latency

p99:trace.rack.request{service:cupixworks-api,http.route:/api/v1/sessions}

4. users.first_sign_in_at IS NULL UPDATE 의 평균 시간 (백필 후 0 으로 수렴해야 함; 픽스 효과 검증용)

avg:trace.mysql2.query.duration{service:cupixworks-api,resource_name:UPDATE users}

각 쿼리는 widget 에 timeseries 로 표시되며, monitor 전용 문법 (| stats, count by(...), threshold suffix 등) 을 포함하지 않는다.

Risk Assessment#

• Risk level: high — 같은 RDS 를 공유하는 모든 cupixworks-api 인스턴스의 인증 경로에 영향. 단일 사용자의 동시 요청만으로도 50s 동안 Puma worker 가 점유돼 다른 사용자 latency 까지 전파될 수 있음. 트래픽이 많은 사용자 (예: 자동화 스크립트, SPA 의 fan-out) 가 있으면 worker pool exhaustion 가능.
• 예상 복잡도: standard — 코드 변경은 두 줄 (update! → 비동기 또는 update_all guarded), 마이그레이션은 idempotent backfill 1개. 단, 운영 backfill 은 row 수에 따라 chunked 실행 필요.