ES /docs

Quote#schedule_apply! logs validation errors as ERROR — missing exception filtering

RCA: [Quote][GYVGXJU55F] Quote application failed: Billable already has a scheduled quote: 870

Overview#

What Happened#

2026-07-22 00:54 KST 경 cupixworks-api (production, ap-southeast-2) 에서 back-office 담당자가 PUT /api/v1/admin/quotes/{id}/apply 로 미래 시작일(2026-07-29) 의 Quote 를 Workspace 530 에 적용하려다 BILL10000 — Billable already has a scheduled quote: 870 로 실패했다. 직전 00:53 에 이미 다른 Quote(number R3B14IOIQL, id 870) 가 같은 Workspace 에 스케줄된 상태였기 때문이다. 이후 약 15분 동안 담당자가 6개의 서로 다른 Quote 로 재시도하며 동일 에러가 반복되어 총 7건이 error 로그로 남았다.

Quick Facts#

Field Value
exception.class Cupix::Errors::Billing
exception.message Billable already has a scheduled quote: 870
error.code BILL10000
top_frame app/models/quote.rb (schedule_apply!)
env production / ap-southeast-2
tenant cupix
HTTP status 400 (PUT /api/v1/admin/quotes/{id}/apply)

Affected Teams#

Team / Domain Error Count Impact
Back office / Accounting (Retool) 7 (Workspace 530 대상 반복 재시도) 미래 시작일 Quote 를 적용하지 못해 라이선스 발급 워크플로우가 15분간 진행되지 않음. 실제 서비스 사용자 영향 없음.

Timeline#

  1. 2026-07-22 00:53:07 KST — Quote R3B14IOIQL (id 870) 가 Workspace 530 에 Schedule quote application for 2026-07-29 로 정상 등록됨 → workspace.scheduled_quote_id = 870 세팅.
  2. 2026-07-22 00:54:03 KST — Quote GYVGXJU55F 로 재적용 시도 → Billable already has a scheduled quote: 870 (본 클러스터의 first_seen).
  3. 2026-07-22 00:54:19 KST — Quote M9X89PV6G6 (id 874) 재시도 → 동일 에러.
  4. 2026-07-22 00:55:27 KST — Quote ZT5TKAT9CA (id 876) 재시도 → 동일 에러.
  5. 2026-07-22 00:58:15 KST — Quote F43544W7U8 (id 878) 재시도 → 동일 에러.
  6. 2026-07-22 01:06:13 KST — Quote VA8VQHH64X (id 880) 재시도 → 동일 에러.
  7. 2026-07-22 01:06:49 KST — Quote N7KE58TH44 (id 884) 재시도 → 동일 에러.
  8. 2026-07-22 01:08:37 KST — Quote U5XQ1208JW (id 886) 재시도 → 동일 에러. 이후 재시도 중단.

Error Log#

Datadog Logs

text
[Quote][GYVGXJU55F] Quote application failed: Billable already has a scheduled quote: 870

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 1 (본 fingerprint) / 실제로는 동일 원인으로 7건이 15분 사이 발생
  • 최초 발생: 2026-07-22 00:54:03 KST
  • 최근 발생: 2026-07-22 00:54:03 KST

Root Cause Summary#

TSLA-12975 (defer billing switch for future-dated quote applies) 로 도입된 Quote#schedule_apply! 는 billable(Workspace 530) 에 이미 scheduled_quote_id 가 세팅되어 있고 그 값이 현재 적용하려는 Quote 의 id 와 다르면 Cupix::Errors::Billing (BILL10000) 을 raise 한다. 담당자가 00:53 에 Quote 870 을 미래 시작일(2026-07-29) 로 정상 스케줄한 뒤, 00:54 부터 서로 다른 Quote 번호로 재적용을 반복 시도하면서 이 방어 로직에 걸린 것이 근본 원인이다. 즉 정상 방어 로직이 back-office 재시도 시나리오를 error 레벨로 로깅하여 노이즈로 감지된 케이스이며, 서비스 사용자 영향은 없다. 다만 (1) 재시도가 15분간 7회 반복된 점, (2) HTTP 400 (client-side input error) 임에도 서버 error 로그로 남는 점, (3) 담당자가 새 Quote 로 대체하려는 의도인지 실수인지 UX 상 명확하지 않은 점이 개선 여지로 남는다.

Technical Analysis#

Code Path#

  • Entry point: app/controllers/api/v1/admin/quotes_controller.rb:37 (Api::V1::Admin::QuotesController#apply)
  • Repository: app/repositories/admin/quote_repository.rb:45 (Admin::QuoteRepository#apply@model.apply!)
  • Model orchestrator: app/models/quote.rb (Quote#apply!) — 로그 Quote application begins ... 를 남긴 뒤 미래 시작일이면 schedule_apply! 분기.
  • Failure point: Quote#schedule_apply! — TSLA-12975 (2f412c97d) 에서 신규 추가된 private 메서드.

controller/repository 진입:

app/controllers/api/v1/admin/quotes_controller.rb:37-41ruby
def apply
  @model = repository_instance.apply

  show
end
app/repositories/admin/quote_repository.rb:45-50ruby
def apply
  raise Cupix::Errors::Billing.new(code: 'BILL10000', reason: 'Permission denied operation: Only accounting deparment can apply the quote') unless Pundit.policy(self.current_user, @model).apply?

  @model.apply!
  @model
end

Quote 모델 진입 및 미래 시작일 분기 (TSLA-12975 이후):

app/models/quote.rb (Quote#apply!, refactored in 2f412c97d)ruby
def apply!
  Cupix::Logger.info("[Quote][#{number}] Quote application begins #{billable.class.name} #{billable.id}")
  check_appliable

  _billing_started_at, _billing_expires_at = extract_billing_dates

  if _billing_expires_at > MAX_BILLING_EXPIRES_AT
    raise Cupix::Errors::Parameter.new(code: 'ARG14000', reason: 'Billing expiration date exceeds the maximum allowed value')
  end

  ActiveRecord::Base.transaction do
    if _billing_started_at > Time.zone.today
      schedule_apply!(_billing_started_at)
    else
      activate_apply!(_billing_started_at, _billing_expires_at)
    end
  end
rescue Cupix::Errors::Parameter => e
  Cupix::Logger.error("[Quote][#{number}] Invalid Parameter : #{e.message}", ...)
  raise e
rescue StandardError => e
  Cupix::Logger.error("[Quote][#{number}] Quote application failed: #{e.message}")
  raise e

실제 실패 지점 — schedule_apply! 의 첫 가드:

app/models/quote.rb (Quote#schedule_apply!, added in 2f412c97d)ruby
def schedule_apply!(billing_started_at)
  if billable.scheduled_quote_id.present? && billable.scheduled_quote_id != id
    raise Cupix::Errors::Billing.new(
      code: 'BILL10000',
      reason: "Billable already has a scheduled quote: #{billable.scheduled_quote_id}"
    )
  end

  Cupix::Logger.info("[Quote][#{number}] Schedule quote application for #{billing_started_at} on #{billable.class.name} #{billable.id}")

  billable.update!(
    scheduled_quote: self,
    scheduled_billing_started_at: billing_started_at
  )

  applied_state! if state_paid?
end

activate_apply! 는 정상 종료 시 scheduled_quote: nil 로 초기화하지만, 스케줄된 Quote 를 다른 Quote 로 교체하는 경로는 존재하지 않는다. 따라서 어떤 Quote 든 scheduled_quote_id 가 이미 다른 값으로 세팅되어 있으면 새 Quote 는 적용될 수 없다.

app/models/quote.rb (Quote#activate_apply! 후반부)ruby
update_attrs = {
  quote: self,
  billing_started_at: billing_started_at,
  billing_expires_at: billing_expires_at,
  # ...
  scheduled_quote: nil,
  scheduled_billing_started_at: nil
}
billable.update!(update_attrs)

기대 동작: 담당자가 새 Quote 를 apply 하면, 이전 스케줄된 Quote 는 자동으로 취소되거나 명시적 취소 API 를 통해 정리된 뒤 새 Quote 가 스케줄되어야 함.

실제 동작: 이전 스케줄 Quote(id 870) 가 그대로 남아 있어 신규 apply 가 모두 400 으로 튕겨나가며, 담당자가 다른 Quote 번호로 여러 번 재시도해도 결과는 동일.

Log Evidence#

Datadog 쿼리 (본 클러스터):

text
service:cupixworks-api status:error @environment:production "[Quote][GYVGXJU55F] Quote application failed: Billable already has a scheduled quote: 870"

동일 Workspace/원인의 확장 쿼리:

text
service:cupixworks-api "scheduled quote"

핵심 로그 시퀀스 (Workspace 530 기준):

text
2026-07-22 00:53:07 INFO  [Quote][R3B14IOIQL] Quote application begins Workspace 530
2026-07-22 00:53:07 INFO  [Quote][R3B14IOIQL] Schedule quote application for 2026-07-29 on Workspace 530
2026-07-22 00:54:03 INFO  [Quote][GYVGXJU55F] Quote application begins Workspace 530
2026-07-22 00:54:03 ERROR [Quote][GYVGXJU55F] Quote application failed: Billable already has a scheduled quote: 870
2026-07-22 00:54:19 INFO  [Quote][M9X89PV6G6] Quote application begins Workspace 530
2026-07-22 00:54:19 ERROR [Quote][M9X89PV6G6] Quote application failed: Billable already has a scheduled quote: 870
2026-07-22 00:55:27 ERROR [Quote][ZT5TKAT9CA] Quote application failed: Billable already has a scheduled quote: 870
2026-07-22 00:58:15 ERROR [Quote][F43544W7U8] Quote application failed: Billable already has a scheduled quote: 870
2026-07-22 01:06:13 ERROR [Quote][VA8VQHH64X] Quote application failed: Billable already has a scheduled quote: 870
2026-07-22 01:06:49 ERROR [Quote][N7KE58TH44] Quote application failed: Billable already has a scheduled quote: 870
2026-07-22 01:08:37 ERROR [Quote][U5XQ1208JW] Quote application failed: Billable already has a scheduled quote: 870

각 실패는 HTTP 400 응답으로 이어짐:

json
{
  "message": "[400] PUT /api/v1/admin/quotes/886/apply (Api::V1::Admin::QuotesController#apply)",
  "error": {
    "reason": "Billable already has a scheduled quote: 870",
    "code": "BILL10000",
    "message": "Billable already has a scheduled quote: 870",
    "class": "Cupix::Errors::Billing"
  }
}

R3B14IOIQL 로그만 유일하게 Schedule quote application for 2026-07-29 정상 정보 로그로 마무리되고, 이후 모든 재시도 Quote 는 error 로그만 남긴다 → 재시도 담당자가 첫 번째 스케줄된 Quote 를 인지하지 못했거나 교체하려는 시나리오로 추정.

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 back-office 담당자가 미래 시작일(2026-07-29) Quote 를 이미 스케줄한 뒤(Quote id 870), 다른 Quote 번호로 재적용을 반복 시도하여 schedule_apply! 의 기존 스케줄 가드에 걸림 00:53:07 R3B14IOIQL info 로그(Schedule quote application for 2026-07-29 on Workspace 530) 뒤 00:54~01:08 사이 7건의 다른 quote 번호로 PUT /api/v1/admin/quotes/{876,878,880,884,886,...}/apply 요청이 모두 동일 workspace 530 에서 발생. code path app/models/quote.rb#schedule_apply! 의 raise 조건과 로그 메시지가 정확히 일치. Confirmed
H2 동시성/race condition — 여러 Quote 가 동시에 apply 되면서 scheduled_quote_id 세팅과 충돌 없음 로그 타임스탬프가 16초~2분 간격으로 순차 발생. 동일 tid/session 재시도 패턴. apply!ActiveRecord::Base.transaction 안에서 실행되어 원자적. Rejected
H3 데이터 무결성 손상 — scheduled_quote_id 필드가 오래된 데드 데이터로 남아 있음 없음 직전 성공 로그(R3B14IOIQL → id 870, 00:53:07)가 명확히 존재. 정상 세팅된 값. Rejected
H4 신규 배포된 TSLA-12975 코드의 회귀 — 예전에는 통과하던 케이스가 새로 raise 됨 TSLA-12975(2f412c97d) 가 schedule_apply! 및 해당 raise 를 신규 도입한 것은 사실 (git show 확인) 도입된 가드는 의도적(미래 스케줄 중복 방지) 이며 raise 메시지도 설계된 값. spec spec/lib/cupix/cron/scheduled_quote_spec.rb, spec/models/quote_spec.rb 가 함께 추가됨. 회귀가 아닌 by-design 동작. Rejected (by-design)

Fix Recommendation#

본 에러는 코드 결함이 아니라 정상 방어 로직이 back-office 재시도 UX 로 인해 error 레벨로 다량 노출된 케이스다. 아래 개선안은 우선순위 순.

즉시 조치 (Critical)#

  • 별도의 코드 즉시 조치는 필요하지 않음(서비스 사용자 영향 없음, 이미 배포된 로직대로 정상 동작).
  • 운영/CS 채널에 back-office 담당자에게 "Workspace 530 에 이미 미래 스케줄 Quote(id 870, 시작일 2026-07-29) 가 존재하므로 새 Quote 로 대체하려면 별도의 취소/해제 절차가 필요하다" 를 안내 (프런트엔드/운영 조율 필요 — 자동 code-fix 대상 아님).

단기 개선 (1주 이내)#

  • Log level 조정: app/models/quote.rbapply! 에 있는 rescue StandardError => eCupix::Logger.error("[Quote][#{number}] Quote application failed: #{e.message}")Cupix::Errors::Billing (특히 BILL10000 계열의 사용자 입력 검증성 예외) 에 한해 warn 으로 낮추는 것을 검토. 무결성/시스템 오류는 error 유지. 그렇지 않으면 back-office 담당자의 정상 재시도가 매번 error 알림/대시보드 오염을 유발함.
  • 스케줄 취소 API 필요성 재확인: schedule_apply! 에서 세팅되는 billable.scheduled_quote_id 를 다른 Quote 로 교체하거나 취소하는 admin API 가 있는지 검토. 없다면 back-office 팀 요청 사항으로 도입.
  • 에러 응답 개선: PUT /api/v1/admin/quotes/{id}/apply 응답의 error.reason 에 기존 스케줄 Quote id 뿐 아니라 numberscheduled_billing_started_at 도 함께 노출하여 Retool UI 에서 담당자가 상황을 즉시 파악할 수 있도록.

장기 개선 (재발 방지)#

  • Retool back-office 화면에서 Workspace/Team/Facility 의 현재 scheduled_quote_idscheduled_billing_started_at 을 apply 화면 진입 시점부터 노출하여 중복 시도 자체를 사전에 차단.
  • 스케줄 Quote 의 라이프사이클(생성 → 대기 → cron 활성화 or 취소) 이 문서화되었는지 docs/license-creation-flow.md 에 확인/보강. 특히 "이미 스케줄된 Quote 가 있을 때 새 Quote 를 어떻게 대체하나?" 는 현재 문서에 없음.

Monitoring#

schedule_apply! 가드에 걸리는 빈도를 별도 계측하여 반복 시도 시 back-office 팀에 알림. 현재는 일반 error 와 섞여 있어 노이즈 판별이 어렵다.

Datadog Log-based Metric 쿼리 (release dashboard timeseries widget 용):

text
service:cupixworks-api @environment:production "Billable already has a scheduled quote"

전체 Quote apply 실패 추이:

text
service:cupixworks-api @environment:production "Quote application failed"

동일 billable 반복 재시도 감지용 (Workspace/Team/Facility id 별 분포는 대시보드 group-by 로 처리):

text
service:cupixworks-api @environment:production "Quote application begins Workspace"

주의: 위 쿼리들은 monitor-only 문법(| stats, count by(...) 등) 을 포함하지 않으므로 timeseries widget 에 그대로 사용 가능. group-by 는 widget 설정에서 지정.

Risk Assessment#

  • Risk level: low — 서비스 사용자 영향 없음. 방어 로직이 정상 동작한 케이스이며, 데이터 손상이나 재정 손실 없음. 다만 back-office 워크플로우 지연(15분) 및 error 로그 노이즈 발생.
  • 예상 복잡도: trivial — 즉시 조치 불필요. log-level 조정만 진행할 경우 trivial. 스케줄 취소 API 신설까지 확장하면 standard.