RCA: [Cupix::Cron::Integration] failed to renew integration: Refresh access token request is too many

Overview#

What Happened#

2026-07-16 09:07:20 KST 에 cupixworks-migration-worker 에서 실행되던 Cupix::Cron::Integration.renew_before_expiration cron 이 특정 BIM360 integration 1건에 대해 refresh token 갱신을 시도하다 ARG10060 Refresh access token request is too many 에러로 실패했다. 이 에러는 Redis 기반 per-integration lock (Cache::Integration::{id}::Lock::Key) 획득 실패시 발생하며, 동시에 다른 refresh 요청이 진행 중이라는 신호다. cron 은 rescue 후 next 로 다음 integration 으로 진행했으므로 사용자 영향은 없다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-16 09:07:18 KST — cron Cupix::Cron::Integration.renew_before_expiration 시작, refresh_token_due_to_expire 로 만료 임박 candidate 다수를 순회하며 refresh_token 호출 시작
2. 2026-07-16 09:07:20 KST — 특정 integration 에서 check_refresh_request 의 setnx 가 false 반환 → ARG10060 예외 발생, [Cupix::Cron::Integration] failed to renew integration: Refresh access token request is too many 로그 기록
3. 2026-07-16 09:07:20~23 KST — cron 은 rescue 후 나머지 candidate (integrations 1012, 953, 3218, 3219, 5332, 5353, ...) 계속 처리
4. 2026-07-16 13:07 KST (예상) — 다음 cron 주기 (7 */4 * * *) 에 동일 integration 재시도 예정

Error Log#

Datadog Logs

[Cupix::Cron::Integration] failed to renew integration: Refresh access token request is too many

Impact#

• Service: cupixworks-migration-worker
• 발생 횟수: 1 (14일간 이 fingerprint 는 이 1건이 유일 — Datadog "Refresh access token request is too many" 쿼리 검증됨)
• 최초 발생: 2026-07-16 09:07:20 KST
• 최근 발생: 2026-07-16 09:07:20 KST

Root Cause Summary#

Cupix::Cron::Integration.renew_before_expiration cron 이 순회 중이던 특정 BIM360 integration 의 refresh_token 갱신 lock 을 획득하지 못했다. 원인은 동시성 lock 충돌: 같은 integration 에 대해 다른 경로(API access_token 요청 또는 이전 실행 잔류)가 이미 Redis lock (Cache::Integration::{id}::Lock::Key) 을 보유 중이었다. Lock 은 5초 TTL 을 가지며 정상 완료시 unsetnx 로 명시적 해제된다. IntegrationRepository#refresh_token 은 lock 획득 실패시 ARG10060 예외를 던지고, Cupix::Cron::Integration.renew_before_expiration 은 이를 catch 하여 로그를 남기고 next 로 넘어간다. 이 에러는 설계상 방어 로직의 정상 동작 결과이며 데이터 손상이나 사용자 영향은 없다 — 다만 로그 level 이 error 로 기록되어 alerting 신호로 오해될 수 있다.

Technical Analysis#

Code Path#

• Entry point: cron schedule at config/schedule.rb:94 — every '7 */4 * * *'
• Iteration: lib/cupix/cron/integration.rb:7-14
• Lock acquisition: app/repositories/integration_repository.rb:124 (via check_refresh_request at :29-34)
• Failure point: app/repositories/integration_repository.rb:125 (raise ARG10060)
• Rescue at caller: lib/cupix/cron/integration.rb:10-14

every '7 */4 * * *' do # 00:07,04:07,08:07 ...
  # runner 'Cupix::Cron::Record.consume_credits'
  runner 'Cupix::Cron::Floorplan.cleanup_creating_floorplans'
  runner 'Cupix::Cron::Integration.renew_before_expiration'
  runner 'Cupix::Cron::Review.flush_stale_reviews'
  runner 'Cupix::Cron::Record.flush_stale_records'
end

module Cupix::Cron
  class Integration < ::Integration
    def self.renew_before_expiration
      candidates = Integration.refresh_token_due_to_expire
      return nil if candidates.blank?

      candidates.each do |model|
        integration_repository = IntegrationRepository.new(model)
        integration_repository.refresh_token
      rescue StandardError => e
        Cupix::Logger.error("[Cupix::Cron::Integration] failed to renew integration: #{e.message}")

        next
      end
    end
  end
end

def check_refresh_request
  key = @model.cache_key
  value = @model.provider
  lock_key = "#{key}::Lock::Key"
  @model.setnx(lock_key, @model.provider)
end

def uncheck_refresh_request
  key = @model.cache_key
  lock_key = "#{key}::Lock::Key"
  @model.unsetnx(lock_key)
end

begin
  unless check_refresh_request
    raise Cupix::Errors::Parameter.new(code: 'ARG10060', reason: 'Refresh access token request is too many')
  end

  token = operation_class.refresh_token(@model.refresh_token, @model.region)
  uncheck_refresh_request
rescue StandardError => e
  uncheck_refresh_request

  raise e if e.respond_to?(:code) && e.code == 'ARG10060'
  ...

def setnx(lock_key, value)
  return if Rails.cache.is_a?(ActiveSupport::Cache::NullStore)

  lock_acquired = Rails.cache.redis_instance.setnx(lock_key, value)
  Rails.cache.redis_instance.expire(lock_key, 5.second)
  lock_acquired
end

def unsetnx(lock_key)
  return if Rails.cache.is_a?(ActiveSupport::Cache::NullStore)

  Rails.cache.redis_instance.del(lock_key)
end

기대 동작 대비 실제 동작:

• 기대: cron 은 만료 임박 integration 각각에 대해 순차적으로 refresh_token 을 호출하고, integration 별 lock 은 갱신이 완료될 때까지 홀로 보유된다.
• 실제: 이 integration 의 lock 은 다른 refresh 경로(예: 사용자 요청으로 IntegrationRepository#access_token → refresh_token)가 이미 보유하고 있어서 setnx 가 false 를 반환했다. access_token 은 expired_at < 10.minutes.since 일 때 자동으로 refresh_token 을 호출하므로, cron 이 도는 시각과 API 요청이 겹치면 충돌 가능하다.
• 5초 TTL 자체는 이 정도 유즈케이스에서 짧지 않지만, cron 시작과 API 요청이 거의 동시에 진입한 microwindow 에서는 lock 충돌이 발생한다.

Log Evidence#

Datadog 쿼리 (재현용):

service:cupixworks-migration-worker "Refresh access token request is too many"

전체 14일 retention 에서 정확히 1건 확인:

{
  "timestamp": "2026-07-16T00:07:20.789Z",
  "status": "error",
  "service": "cupixworks-migration-worker",
  "dd.service": "cupixworks-api",
  "dd.env": "production",
  "dd.version": "production-us-west-2-20260716T0007Z0-f2b18e95-cupixworks",
  "environment": "production",
  "region": "us-west-2",
  "host": "ip-10-1-144-200.us-west-2.compute.internal",
  "log.file.path": "/var/app/current/log/tesla_production-json.log",
  "message": "[Cupix::Cron::Integration] failed to renew integration: Refresh access token request is too many"
}

동일 시간대(09:07:18~23 KST) 에 다수의 [Integration] refresh token for bim360 integration(N) info 로그가 관찰되어 cron 이 다수 candidate 를 정상 순회하고 있었음을 확인:

09:07:18 info  [Integration] refresh token for bim360 integration(6541) - state: active, ...
09:07:18 info  [Integration] refresh token for bim360 integration(3211) - state: inactive, ...
09:07:18 info  [Integration] refresh token for bim360 integration(5978) - state: active, ...
09:07:20 error [Cupix::Cron::Integration] failed to renew integration: Refresh access token request is too many
09:07:20 info  [Integration] refresh token for bim360 integration(3218) - state: inactive, ...
09:07:22 info  [Integration] refresh token for bim360 integration(6857) - state: inactive, ...
09:07:23 info  [Integration] refresh token for bim360 integration(953)  - state: active, ...

동일 시간 창에 service:cupixworks-api 에서도 [Integration] refresh token for bim360 info 로그가 다수 관찰됨 (사용자 API 요청 경로가 병렬로 토큰 갱신을 유발):

09:06:00 info  cupixworks-api  [Integration] refresh token for bim360 integration(1014)
09:08:34 info  cupixworks-api  [Integration] refresh token for bim360 integration(833)
09:09:34 info  cupixworks-api  [Integration] refresh token for bim360 integration(1706)

Datadog service:cupixworks-migration-worker "Cupix::Cron::Integration" 조회 결과, Refresh access token request is too many 는 이 시점의 유일한 발생이며, 같은 cron 실행 내 대부분의 실패는 별개의 BIM360 Authentication failed: (외부 API 응답 오류) 임 — 본 클러스터의 fingerprint 와는 다른 문제.

Status board 조회 결과:

{
  "scope": "svc:cupixworks-migration-worker::unknown",
  "active": null,
  "recent": [
    { "id": "2026-07-13-svc-cupixworks-migration-worker--unknown-1", "resolved_at": "2026-07-13T05:03:40.105Z" },
    { "id": "2026-07-10-svc-cupixworks-migration-worker--unknown-1", "resolved_at": "2026-07-10T05:13:23.752Z" }
  ]
}

같은 서비스에서 unknown root-cause 로 최근 2건이 자동 해소된 이력이 있으나 별도 cluster id 로, 이 fingerprint 는 신규.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 없음. 코드가 이미 방어 로직으로 예외를 잡고 next 로 진행하며, 다음 cron 주기(4시간 후)에 자동으로 재시도된다. 데이터 손상 없음, 사용자 영향 없음.

단기 개선 (1주 이내)#

• 로그 level 을 warn 으로 강등: lib/cupix/cron/integration.rb:11 의 Cupix::Logger.error 호출을 warn 으로 변경하되 오직 ARG10060 코드에 한정. 그 외 예외(BIM360 인증 실패 등)는 계속 error 를 유지해야 한다. 이유: 이 경로는 예상되는 정상 재시도 시나리오이며 error 알림 신호로는 부적절하다. 참고 사례 (MEMORY.md 의 cc2e2887 AUTH20022/AUTH20023 episode) — 유사한 "예상되는 정상 실패" 는 warn 으로 강등한 전례가 있다.
• 대안: IntegrationRepository#refresh_token 에서 lock 획득 실패시 짧은 backoff(예: 100500ms) 후 1회 재시도. 실제로 lock 을 보유한 다른 refresh 는 대체로 12초 안에 완료되므로 성공률이 높아질 수 있다. 다만 cron 실행 시간이 늘어나므로 단순 log-level 강등을 우선한다.

장기 개선 (재발 방지)#

• cron 의 dedup 을 lock 대신 조건절로: refresh_token_due_to_expire scope 가 반환하는 candidate 를 순회하기 전, 이미 refresh_token_response_body / expired_at 이 최근 값으로 갱신된 항목은 스킵. Redis lock 은 동시성 protection 의 최후 수단으로 남기되, cron 은 stale 여부를 재확인해 불필요한 lock 경쟁을 줄일 수 있다.
• Lock 획득 관측성: check_refresh_request 가 false 를 반환하는 빈도를 metric 으로 (예: integration.refresh.lock_contention.count{provider}) 노출하면 실제 병목 여부를 정량 판단 가능.

Monitoring#

Datadog 대시보드 timeseries widget 용 쿼리 예시:

• Cron 의 lock contention 발생 추이 (fingerprint 별):

  textCopy

  service:cupixworks-migration-worker status:error "Refresh access token request is too many"
  

• 전체 Integration cron 실패 추이(외부 인증 실패 포함):

  textCopy

  service:cupixworks-migration-worker status:error "[Cupix::Cron::Integration] failed to renew integration"
  

• Cron 정상 refresh 발생 빈도 (baseline):

  textCopy

  service:cupixworks-migration-worker "[Integration] refresh token for" status:info
  

writing-datadog-monitoring-queries 가이드에 따라 monitor-only 문법(| stats, count by(...) suffix 등)은 사용하지 않았다. 위 쿼리는 dashboard timeseries widget 에 그대로 사용 가능.

Alert 정책:

• Refresh access token request is too many 단독으로는 알림을 발생시키지 않는다 (예상 방어 로직). 임계값을 두려면 4시간 창당 10건 이상일 때만 warn 알림.

Risk Assessment#

• Risk level: low — 이벤트는 14일간 1건, 데이터/사용자 영향 없음, cron 이 자동 재시도.
• 예상 복잡도: trivial — 로그 level 강등 시 lib/cupix/cron/integration.rb:11 한 줄 (또는 예외 코드 분기 몇 줄) 수정.