ES /docs

failed to get captured area - error: 500 Internal Server Error

RCA: failed to get captured area - error: 500 Internal Server Error

Overview#

What Happened#

2026-07-15 21:36 KST 부터 21:42 KST 사이에 cupixvista-api-migration-worker (tesla 리포지토리, CUPIXVISTA launch mode, migrationworker role) 에서 Cupix::Cron::Facility.flush_stale_captured_size 크론이 실행되면서 downstream voxel-service Lambda 로의 PUT /captured_area 호출이 5회 연속 500 Internal Server Error 를 반환했다. Lambda 응답 본문을 확인한 결과, 원인은 Athena GetQueryExecution API 에서 발생한 ThrottlingException: Rate exceeded 였다. 영향을 받은 facility 는 최소 5건(ID 604, 607, 609, 610, 612)이며, captured_size 갱신이 실패해 stale 상태로 남았다.

Quick Facts#

Field Value
exception.class Cupix::Errors::System (code SYS20000)
exception.message failed to get captured area - error: 500 Internal Server Error
top_frame app/services/cupix/voxel_service.rb:99
downstream voxel-service Lambda → Athena GetQueryExecution ThrottlingException
runtime Ruby 3.3.7 (rest-client/2.1.0)
env production, us-west-2, tenant=cupix, launch_mode=CUPIXVISTA

Affected Teams#

Team / Domain Error Count Impact
cupixvista-api-migration-worker 5 5개 facility 의 captured_size 갱신 실패 (state=stale 유지)

동일 svc:cupixvista-api-migration-worker::unknown scope 아래 진행 중인 status board 인시던트 에는 관련 클러스터 3개(a558bd06..., fe12d217..., 3a8d30cc...)가 묶여 있다.

Timeline#

  1. 2026-07-15 21:31 KST — 매 4시간 :31분에 실행되는 flush_stale_captured_size 크론이 기동 (스케줄: 31 */4 * * *).
  2. 2026-07-15 21:36 KST — Facility 604 부터 Flushing stale captured size 로그 시작, 첫 실패 발생.
  3. 2026-07-15 21:38 ~ 21:42 KST — Facility 604, 607, 609, 610 순차 실패 (500 Internal Server Error).
  4. 2026-07-15 21:42:20 ~ 21:42:28 KST — voxel-service Lambda 가 초당 여러 건의 Athena ThrottlingException: Rate exceeded (max retries: 3) 응답 반환.
  5. 2026-07-15 21:44:41 KST — Facility 612 는 downstream 이 이번엔 503 Service Unavailable 반환 (동일 fingerprint 의 sister cluster fe12d217... 로 분류).

Error Log#

Datadog Logs

text
failed to get captured area - error: 500 Internal Server Error

Impact#

  • Service: cupixvista-api-migration-worker
  • 발생 횟수: 5
  • 최초 발생: 2026-07-15 21:36 KST
  • 최근 발생: 2026-07-15 21:42 KST

기능적 영향은 제한적이다. flush_stale_captured_size 는 4시간마다 재실행되며 실패한 facility 는 captured_size_state: :stale 이 유지되어 다음 주기에 다시 시도된다. 다만 batch 내 다른 facility 요청까지 throttle 를 유발할 수 있어, 스로틀 구간에 걸린 batch 는 대부분 실패로 종료될 가능성이 높다.

Root Cause Summary#

Cupix::Cron::Facility.flush_stale_captured_size 가 최대 30개 stale facility 를 find_each 로 순회하며 각 건마다 Cupix::VoxelService.captured_area! 를 호출한다. 이 호출은 voxel-service Lambda 로 넘어가 Athena 에서 start_query_execution 후 결과가 나올 때까지 while True 루프로 get_query_execution 을 폴링한다. 이 폴링 루프에 sleep/backoff 가 없어 Athena GetQueryExecution API 의 계정별 rate limit 을 초과하고, boto3 기본 standard retry (max 3회) 를 모두 소진한 뒤 ThrottlingException: Rate exceeded 를 500 으로 응답한다. tesla 측 Cupix::VoxelService.captured_area!RestClient::Exception 을 그대로 Cupix::Errors::System 으로 승격시켜 크론에 에러를 전파한다.

Technical Analysis#

Code Path#

  • Entry point: config/schedule.rb:105every '31 */4 * * *' 로 4시간마다 실행.
  • Cron: lib/cupix/cron/facility.rb:97Facility.stale_captured_size.limit(30).find_each 로 순차 호출.
  • HTTP 호출: app/services/cupix/voxel_service.rb:89PUT #{$CUPIX_VOXEL_SERVICE_URL}/captured_area.
  • Failure point (tesla): app/services/cupix/voxel_service.rb:96-99RestClient::ExceptionCupix::Errors::System 으로 재발생.
  • Failure origin (downstream): services/voxel/lambda/captured_area.py:49-53 — Athena 폴링 루프.
lib/cupix/cron/facility.rb:90-106ruby
def flush_stale_captured_size
  session = Cupix::Initializer::User.tesla_internal_user.default_session
  # ...
  ::Facility.stale_captured_size.limit(30).find_each do |facility|
    Cupix::Logger.info("Flushing stale captured size for Facility #{facility.id}", ...)

    if facility.calculate_captured_size(session: session)
      Cupix::Logger.info("Successfully flushed stale captured size for Facility #{facility.id}", ...)
    else
      Cupix::Logger.warn("Failed to flush stale captured size for Facility #{facility.id}", ...)
    end
  end
end
app/services/cupix/voxel_service.rb:88-99ruby
begin
  response = Cupix::HttpClient.put("#{$CUPIX_VOXEL_SERVICE_URL}/captured_area", body.to_json, headers)

  body = JSON.parse(response.body)

  Cupix::Logger.info("Completed - total: #{body.dig('results', 'total')}, ...", ...)

  body['results']
rescue RestClient::Exception => e
  Cupix::Logger.error("failed to get captured area - error: #{e.message}", ...)

  raise Cupix::Errors::System.new(code: 'SYS20000', reason: "failed to get captured area - error: #{e.message}")
services/voxel/lambda/captured_area.py:11-53python
config = Config(
  retries = {
    'max_attempts': 3,
    'mode': 'standard'
  }
)

athena = boto3.client('athena', config=config)

def run_athena_query(query, output_location):
  # ...
  response = athena.start_query_execution(...)
  query_execution_id = response['QueryExecutionId']

  # Wait for Athena query to finish
  while True:
    response = athena.get_query_execution(QueryExecutionId=query_execution_id)
    if response['QueryExecution']['Status']['State'] in ('SUCCEEDED', 'FAILED', 'CANCELLED'):
      break

기대 동작: Athena 쿼리 실행 상태 확인 시 짧은 sleep(예: 1~2초)과 exponential backoff 를 두어 계정 rate limit 을 준수.

실제 동작: 폴링 루프가 tight loop 로 get_query_execution 을 호출 → Athena API rate limit 초과 → boto3 standard retry(3회) 소진 후 ThrottlingException 예외로 lambda 실패 → 500 응답.

또한 tesla 측 flush_stale_captured_size 는 여러 facility 를 즉시 순차 호출하기 때문에 Lambda 인스턴스가 동시에 여러 개 warm 상태에서 각자 Athena 를 폴링하게 되어 계정 단위의 GetQueryExecution TPS 를 더 빠르게 소진시킨다.

Log Evidence#

Datadog 쿼리:

text
service:cupixvista-api-migration-worker status:error "failed to get captured area - error: 500 Internal Server Error"

Cron 실행 흐름 (worker 측):

text
2026-07-15 21:38:03 info  Flushing stale captured size for Facility 604
2026-07-15 21:39:23 error failed to calculate captured size for Facility ID: 604, error: failed to get captured area - error: 500 Internal Server Error
2026-07-15 21:39:23 info  Flushing stale captured size for Facility 607
2026-07-15 21:41:37 error failed to calculate captured size for Facility ID: 607, error: failed to get captured area - error: 503 Service Unavailable
2026-07-15 21:41:37 info  Flushing stale captured size for Facility 609
2026-07-15 21:42:27 error failed to calculate captured size for Facility ID: 609, error: failed to get captured area - error: 500 Internal Server Error
2026-07-15 21:42:27 info  Flushing stale captured size for Facility 610
2026-07-15 21:42:27 error failed to calculate captured size for Facility ID: 610, error: failed to get captured area - error: 500 Internal Server Error
2026-07-15 21:42:27 info  Flushing stale captured size for Facility 612
2026-07-15 21:44:41 error failed to calculate captured size for Facility ID: 612, error: failed to get captured area - error: 503 Service Unavailable

Downstream voxel-service Lambda 응답 (동일 시간대, 다수 발생):

Datadog 쿼리:

text
"Voxel::CapturedArea" ("status_code: 500" OR "Athena query failed")
text
2026-07-15 21:42:20 info  Voxel::CapturedArea | handler_response - status_code: 500, body: "Failed to calculate captured area - An error occurred (ThrottlingException) when calling the GetQueryExecution operation (reached max retries: 3): Rate exceeded"
2026-07-15 21:42:21 info  Voxel::CapturedArea | handler_response - status_code: 500, body: "Failed to calculate captured area - An error occurred (ThrottlingException) when calling the GetQueryExecution operation (reached max retries: 3): Rate exceeded"
2026-07-15 21:42:22 info  Voxel::CapturedArea | handler_response - status_code: 500, body: "Failed to calculate captured area - An error occurred (ThrottlingException) when calling the GetQueryExecution operation (reached max retries: 3): Rate exceeded"
2026-07-15 21:42:23 info  Voxel::CapturedArea | handler_response - status_code: 500, body: "Failed to calculate captured area - ... (reached max retries: 3): Rate exceeded"
2026-07-15 21:42:26 info  Voxel::CapturedArea | handler_response - status_code: 500, body: "Failed to calculate captured area - ... (reached max retries: 3): Rate exceeded"

같은 시간대에 정상 응답(200)도 다수 관측되며, throttling 이 계정 전체 API 콜에서 발생하고 있음을 시사한다:

text
2026-07-15 21:46:23 info  Voxel::CapturedArea | handler_response - status_code: 200, body: {"facility_key": "1def0u", "results": {"total": 104, ...}}

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 voxel-service Lambda 의 Athena GetQueryExecution 폴링 루프가 sleep/backoff 없이 tight loop 로 호출되어 계정 단위 rate limit 초과 (ThrottlingException) Lambda 응답 본문에 ThrottlingException ... reached max retries: 3: Rate exceeded 명시; captured_area.py:49-53 폴링 루프에 sleep 부재; 21:42:20~21:42:28 사이 다수의 동일 에러 관측 Confirmed
H2 Athena partition 미존재로 인한 500 (e.g., ALTER TABLE ADD PARTITION 실패) captured_area.py:107-108 은 partition 실패 시 500 반환 실패 로그 본문이 ThrottlingException 을 명시하며 partition 관련 에러 로그 없음 Rejected
H3 tesla CUPIX_VOXEL_SERVICE_URL 설정 오류 또는 endpoint down 워커가 500/503 을 지속적으로 받음 같은 endpoint 에 대해 21:45~21:49 KST 사이 정상 status_code: 200 응답 다수 (facility_key 1def0u, bk7vdk 등) Rejected
H4 요청 body 오류 (facility_key 누락 등, 400) Lambda 응답은 500 (KeyError 는 400 처리 — captured_area.py:133-137) Rejected
H5 Athena 쿼리 자체 실패 (FAILED 상태) 실패 응답에 State 관련 문구 없이 boto3 client-side ThrottlingException 로 즉시 종료; Athena query id ... state: FAILED 로그 없음 Rejected

Fix Recommendation#

즉시 조치 (Critical)#

  • 파일: data-pipeline-functions/services/voxel/lambda/captured_area.py:49-53
    • 폴링 루프에 time.sleep(...) 을 추가해 Athena GetQueryExecution 호출 빈도를 낮춘다. 방향: 첫 1초 sleep 후 지수 백오프 (예: 1s → 2s → 4s, 상한 10s). Athena 는 통상 1~수 초 내 상태 변경이 완료되므로 사용자 지연은 무시할 수 있는 수준.
    • boto3 retry mode 를 adaptive 로 상향 (Config(retries={'max_attempts': 5, 'mode': 'adaptive'})) — client-side throttling token bucket 이 활성화되어 Rate 초과 시 자동으로 요청 속도를 줄인다.
  • 파일: tesla/lib/cupix/cron/facility.rb:97-105
    • find_each 사이에 짧은 sleep (예: sleep 0.5) 을 두거나, 여러 tenant / 리전 워커가 동시에 실행되지 않도록 크론 스케줄을 tenant 별로 offset 을 부여한다. 근거: 여러 launch_mode(CUPIXWORKS/CUPIXVISTA) 워커가 동일 AWS 계정의 Athena API 를 공유 사용.

단기 개선 (1주 이내)#

  • voxel-service Lambda 에서 botocore.exceptions.ClientErrorThrottlingException 을 명시적으로 catch 하여 500 대신 429 (또는 503 Retry-After) 를 반환하도록 변경. tesla Cupix::VoxelService.captured_area! 는 429/503 을 감지해 재시도 큐로 위임할 수 있도록 재시도 로직을 도입한다.
  • Cupix::Cron::Facility.flush_stale_captured_size 를 동기 순회 대신 RefreshCapturedSizeWorker (이미 존재, app/workers/refresh_captured_size_worker.rb) 로 async enqueue 하고 Sidekiq retry 정책 (backoff) 을 활용하도록 변경. 이렇게 하면 한 facility 실패가 batch 전체를 밀리게 하지 않는다.

장기 개선 (재발 방지)#

  • Athena 폴링 패턴 자체를 Step Functions + AthenaGetQueryExecution task token 방식으로 전환하거나, API Gateway 뒤의 Lambda 를 async invocation + SQS 결과 통지 구조로 리팩터하여 계정 단위 Athena TPS 한도(기본 GetQueryExecution 100 TPS, StartQueryExecution 20 TPS)를 지속 준수.
  • Athena 서비스 쿼터를 확인하고 필요 시 AWS Service Quotas 로 상향 요청.
  • 여러 tenant/서비스가 같은 AWS 계정에서 Athena 를 공유하는 현황을 workspace 단위로 정리 (계정 분리 또는 workgroup 별 쿼터).

Monitoring#

  • 추가 메트릭:
    • voxel-service Lambda 에서 ThrottlingException 발생 시 사용자 정의 CloudWatch metric emit (VoxelService.CapturedArea.AthenaThrottled).
    • tesla 측 Cupix::VoxelService.captured_area! 실패 카운트를 status 별 (500/503) 로 tag.

Datadog 쿼리 예시:

text
service:cupixvista-api-migration-worker status:error "failed to get captured area"
text
"Voxel::CapturedArea" "ThrottlingException"
text
service:cupixvista-api-migration-worker "Failed to flush stale captured size"

Risk Assessment#

  • Risk level: medium — 사용자 트래픽 경로가 아니라 백그라운드 크론이므로 즉시 사용자 영향은 적으나, throttling 이 다른 Athena 소비자(voxel calculate_voxels, merge 등) 에도 collateral damage 를 유발할 수 있다.
  • 예상 복잡도: standard — Lambda 폴링 로직에 sleep/adaptive retry 추가는 간단하나, 크론 스로틀 및 async 전환은 회귀 테스트가 필요하다.