RCA: Timeout while getting cupix-trace-id

Overview#

What Happened#

2026-07-02 04:44~04:48 KST 사이 production us-west-2 cupixworks-worker 에서 Editing 모델의 before_create 콜백이 CupixTrace API Gateway 엔드포인트(tkyb8r1rlg.execute-api.us-west-2.amazonaws.com/cupix_trace_id)에 POST 하는 동안 10초 타임아웃이 두 번 발생했다. 두 건 모두 rescue Timeout::Error 브랜치가 실행되어 fallback_cupix_trace_id가 로컬 UUID로 값을 채웠고, Editing 레코드는 정상 생성되었다.

Quick Facts#

Affected Teams#

Fallback 경로가 성공했음이 같은 타임스탬프의 Fallback to use uuid as cupix-trace-id info 로그로 확인된다. 최종 Editing 저장은 정상 진행되었다.

Timeline#

1. 2026-07-02 04:44:50 KST — 첫 번째 Timeout::Error 발생, fallback UUID 사용 성공.
2. 2026-07-02 04:48:46 KST — 두 번째 Timeout::Error 발생, fallback UUID 사용 성공. (약 3분 56초 후)
3. 이후 24h — generate_cupix_trace_id 성공 로그 다수 (Success to get cupix-trace-id when Capture create) 관찰, 추가 error 없음.

Error Log#

Datadog Logs

Timeout while getting cupix-trace-id

Impact#

• Service: cupixworks-worker
• 발생 횟수: 2
• 최초 발생: 2026-07-02 04:44:50 KST
• 최근 발생: 2026-07-02 04:48:46 KST

사용자 가시 영향 없음. Editing 레코드는 fallback UUID를 사용하여 정상 생성되었다. 다만 해당 두 건은 CupixTrace 서비스가 부여한 canonical cupix_trace_id 대신 로컬 UUID를 가지므로, CupixTrace 조회 시스템에서 두 레코드에 대한 trace 조회는 매칭이 되지 않을 수 있다.

Root Cause Summary#

Editing 모델의 before_create :generate_cupix_trace_id 콜백은 HTTParty.post 로 외부 CupixTrace API Gateway (Lambda) 를 호출하며 Timeout.timeout(10) 로 감싸져 있다. 문제의 두 시점(04:44:50, 04:48:46 KST)에 이 HTTP 호출이 10초 안에 응답을 반환하지 못했다. 이는 외부 dependency (API Gateway + 뒤의 Lambda) 의 일시적 latency 스파이크로 판단되며, 코드는 이미 rescue → fallback UUID 경로로 graceful degradation 을 수행했다. 재현 빈도(14일 동안 2건, 같은 24h 창에서 성공 호출 다수)로 볼 때 systematic bug 가 아니라 dependency 의 transient 문제이다.

Technical Analysis#

Code Path#

• Entry point: app/models/editing.rb:17 — include ::Tracable::Editing
• Tracable::Editing → include ::Tracable (app/models/concerns/tracable/editing.rb:6)
• Tracable 이 before_create :generate_cupix_trace_id 를 등록 (app/models/concerns/tracable.rb:7)
• Editing.create 시 콜백 실행 → HTTParty POST → Timeout::Error 발생 지점: app/models/concerns/tracable.rb:31-33

def generate_cupix_trace_id
  return if Cupix::CupixTrace.service_url.nil?

  Timeout.timeout(10) do
    response = HTTParty.post(
      "#{Cupix::CupixTrace.service_url}/cupix_trace_id",
      body: { crn: self.crn }.to_json,
      headers: { 'Content-Type' => 'application/json' }
    )

    if response.success?
      response_body = JSON.parse(response.body)
      self.cupix_trace_id = response_body['result']['cupix_trace_id']
      Cupix::Logger.info('Success to get cupix-trace-id when Capture create', class: self.class.name, function: __method__, cupix_trace_id: self.cupix_trace_id)
    else
      fallback_cupix_trace_id
      Cupix::Logger.info("#{message} when Capture create", class: self.class.name, function: __method__, response_body: response.body, cupix_trace_id: self.cupix_trace_id)
    end
  end
rescue Timeout::Error
  fallback_cupix_trace_id
  Cupix::Logger.error('Timeout while getting cupix-trace-id', class: self.class.name, function: __method__, cupix_trace_id: self.cupix_trace_id)

호출되는 downstream URL 은 production us-west-2 (uswe2, tenant cupix) 기준:

when 'uswe2'
  'https://tkyb8r1rlg.execute-api.us-west-2.amazonaws.com'

Fallback 로직 (실제로 두 timeout 사건 모두 이 경로로 복구되었다):

def fallback_cupix_trace_id
  self.cupix_trace_id = respond_to?(:uuid) ? self.uuid : SecureRandom.uuid
  Cupix::Logger.info('Fallback to use uuid as cupix-trace-id', class: self.class.name, function: __method__, cupix_trace_id: self.cupix_trace_id)
end

기대 동작: 10초 내 CupixTrace API Gateway 가 200 응답을 반환하고 canonical cupix_trace_id 를 저장. 실제 동작: 04:44:50, 04:48:46 KST 두 시점에 10초 안에 응답을 받지 못해 Timeout::Error raise → rescue → local UUID 로 저장.

Log Evidence#

Datadog query 사용:

service:cupixworks-worker "Timeout while getting cupix-trace-id"

결과 (14일 창):

{"timestamp":"2026-07-02 04:48:46","status":"error","message":"Timeout while getting cupix-trace-id","class":"Editing","function":"generate_cupix_trace_id"}
{"timestamp":"2026-07-02 04:44:50","status":"error","message":"Timeout while getting cupix-trace-id","class":"Editing","function":"generate_cupix_trace_id"}

Fallback 성공 로그 (같은 시점, info level):

service:cupixworks-worker "Fallback to use uuid as cupix-trace-id"

{"timestamp":"2026-07-02 04:48:46","status":"info","message":"Fallback to use uuid as cupix-trace-id","class":"Editing","function":"fallback_cupix_trace_id"}
{"timestamp":"2026-07-02 04:44:50","status":"info","message":"Fallback to use uuid as cupix-trace-id","class":"Editing","function":"fallback_cupix_trace_id"}

동일 24h 창에서 CupixTrace 정상 호출 로그가 다수 (@function:generate_cupix_trace_id status:info) 확인되어, 서비스가 전면 outage 상태가 아니었음을 확인:

service:cupixworks-worker "cupix-trace-id"

→ 04:57:33 ~ 05:11:00 KST 사이 최소 18건의 Success to get cupix-trace-id when Capture create info 로그가 반환됨. 즉 후속 트래픽은 정상.

동일 14일 창에서 @function:generate_cupix_trace_id status:(error OR warn) 검색 결과는 위 2건이 전부. 재발성 문제는 아니다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

없음. 코드는 이미 rescue Timeout::Error → fallback_cupix_trace_id 로 정상 degrade 하고 있으며, Editing 저장은 실패하지 않았다. 사용자 영향 없음.

단기 개선 (1주 이내)#

• 로그 레벨 재조정 검토 (app/models/concerns/tracable.rb:33): 이 조건은 명확히 예상된 operational scenario (외부 dependency 의 transient 지연 + 정상 fallback) 이다. error 레벨은 on-call 알람을 유발할 수 있으므로 warn 으로 낮추는 것이 관례상 적절하다. (MEMORY 참고: 유사한 AUTH20022/AUTH20023 사례에서 사용자가 post-merge 로 log level 하향을 요청.)
• Timeout retry 도입 검토: Timeout::Error rescue 브랜치에서 1회 짧은 재시도 (예: 3초) 후에도 실패 시 fallback. 이렇게 하면 canonical trace id 확보율이 향상되며, 재시도로도 실패한 진짜 이상 상황만 error 로 남길 수 있다. (구현 코드는 별도 티켓에서 논의)

장기 개선 (재발 방지)#

• CupixTrace API Gateway/Lambda 쪽 p95/p99 latency 를 지속 모니터링. 10s 초과 스파이크가 systematic 해질 경우 Timeout.timeout 값을 상향하거나 async(예: after_create + 워커 재시도) 로 이동시켜 Editing.create 핫패스에서 분리.
• Fallback UUID 로 저장된 Editing 레코드를 나중에 reconcile 하여 canonical cupix_trace_id 로 교체하는 백그라운드 작업 (선택). 현재는 두 건뿐이라 수동 처리도 가능.

Monitoring#

Datadog dashboard timeseries 로 아래 쿼리를 사용하여 재발 여부를 추적한다:

sum:cupixworks.worker.logs{service:cupixworks-worker,status:error} by {message}.rollup(sum, 3600)

또는 직접 log-based metric 이 없다면 log search 그래프로:

service:cupixworks-worker "Timeout while getting cupix-trace-id"

Fallback 발동 빈도 모니터링:

service:cupixworks-worker "Fallback to use uuid as cupix-trace-id"

Fallback 이 24h 내 5건 이상 발생하면 CupixTrace 서비스 오너에게 latency 확인을 요청한다.

Risk Assessment#

• Risk level: low — 두 건에 그친 transient 이슈, graceful fallback 확인, 사용자 영향 없음.
• 예상 복잡도: trivial — 로그 레벨 downgrade 만 하면 즉시 종료 가능. Retry 도입은 standard.