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

Overview#

What Happened#

2026-07-15 21:33 KST부터 21:58 KST 사이 cupixworks-migration-worker 서비스에서 Cupix::VoxelService.captured_area! 호출이 총 10건 실패했다. 원인은 downstream voxel Lambda(Voxel::CapturedArea)가 AWS Athena GetQueryExecution API 호출 시 ThrottlingException: Rate exceeded(max retries 3 소진)를 반환하며 500을 낸 것이다. 트리거는 21:31 KST에 실행된 cron Cupix::Cron::Facility.flush_stale_captured_size 로, stale facility 30개에 대해 연속으로 voxel-service 를 호출하면서 Athena API 를 폭주시켰다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-15 21:31 KST — cron 스케줄 every '31 */4 * * *' 이 발화, Cupix::Cron::Facility.flush_stale_captured_size 진입 (config/schedule.rb:105).
2. 2026-07-15 21:33 KST — 첫 실패 로그. 배치에서 처리 중이던 여러 Facility 에 대해 Cupix::VoxelService.captured_area! 가 RestClient::Exception (500) 로 rescue 됨.
3. 2026-07-15 21:34 KST 근방 — voxel-service Lambda 내부 로그에 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" 다수 관측.
4. 2026-07-15 21:58 KST — 마지막 실패 로그 (Facility ID 16255). 이후 배치가 소진되며 자연 종료.

Error Log#

Datadog Logs

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

Impact#

• Service: cupixworks-migration-worker
• 발생 횟수: 10
• 최초 발생: 2026-07-15 21:33 KST
• 최근 발생: 2026-07-15 21:58 KST

Root Cause Summary#

Cron flush_stale_captured_size가 4시간마다 stale 상태 Facility 30개를 find_each 로 순차 처리하며 각 건마다 voxel-service Lambda 의 /captured_area 엔드포인트를 호출한다. Lambda(captured_area.py) 는 요청당 두 번의 Athena 쿼리(파티션 ALTER + SELECT)를 실행하고, 각 쿼리 완료를 athena.get_query_execution 을 sleep 없이 while 루프로 폴링한다 (services/voxel/lambda/captured_area.py:49-52). boto3 클라이언트는 retries.max_attempts=3, mode=standard (같은 파일 11-16 라인) 로만 설정돼 있어 Athena GetQueryExecution 의 계정/리전 단위 TPS 한도를 초과하면 재시도 3회 후 ThrottlingException 을 그대로 상위로 던진다. 결과적으로 최상위 except Exception (139-140 라인) 에서 handler_response(500, ...) 로 변환돼 tesla 쪽에서는 RestClient::Exception 500 으로 관측된다.

Technical Analysis#

Code Path#

• Entry point: cron 스케줄 config/schedule.rb:105
• Cron 본문: lib/cupix/cron/facility.rb:90-106 — stale facility 최대 30개를 순차 처리
• HTTP call site: app/services/cupix/voxel_service.rb:77-105 — voxel-service /captured_area PUT
• Failure point (tesla): app/services/cupix/voxel_service.rb:96-99 — RestClient::Exception rescue 후 Cupix::Errors::System re-raise
• Failure point (downstream Lambda): services/voxel/lambda/captured_area.py:49-52 (tight polling loop) + 138-139 (generic 500 wrapper)

def flush_stale_captured_size
  session = Cupix::Initializer::User.tesla_internal_user.default_session
  if session.blank?
    Cupix::Logger.info('Failed to flush stale captured size: session is nil or blank', class: self.name, function: __method__, module: 'Cupix::Cron')
    return
  end

  ::Facility.stale_captured_size.limit(30).find_each do |facility|
    Cupix::Logger.info("Flushing stale captured size for Facility #{facility.id}", class: self.name, function: __method__, module: 'Cupix::Cron')

    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

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}", class: self.name, function: __method__, facility_key: params[:facility_key], group_by_record: params[:group_by_record])
  raise Cupix::Errors::System.new(code: 'SYS20000', reason: "failed to get captured area - error: #{e.message}")

config = Config(
  retries = {
    'max_attempts': 3,
    'mode': 'standard'
  }
)

athena = boto3.client('athena', config=config)
# ...
def run_athena_query(query, output_location):
  # ...
  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

except Exception as e:
  return handler_response(500, f'Failed to calculate captured area - {str(e)}')

• 기대 동작: 각 facility 의 captured_area 계산이 성공하고 captured_size / captured_size_state=fresh 로 갱신됨.
• 실제 동작: 배치 내 여러 요청이 겹치면서 Athena GetQueryExecution API TPS 한도를 초과 → 3회 재시도 소진 → 500 반환 → 상위 calculate_captured_size 가 false 반환. captured_size_state 는 stale 유지.

Log Evidence#

Datadog query (재현):

service:cupixworks-migration-worker status:error @environment:production "failed to get captured area - error: 500 Internal Server Error"

Tesla worker 에러 로그 (원문):

{
  "timestamp": "2026-07-15 21:58:42",
  "status": "error",
  "message": "failed to calculate captured size for Facility ID: 16255, error: failed to get captured area - error: 500 Internal Server Error",
  "class": "Facility",
  "function": "calculate_captured_size"
}
{
  "timestamp": "2026-07-15 21:58:42",
  "status": "error",
  "message": "failed to get captured area - error: 500 Internal Server Error",
  "class": "Cupix::VoxelService",
  "function": "captured_area!"
}

Downstream voxel-service Lambda 로그 (같은 시간대):

service:voxel-service (matched via keyword "Voxel::CapturedArea")

{
  "timestamp": "2026-07-15 22:04:51",
  "status": "info",
  "message": "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\""
}

Cron 진입 로그 (같은 배치, 성공/실패 혼재):

{
  "timestamp": "2026-07-15 21:56:50",
  "status": "info",
  "message": "Flushing stale captured size for Facility 16255",
  "class": "Cupix::Cron::Facility",
  "function": "flush_stale_captured_size"
}

성공한 요청도 다수 관측됨 (예: 21:45-21:46 KST 여러 건이 200 완료) — 이는 throttling 이 일시적/전역 API rate 기반이며, 배치 전부가 실패한 게 아니라는 것을 뒷받침.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• services/voxel/lambda/captured_area.py:49-52: while True 폴링 루프에 backoff 추가 (예: time.sleep(0.5) 이후 지수 증가, 상한 5s). 현재 루프는 Athena GetQueryExecution 을 최대한 빠르게 반복 호출하여 계정 단위 TPS 를 스스로 소진한다.
• services/voxel/lambda/captured_area.py:11-16: boto3 retries 설정을 standard, max_attempts: 3 에서 adaptive 모드로 상향 또는 max_attempts 를 늘려 client 측에서 exponential backoff 흡수 (adaptive 는 boto3 가 자체적으로 throttling 신호에 맞춰 속도 조절).
• 두 변경 모두 downstream API 변화 없이 Lambda 내부에서만 반영 가능. tesla 쪽 코드 변경은 필요 없음.

단기 개선 (1주 이내)#

• lib/cupix/cron/facility.rb:97: Facility.stale_captured_size.limit(30).find_each 배치를 순차 처리하되 각 반복 사이에 소량 sleep (예: sleep 1) 을 넣거나, Sidekiq job 으로 분산시켜 voxel-service 호출을 시간축에 퍼뜨림. 현재는 30개가 사실상 한 프로세스에서 back-to-back 으로 나가며 downstream 폭주 요인이 됨.
• voxel-service add_partition.py, merge_voxel.py, remove_athena_cache.py 도 동일한 sleep-less 폴링 패턴 여부 확인 (Grep 결과 4개 파일 모두 Athena 사용 — uncertain, needs verification). 동일하면 같은 패턴 적용.

장기 개선 (재발 방지)#

• Athena 쿼리 결과 폴링을 Step Functions / EventBridge 기반 async 로 전환하여 Lambda 실행 시간과 Athena API 호출을 분리.
• voxel-service 응답에 명시적 error code (예: THROTTLED) 를 담아 tesla 가 retry 여부를 판단할 수 있도록 개선. 현재는 tesla 가 body 파싱 없이 RestClient::Exception 만 rescue.
• captured_size 업데이트를 stale 감지 시점에 개별 Sidekiq job 으로 enqueue 하는 방식으로 재설계 (batch cron 폐기), retry backoff 는 Sidekiq 이 담당.

Monitoring#

• Datadog Lambda 5xx 비율 지표 (voxel-service Voxel::CapturedArea):

sum:aws.lambda.errors{functionname:voxel-captured-area}.as_count()

• Athena ThrottlingException 발생 빈도:

sum:aws.athena.processed_bytes{*}.as_count()

(정확한 throttling 카운터는 CloudWatch Athena 네임스페이스에 노출되지 않으므로 로그 기반 monitor 로 대체)

• 로그 기반 실패 카운트 (Datadog log-to-metric):

service:voxel-service "ThrottlingException" "GetQueryExecution"

service:cupixworks-migration-worker "failed to get captured area"

• Cupix::Cron::Facility.flush_stale_captured_size 성공률 (info Successfully flushed vs warn Failed to flush 비율):

service:cupixworks-migration-worker @function:flush_stale_captured_size

Risk Assessment#

• Risk level: medium — 사용자 노출은 낮지만(면적 표시가 일시적으로 stale) cron 이 4시간마다 반복되며 동일 조건에서 계속 재발한다. 실패한 facility 는 captured_size_state=stale 유지되어 다음 주기에 다시 시도되지만 근본 원인이 그대로면 재발.
• 예상 복잡도: standard — Lambda 파일 1개(captured_area.py) 내부의 폴링 backoff 추가와 boto3 config 조정으로 충분. cron 측 sleep 은 추가 개선 사항.