Api::V1::SignupsController#signup_on_team (avg 11364ms, max 11364ms)

RCA: Api::V1::SignupsController#signup_on_team latency (11.4s)

Overview#

What Happened#

2026-07-14 07:01 KST 무렵, cupixworks-api (us-west-2, tenant cupix) 에서 Api::V1::SignupsController#signup_on_team 요청 1건이 11,361ms 만에 200 응답으로 완료. 동일 endpoint 의 최근 14일 정상 요청은 대부분 1.3–2.3s 범위이므로 이번 요청은 명백한 outlier. DB time 은 1,094ms 로 전체 latency 의 10% 에 불과하고, 나머지 시간은 in-process 및 외부 (Cognito / Elasticsearch) 호출로 소비됨.

Quick Facts#

Field	Value
exception.class	(없음 — 200 OK, latency 이슈)
resource	`Api::V1::SignupsController#signup_on_team`
top_frame	`app/operations/signup_operation.rb:43-99` (`SignupOperation.team_signup`)
duration	11,361.63 ms (avg=max, n=1)
db	1,094.38 ms
view	0.14 ms
env	production, us-west-2
deploy	`production-us-west-2-20260713t1454z0-3ebb21b6-cupixworks`
trace_id	`1486681629062685307`
request_id	`6f60bf89-782f-4795-9726-c18873e6ba45`
tenant	cupix

Affected Teams#

Team / Domain	Error Count	Impact
bnbuilders (Team domain)	1	신규 팀 사용자 1명이 signup 완료까지 11초 대기. 요청은 성공하여 정상 signup 됨.

Timeline#

모든 시각은 KST (UTC+9).

2026-07-14 06:51 KST (approx) — 초대 발송. User noriel.bargo@bnbuilders.com 이 invited 상태로 생성 (updated_at: 2026-07-13 21:51:21 UTC, invitation_token: 950881 세팅).
2026-07-14 07:01:21 KST — signup_on_team 요청 시작 (request_id 6f60bf89-...).
2026-07-14 07:01:23 KST — Cognito update_user! / update_cognito_user 로그 (요청 시작 후 ~1.8s). user.active_state! 로 인한 after_update :update_cognito_user 콜백 실행.
2026-07-14 07:01:31 KST — flush_cached_permission / flush_cached_permissions 로그 (Cognito update 이후 ~7.7s 뒤). Group 소속 추가 완료 후 permission cache flush.
2026-07-14 07:01:33 KST — 응답 200 반환 (총 11,361.63ms).

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::SignupsController#signup_on_team",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11364,
  "max_ms": 11364,
  "sample_trace_id": "1486681629062685307"
}

Impact#

Service: cupixworks-api
발생 횟수: 1
최초 발생: 2026-07-14 07:01 KST
최근 발생: 2026-07-14 07:01 KST

Root Cause Summary#

SignupOperation.team_signup 은 사용자 활성화 이후 team 소속 Group 들을 순차적으로 loop 하며 group.users << user 로 grouped_user 를 생성한다. GroupedUser 에는 after_create :reindex_group 콜백이 걸려 있어 매 group 추가마다 동기식 Elasticsearch __elasticsearch__.index_document 가 실행된다. 여기에 user.active_state! 로 인한 Cognito admin_update_user_attributes 호출과 마지막 change_password 로 인한 Cognito admin_set_user_password 호출이 요청 스레드에서 직렬로 수행된다. 이번 요청에서는 이 조합이 ~10초 지연을 유발했다. DB time 이 1,094ms 에 불과한데 총 11,361ms 가 걸린 점, 그리고 Cognito update 로그와 permission cache flush 로그 사이의 7.7초 공백이 이를 뒷받침한다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/signups_controller.rb:24-30
Business logic: app/operations/signup_operation.rb:43-99 (SignupOperation.team_signup)
동기 Cognito 콜백: lib/cupix/aws/cognito/user.rb:11,74-83 (after_update :update_cognito_user)
동기 ES reindex: app/models/grouped_user.rb:15,26-30 (after_create :reindex_group)
마지막 동기 Cognito 호출: lib/cupix/aws/cognito.rb:156-166 (admin_set_user_password)

Controller entry:

app/controllers/api/v1/signups_controller.rb:24-30ruby

def signup_on_team
  user = SignupOperation.team_signup(params)

  token = UserOperation.get_token(user)

  render_json 200, TokenSerializer.new(token).serializable_hash[:data][:attributes]
end

Operation body — 활성화, 그룹 소속 부여, 비밀번호 세팅이 순차 동기 실행:

app/operations/signup_operation.rb:78-97ruby

user.confirmation_token = nil
user.invitation_token = nil
user.joined_at = user.confirmed_at = DateTime.now
user.active_state!                       # → after_update :update_cognito_user (동기 Cognito 호출)

user_email_domain = user.email.split('@').last

Group.left_outer_joins(:email_domains).where(
  team: team,
  email_domains: { domain: ['*', user_email_domain] },
  group_type_code: 'normal'
).or(Group.left_outer_joins(:email_domains).where(
       team: team,
       group_type_code: 'users'
     )).distinct.each do |group|
  group.users << user unless group.users.exists?(user.id)   # → GroupedUser.create → 동기 ES reindex
end

change_password(user, params)            # → Cognito.admin_set_user_password (동기)

Cognito 콜백 (user.active_state! 이후 firstname/lastname 변경이 함께 반영되어 조건 통과):

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

def update_cognito_user
  return if saved_changes.blank? || (saved_changes.keys & %w[firstname lastname locale]).blank?

  flush_cognito_user_cache
  Cupix::Aws::Cognito.update_user!(self)     # AWS Cognito admin_update_user_attributes
rescue StandardError => e
  Cupix::Logger.error("Failed to update cognito user: #{self.email}", ...)
else
  Cupix::Logger.info("User updated in Cognito: #{email}", ..., changes: saved_changes)
end

GroupedUser 콜백 — 매 그룹 추가마다 동기 ES index_document 실행:

app/models/grouped_user.rb:15-38ruby

after_create :reindex_group
after_create :reindex_team, if: proc { |grouped_user| grouped_user.group.group_type_code == 'assigned_customer_success_managers' }
after_destroy :reindex_group
after_destroy :reindex_team, if: proc { |grouped_user| grouped_user.group.group_type_code == 'assigned_customer_success_managers' }
after_commit :flush_cached_permitted_items, on: %i[create destroy]

def reindex_group
  return nil if group.nil?

  group.reload.__elasticsearch__.index_document        # 동기 ES 호출
end

Cognito 비밀번호 세팅 (요청 스레드에서 마지막에 실행):

lib/cupix/aws/cognito.rb:156-166ruby

def change_password(user, password)
  response = client.admin_set_user_password(
    user_pool_id: $AWS.fetch(:cognito).fetch(:user_pool_id),
    username: user.email,
    password: password,
    permanent: true
  )
rescue StandardError => e
  Cupix::Logger.error("Failed to change password in Cognito: #{user.email}", ...)
  raise Cupix::Errors::System.new(code: 'SYS20000', reason: 'Failed to change password')
end

기대 동작: signup 은 사용자 체감상 1–2초 이내에 완료되어야 함 (동일 endpoint P50 관측치와 일치). 실제 동작: Cognito 두 번 (update_user!, admin_set_user_password) + N 회의 동기 ES index_document (group 수만큼) 가 요청 스레드에서 직렬 실행되어 11.4초 소요.

Log Evidence#

Datadog 검색 쿼리 (재현용):

text

service:cupixworks-api "signup_on_team"
2026-07-13T21:55:00Z ~ 2026-07-13T22:10:00Z

요청 완료 access log (원본):

json

{
  "@timestamp": "2026-07-13T22:01:33.203Z",
  "message": "[200] POST /api/v1/signups/team (Api::V1::SignupsController#signup_on_team)",
  "status": "info",
  "controller": "Api::V1::SignupsController",
  "action": "signup_on_team",
  "duration": 11361.63,
  "db": 1094.38,
  "view": 0.14,
  "params": {
    "firstname": "Noriel",
    "team_domain": "bnbuilders",
    "email": "noriel.bargo@bnbuilders.com",
    "lastname": "Bargo"
  },
  "request_id": "6f60bf89-782f-4795-9726-c18873e6ba45",
  "http": { "status_code": 200, "method": "POST", "url_details": { "path": "/api/v1/signups/team" } },
  "version": "production-us-west-2-20260713t1454z0-3ebb21b6-cupixworks"
}

동일 요청의 Cognito update 로그 (요청 시작 후 ~1.8s):

json

{
  "@timestamp": "2026-07-13T22:01:23.628Z",
  "message": "User updated in Cognito: noriel.bargo@bnbuilders.com",
  "class": "Cognito",
  "function": "update_cognito_user",
  "request_id": "6f60bf89-782f-4795-9726-c18873e6ba45",
  "changes": {
    "state": ["invited", "active"],
    "firstname": ["Noriel"],
    "lastname": ["Bargo"],
    "joined_at": ["2026-07-13 22:01:20 UTC"],
    "confirmed_at": ["2026-07-13 22:01:20 UTC"],
    "invitation_token": ["950881"],
    "updated_at": ["2026-07-13 21:51:21 UTC", "2026-07-13 22:01:21 UTC"],
    "encrypted_password": ["…", "…"]
  }
}

동일 요청의 permission cache flush 로그 (Cognito update 이후 ~7.7s 뒤):

text

2026-07-13T22:01:31Z  Deleting cached_permission on user 52454     (User#flush_cached_permission)
2026-07-13T22:01:31Z  Flush cached permissions for User 52454       (Module#flush_cached_permissions)

같은 endpoint 최근 14일 요청 duration 비교 (Datadog service:cupixworks-api @action:signup_on_team, 최근 성공/오류 요청 발췌):

text

2026-07-13T22:14:47.168Z  duration=1717.22   db=312.41
2026-07-13T22:01:33.203Z  duration=11361.63  db=1094.38   ← 이번 outlier
2026-07-13T20:38:22.395Z  duration=1604.27   db=315.37
2026-07-13T20:01:59.813Z  duration=2267.39   db=702.86
2026-07-13T19:57:07.413Z  duration=1357.33   db=323.06
2026-07-13T19:51:16.716Z  duration=1418.50   db=301.48
2026-07-13T19:06:54.191Z  duration=1347.21   db=331.95
2026-07-13T18:42:47.276Z  duration=1644.02   db=371.45

성공 요청의 정상 대역은 1.3–2.3s. 이번 요청만 5배 이상 벗어남.

동시간대 (2026-07-13T21:59:00Z ~ 22:03:00Z) service:cupixworks-api status:error 검색 결과 0 건 → 인프라 광역 장애 아님.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	`team_signup` 내 순차 실행되는 Cognito 호출 (update_user + admin_set_user_password) 과 그룹당 동기 ES `reindex_group` 이 누적되어 latency 증가	요청 총 11,361ms 중 db 1,094ms 뿐 (나머지 ~10초 외부/CPU). Cognito update 로그(22:01:23.628Z) 와 permission flush 로그(22:01:31Z) 사이 7.7초 공백. `GroupedUser` after_create 가 동기 ES `index_document` 를 호출 (`app/models/grouped_user.rb:15,26-30`). `team_signup` 코드가 그룹 loop + change_password 를 요청 스레드에서 실행 (`signup_operation.rb:85-96`).	—	Confirmed
H2	DB slow query 로 인한 latency	db=1,094ms 는 평소(300–700ms) 대비 다소 높음.	전체 duration 의 10% 에 불과. 나머지 90% 를 DB 로 설명할 수 없음.	Rejected
H3	광역 Cognito / AWS 장애	Cognito 호출 자체가 latency 경로에 포함.	동시간대 `cupixworks-api status:error` 0건, status board 도 active dep 인시던트 없음. 최근 7일 recent 인시던트는 `svc:cupixworks-api::unknown` 로 다른 root cause 유형. Cognito 로그가 정상 완료(`User updated in Cognito`).	Rejected
H4	Ruby GC / 앱 서버 순간 지연	특정 span 없이 latency 만 튀는 경우 가능.	동일 endpoint 동시간대 다른 요청 (22:14:47) 은 1.7s 정상. 같은 host `ip-10-1-19-190` 다른 요청도 정상. 앱 서버 지연이면 여러 endpoint 에 영향이 있어야 함.	Rejected
H5	Elasticsearch cluster slowdown 이 `reindex_group` 를 지연	ES `index_document` 가 동기라 slowdown 시 직접 영향.	광범위 ES slowdown 이면 다른 write path (e.g. `after_create :reindex_group` 을 쓰는 다른 모델, capture/pano 등) 에도 영향이 있어야 함. 동시간대 관련 status:error 로그 없음. 그룹 loop N 회 누적 (H1) 로 설명 충분.	Inconclusive — H1 의 하위 요인으로 잠재적 기여 가능

Fix Recommendation#

즉시 조치 (Critical)#

즉각적 코드 변경은 불필요. n=1 outlier 이며 요청은 200 으로 성공. 우선 모니터링에서 P95/P99 를 지속 관측하여 재발 여부 확인.
대신 아래 개선 작업 (Group.users << 루프 최적화, Cognito call 병렬/후처리화) 을 트래킹 Jira 로 등록 권장.

단기 개선 (1주 이내)#

app/operations/signup_operation.rb:85-94 그룹 소속 부여 루프: GroupedUser.insert_all 또는 user.grouped_users.create! 배치로 변경해 after_create :reindex_group 이 그룹당 1회 호출되는 구조를 유지하되, reindex_group 을 별도 Sidekiq worker (FlushCachedPermissionByUserWorker 와 유사한 패턴) 로 이관.
app/models/grouped_user.rb:15,26-30 의 reindex_group 을 after_commit + perform_async 로 옮겨 동기 ES index_document 를 요청 경로에서 제거. 유사 워커 (app/workers/flush_cached_permission_worker.rb, flush_cached_permission_by_user_worker.rb) 가 이미 존재하므로 동일 패턴 채택 가능.
SignupOperation.change_password (signup_operation.rb:316-318) 호출을 요청 스레드에서 제거 검토 — 다만 로그인 직후 비밀번호 검증에 필요하므로 그대로 유지하되, admin_set_user_password timeout / retry 정책 확인 (lib/cupix/aws/cognito.rb:156-166 에는 명시적 timeout 없음).

장기 개선 (재발 방지)#

회원가입 같은 사용자 대기 경로에서 외부 서비스 (Cognito, Elasticsearch) 호출은 원칙적으로 background job 화. active_state! → after_update :update_cognito_user 처럼 AR 콜백에 의존한 외부 호출은 지연 원인 파악을 어렵게 하므로, Cognito 동기화 전용 서비스 오브젝트 + 명시적 호출 지점으로 이관.
APM span breakdown 을 강화 (Cognito client / Elasticsearch client 를 각각 별도 span 으로) 하여 다음 outlier 발생 시 어느 외부 의존이 병목인지 즉시 확인 가능하게 한다.

Monitoring#

Signup latency P95/P99 추적 (release dashboard timeseries widget 용, monitor 전용 문법 사용 금지):

text

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::signupscontroller#signup_on_team,env:production}

text

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::signupscontroller#signup_on_team,env:production}

Signup 요청 처리량 (as_rate 로 급락/급증 파악):

text

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::signupscontroller#signup_on_team,env:production}.as_rate()

Cognito 호출 오류 추이 (cupixworks-api 자체 로그 기반 metric — Cognito 호출 실패 시 error 레벨 로그 발생):

text

sum:logs.hits{service:cupixworks-api,status:error,@class:Cognito}.as_count()

Elasticsearch client latency (있다면):

text

p95:trace.elasticsearch.query{service:cupixworks-api,env:production}

P95 > 3s 상태가 5분 이상 지속되면 Slack 알림 (monitor 는 dashboard 와 별도 정의 필요).
동일 endpoint 에서 duration > 5000ms 로그가 5분 내 3건 이상 발생 시 alert.

Risk Assessment#

Risk level: low (n=1, 요청 성공, 사용자 영향은 signup 대기 11초 1회)
예상 복잡도: standard (콜백을 sync → async 로 변경하는 리팩토링, 회원가입 경로 회귀 테스트 필수)