AWS Cognito — access token revoked after session invalidation

RCA: Api::V1::UsersController#destroy Latency (avg 4824ms)

Overview#

What Happened#

2026-05-26 08:15~08:21 UTC 사이에 cupixworks-api 서비스의 UsersController#destroy 엔드포인트에서 평균 4824ms, 최대 4902ms의 응답 지연이 5건 발생했다. 동일 시간대에 한 명의 관리자가 15명의 사용자를 일괄 삭제하는 작업을 수행했으며, 그 중 5건에서 AWS Cognito API 호출이 비정상적으로 느려지면서 전체 요청 시간이 급증했다.

Quick Facts#

Field	Value
resource_name	`Api::V1::UsersController#destroy`
top_frame	`app/repositories/user_repository.rb:141`
env	production, us-west-2
avg_duration	4824ms
max_duration	4902ms
HTTP status	204 (모든 요청 성공)

Affected Teams#

Team / Domain	Error Count	Impact
cupixworks-api (user management)	5	관리자의 사용자 삭제 요청이 ~5초 지연. 기능적 실패는 없으나 UX 저하

Timeline#

08:05:14 UTC — 관리자(Mustapha Djaziri)가 사용자 일괄 삭제 시작 (15명)
08:15:33 UTC — 첫 번째 slow request 발생 (user 13489, 4703ms)
08:21:51 UTC — 마지막 slow request (user 41919, 4841ms)
08:21:56 UTC — 일괄 삭제 작업 완료, 이후 재발 없음

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::UsersController#destroy",
  "service": "cupixworks-api",
  "occurrences": 5,
  "avg_ms": 4824,
  "max_ms": 4902,
  "sample_trace_id": "97686102836197600"
}

Impact#

Service: cupixworks-api
발생 횟수: 5
최초 발생: 2026-05-26T08:15:33.811Z
최근 발생: 2026-05-26T08:21:51.540Z

Root Cause Summary#

UsersController#destroy는 사용자 삭제 시 UserRepository#remove 내에서 동기적으로 AWS Cognito AdminUpdateUserAttributes API를 호출하여 이메일/이름을 익명화한다. 이 Cognito API 호출이 간헐적으로 4~5초가 소요되면서 전체 요청 응답 시간이 ~~4.8초로 증가했다. DB 쿼리 시간은 40~~200ms로 정상이며, 지연의 거의 전부가 외부 Cognito API의 응답 대기 시간이다. 15건의 삭제 요청 중 5건에서만 발생한 것으로 보아 Cognito 서비스의 간헐적 지연(throttling 또는 네트워크 지연)이 원인이다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/users_controller.rb:48
Core logic: app/repositories/user_repository.rb:141-152
Cognito call: lib/cupix/aws/cognito/user.rb:74-79

1단계: Controller → Repository 호출

app/controllers/api/v1/users_controller.rb:48-52ruby

def destroy
  repository_instance.remove
  render_api
end

2단계: UserRepository#remove — 삭제 로직 수행

app/repositories/user_repository.rb:141-152ruby

def remove
  raise ... unless Pundit.policy(current_user, @model).delete?

  delete_user = DeletedUser.new(@model.attributes.except('id').slice(*DeletedUser.attribute_names).merge(user_id: @model.id, deleted_at: DateTime.now))
  delete_user.save

  @model.reset_cycle_state unless @model.cycle_state_created?
  @model.deleted

  @model.assign_attributes(email: Digest::SHA1.hexdigest("#{@model.id},#{@model.email}") + '@removed user', firstname: nil, lastname: nil, state: 'inactive')
  @model.save
end

@model.save가 호출되면 email, firstname, lastname 변경이 감지되어 after_update :update_cognito_user 콜백이 트리거된다.

3단계: Cognito 동기 호출 (병목 지점)

lib/cupix/aws/cognito/user.rb:74-79ruby

after_update :update_cognito_user

def update_cognito_user
  return unless saved_change_to_firstname? || saved_change_to_lastname?
  Cupix::Aws::Cognito.update_user!(self) if Cupix::Aws::Cognito.user_exists?(email_before_last_save)
end

이 메서드는 user_exists?(Cognito list_users API) + update_user!(Cognito admin_update_user_attributes API) 두 번의 동기적 HTTP 호출을 수행한다. 정상 시 ~~500ms이나, Cognito 응답이 느린 경우 4~~5초까지 소요된다.

4단계: after_deleted 콜백 — 권한 cascading 삭제

app/models/concerns/cyclable/user.rb:31-45ruby

after_deleted do |model|
  model.cleanup_avatar! if model.avatar?
  model.sales_info.destroy if model.sales_info.present?
  model.groups.each { |group| group.users.destroy(model) } if model.groups.exists?
  model.team_permissions.destroy if model.team_permissions.exists?
  model.workspace_permissions.destroy if model.workspace_permissions.exists?
  model.facility_permissions.destroy if model.facility_permissions.exists?
  # ... 7개 추가 permission 타입
end

각 permission은 dependent: :destroy로 하위 레코드를 cascade하며, 각 레코드 삭제 시 Elasticsearch _delete_document HTTP 호출이 동기적으로 발생한다. 그러나 이 단계의 총 소요 시간은 DB time(40~200ms) 내에 포함되어 있어 주 병목은 아님.

Log Evidence#

Datadog 로그에서 확인한 요청별 duration 분석:

text

service:cupixworks-api @http.url_details.path:"/api/v1/users/*" @http.method:DELETE @duration:>3000000000

핵심 로그 (slow requests):

json

{"timestamp": "2026-05-26T08:15:40.264Z", "user_id": 13489, "duration_ms": 4703.60, "db_ms": 40.21, "host": "ip-10-1-19-190"}
{"timestamp": "2026-05-26T08:17:33.512Z", "user_id": 13498, "duration_ms": 4782.31, "db_ms": 61.88, "host": "ip-10-1-144-228"}
{"timestamp": "2026-05-26T08:17:47.900Z", "user_id": 13502, "duration_ms": 4901.10, "db_ms": 198.22, "host": "ip-10-1-80-134"}
{"timestamp": "2026-05-26T08:19:29.701Z", "user_id": 13488, "duration_ms": 4882.24, "db_ms": 69.63, "host": "ip-10-1-144-228"}
{"timestamp": "2026-05-26T08:21:56.904Z", "user_id": 41919, "duration_ms": 4841.45, "db_ms": 93.92, "host": "ip-10-1-19-190"}

Cognito 호출 증거 — 동일 request_id에서 correlate된 로그:

text

service:cupixworks-api "update_cognito_user" @usr.id:(13489 OR 13498 OR 13502 OR 13488 OR 41919)

json

{"timestamp": "2026-05-26T08:15:40.295Z", "message": "update_cognito_user", "user_id": 13489, "changes": {"email": ["mlevesque@stl.laval.qc.ca", "hash@removed user"]}}
{"timestamp": "2026-05-26T08:17:33.557Z", "message": "update_cognito_user", "user_id": 13498, "changes": {"email": ["ddesmarais@stl.laval.qc.ca", "hash@removed user"]}}
{"timestamp": "2026-05-26T08:19:29.710Z", "message": "update_cognito_user", "user_id": 13488, "changes": {"email": ["mlebeau@stl.laval.qc.ca", "hash@removed user"]}}

정상 속도 요청과의 비교:

json

{"timestamp": "2026-05-26T08:14:53.652Z", "user_id": 13496, "duration_ms": 467.15, "db_ms": 66.49}
{"timestamp": "2026-05-26T08:15:19.308Z", "user_id": 13493, "duration_ms": 396.87, "db_ms": 38.22}
{"timestamp": "2026-05-26T08:16:27.744Z", "user_id": 13485, "duration_ms": 518.56, "db_ms": 52.59}

DB time은 slow/fast 요청 모두 유사(40~200ms)하지만, total duration이 10배 차이나므로 병목은 DB 외부(Cognito API)에 존재.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	Cognito API 동기 호출의 간헐적 지연	duration - db_time = ~4.7s, Cognito 로그 timestamp와 request 완료 시간이 일치, slow/fast 요청의 DB time 동일	—	Confirmed
H2	대량 permission cascading 삭제로 인한 DB 지연	코드에서 10+ permission 타입 순차 삭제 + ES 호출 확인	DB time이 40~200ms로 낮음, slow/fast 요청 간 DB time 차이 미미	Rejected
H3	N+1 쿼리 문제	groups.each로 순차 삭제 패턴 존재	총 DB time이 여전히 200ms 미만으로 전체 지연 설명 불가	Rejected
H4	S3 avatar cleanup 지연	같은 시간대 me-south-1에서 S3 timeout 확인	이 요청들은 us-west-2에서 발생, S3 timeout은 별도 리전의 worker 이슈	Rejected

Fix Recommendation#

즉시 조치 (Critical)#

파일: lib/cupix/aws/cognito/user.rb:74-79
Cognito update_cognito_user 호출을 비동기로 전환. after_update 콜백에서 직접 Cognito API를 호출하는 대신, Sidekiq worker로 위임하여 요청 응답 시간에서 분리.
Cognito API 호출에 timeout 설정 추가 (현재 무제한으로 보임). 최대 3초 timeout을 설정하여 최악의 경우에도 요청이 과도하게 지연되지 않도록 방어.

단기 개선 (1주 이내)#

UserRepository#remove 전체 삭제 흐름을 background job으로 이동. Controller에서는 soft-delete만 수행하고 즉시 204 반환, 실제 cleanup(Cognito 익명화, permission 삭제, ES 업데이트)은 UserCleanupWorker에서 비동기 처리.
Permission 삭제 시 destroy_all 대신 delete_all + bulk ES 삭제를 사용하여 개별 콜백 호출 제거.

장기 개선 (재발 방지)#

사용자 삭제 프로세스를 이벤트 기반 아키텍처로 리팩터링. UserDeletedEvent를 발행하고, 각 관심사(Cognito 익명화, permission 정리, ES 인덱스 정리, Segment 통지)가 독립적인 subscriber로 비동기 처리.
Bulk user deletion API 제공 — 관리자가 다수 사용자를 삭제할 때 단일 batch job으로 처리하여 개별 요청 지연 없이 작업 완료.

Monitoring#

UsersController#destroy p95 duration 알림 추가 (threshold: 2000ms)
Cognito API 호출 duration 전용 메트릭 추가

text

service:cupixworks-api resource_name:"Api::V1::UsersController#destroy" @duration:>3000000000

text

service:cupixworks-api "update_cognito_user" @duration:>2000000000

Risk Assessment#

Risk level: low — 기능적 실패 없이 응답 지연만 발생. 모든 삭제 요청이 정상 완료(204).
예상 복잡도: standard — Cognito 호출을 worker로 이동하는 것은 기존 Sidekiq 인프라 활용 가능. Permission 삭제 최적화는 callback 의존성 검토 필요.