voxel-service Athena polling infinite loop — API Gateway timeout

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

Overview#

What Happened#

2026-07-13 17:35~17:40 KST 사이 cupixvista 프로덕션(us-west-2) Sidekiq 워커에서 Cupix::VoxelService.captured_area! 가 voxel-service Lambda(PUT /api/v1/voxels/captured_area) 호출 중 HTTP 500 을 받아 2건의 error 가 기록되었다. 대상은 Facility ID 8(facility_key=3ok09a)와 Facility ID 15(facility_key=yf8szb). 두 요청 모두 Athena 쿼리 자체는 발행됐지만 state: 로그가 남지 않아 Lambda 가 API Gateway 통합 타임아웃(30s) 을 넘긴 채 실행되고 있었음이 확인된다.

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`
runtime	ruby/3.3.7 (rest-client/2.1.0)
deploy	`production-us-west-2-20260713T0831Z0-69260da5-cupixvista`
env	`production`, `us-west-2`, tenant `cupix` (cupixvista 배포)

Affected Teams#

Team / Domain	Error Count	Impact
cupixvista-api-worker (VoxelService / Facility)	2	Facility 2개(ID 8, 15)의 `captured_size` / `FootprintHistory` 갱신 실패 — UI 에 표시되는 촬영 면적 수치가 오래된 값으로 남음

Timeline#

2026-07-13 17:33 KST — Facility 8 (3ok09a) 에 대한 첫 PUT /api/v1/voxels/captured_area 요청 발행 (trace 2180691606340267128).
2026-07-13 17:33~17:35 KST — 동일 facility 로 3회 추가 호출 발행. 각 호출에서 ALTER TABLE ADD PARTITION 쿼리는 SUCCEEDED 로 완료됐지만, 본 SELECT 쿼리(67074fbb..., b11aa3d1..., ede2cf07..., 539bf4f0...)는 이후 state: 로그가 남지 않음.
2026-07-13 17:35:34 KST — Cupix::VoxelService.captured_area! 가 500 을 수신 → SYS20000 발생 → Facility#calculate_captured_size rescue 에서 로깅 (Facility ID 8).
2026-07-13 17:39~17:40 KST — Facility 15 (yf8szb) 로 동일 패턴 반복.
2026-07-13 17:40:48 KST — Facility 15 에 대해 동일한 500 에러 발생. 이후 재발 로그 없음.

Error Log#

Datadog Logs

text

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

Impact#

Service: cupixvista-api-worker
발생 횟수: 2
최초 발생: 2026-07-13 17:35 KST
최근 발생: 2026-07-13 17:40 KST
영향 범위: Facility 2건(ID 8 / 3ok09a, ID 15 / yf8szb)의 captured_size, captured_size_state=:fresh 갱신 및 FootprintHistory 기록이 이번 사이클에서 실패. 사용자 노출: 촬영 면적/히스토리 카드가 stale 상태로 표시. 재실행되지 않는 한 자동 복구되지 않음(Sidekiq retry: 1 이 이미 소진됨).

Root Cause Summary#

voxel-service Lambda(captured_area.py)는 Athena 쿼리 완료를 busy-loop(라인 49–52)으로 대기하는데, time.sleep 없이 get_query_execution 을 반복 호출한다. PUT /api/v1/voxels/captured_area 라우트의 API Gateway 통합 타임아웃은 30초(data-pipeline/cupix-data/services/voxel/main.tf:336)로 설정돼 있어, Athena 쿼리가 30초 안에 SUCCEEDED/FAILED/CANCELLED 로 전이하지 못하면 API Gateway 가 502/504 대신 500 을 클라이언트로 반환하고, Lambda 자체는 최대 300초까지 계속 실행된다. Datadog 로그에서 문제 시점의 SELECT 쿼리들은 Athena query id: ... state: 라인이 전혀 남지 않은 반면 짝을 이룬 ALTER TABLE 쿼리는 모두 state: SUCCEEDED 로그를 남긴 것이 이 시나리오와 일치한다. Ruby 측 Cupix::HttpClient.put 은 500 을 재시도 대상(RETRIABLE_STATUS_CODES = [429, 502, 503, 504]) 에 포함시키지 않으므로 즉시 RestClient::Exception 을 raise → SYS20000 으로 상위에 전달된다.

Technical Analysis#

Code Path#

Entry point (Rails / Sidekiq):

app/workers/refresh_captured_size_worker.rb:5-15ruby

def perform(model_name, id, session_token = nil)
  return if model_name.nil?
  return if id.nil?

  model = model_name.constantize.find_by_id(id)
  session = ::SessionRepository.find_by_token(session_token)

  Cupix::Logger.error("#{model_name} not found: #{id}", class: self.class.name, function: __method__) and return if model.nil?

  model.calculate_captured_size!(session: session)
end

Facility 경로:

app/models/concerns/voxel_module.rb:46-56ruby

def calculate_captured_size!(session: nil)
  if respond_to?(:captured_size)
    if self.instance_of?(::Facility)
      Cupix::VoxelService.calculate_captured_size!(facility: self, session: session)
    elsif self.instance_of?(::Team) || self.instance_of?(::Workspace)
      facilities.find_each do |facility|
        facility.calculate_captured_size!(session: session)
      end
    end
  end
end

Failure point — HTTP 500 을 그대로 SYS20000 으로 승격:

app/services/cupix/voxel_service.rb:77-105ruby

def captured_area!(params = {})
  Cupix::Logger.info('Requested', class: self.name, function: __method__, facility: { key: params[:facility_key] }, group_by_record: params[:group_by_record])
  headers = {
    'Content-Type': :json,
    'x-cupix-auth': params[:'x-cupix-auth']
  }
  body = {
    facility_key: params[:facility_key],
    group_by_record: params[:group_by_record]
  }

  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')}, details: #{body.dig('results', 'details')}", class: self.name, function: __method__, facility: { key: params[:facility_key] }, group_by_record: params[:group_by_record])
    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}")
  rescue JSON::ParserError => e
    ...
  end
end

HTTP 재시도 정책 — 500 은 재시도 대상 아님:

lib/cupix/http_client.rb:8-9ruby

RETRIABLE_STATUS_CODES = [429, 502, 503, 504].freeze
MAX_RETRIES = 3

Downstream Lambda — busy-loop 로 Athena polling:

services/voxel/lambda/captured_area.py:28-63python

def run_athena_query(query, output_location):
  database_name = f'db_{TENANT}_{SERVICE_ENV}'
  response = athena.start_query_execution(
    QueryString=query,
    QueryExecutionContext={ 'Database': database_name },
    ResultConfiguration={ 'OutputLocation': output_location },
    ResultReuseConfiguration={
      'ResultReuseByAgeConfiguration': { 'Enabled': True, 'MaxAgeInMinutes': 720 }
    }
  )
  query_execution_id = response['QueryExecutionId']
  print("Voxel::CapturedArea | Athena DB: " + database_name + ", query id: " + query_execution_id + ", query: " + query.replace('\n', ' '))

  # 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
  print("Voxel::CapturedArea | Athena query id: " + query_execution_id + ", state: " + response['QueryExecution']['Status']['State'])

API Gateway 통합 타임아웃(요청 라우트별):

data-pipeline/cupix-data/services/voxel/main.tf:331-336terraform

"PUT /api/v1/voxels/captured_area" = {
  ...
  lambda_arn             = module.captured_area.lambda_function_arn
  timeout_milliseconds   = 30000 # ms
}

기대 동작: 30초 안에 Athena 쿼리가 완료돼 200 응답. 실제 동작: SELECT ... COUNT(DISTINCT CONCAT(...)) 쿼리가 30초 안에 완료되지 못하는 케이스에서 API Gateway 가 500 을 반환. Lambda 는 계속 polling 을 이어가지만 응답 채널이 이미 닫혔기 때문에 결과 로그는 남더라도 Ruby 측은 이미 실패한 상태.

Log Evidence#

Query used (cluster URL 그대로):

text

service:cupixvista-api-worker status:error @environment:production "failed to get captured area - error: 500 Internal Server Error"
from_ts=1783928100000 to_ts=1783935660000

Rails 워커 로그 (원문):

json

{
  "timestamp": "2026-07-13T08:40:48.158Z",
  "status": "error",
  "message": "failed to get captured area - error: 500 Internal Server Error",
  "class": "Cupix::VoxelService",
  "function": "captured_area!",
  "facility_key": "yf8szb",
  "group_by_record": true,
  "service": "cupixvista-api-worker",
  "dd.version": "production-us-west-2-20260713T0831Z0-69260da5-cupixvista"
}

json

{
  "timestamp": "2026-07-13T08:40:48.158Z",
  "status": "error",
  "message": "failed to calculate captured size for Facility ID: 15, error: failed to get captured area - error: 500 Internal Server Error",
  "class": "Facility",
  "function": "calculate_captured_size",
  "model": { "id": 15, "type": "Facility" }
}

Voxel Lambda 로그 — API Gateway event 수신 후 Athena SELECT 쿼리 발행 (2건 발췌):

text

2026-07-13T08:40:15Z  Voxel::CapturedArea | event: {..., "body":"{\"facility_key\":\"yf8szb\",\"group_by_record\":true}", "timeEpoch": 1783932014932}
2026-07-13T08:40:15Z  Voxel::CapturedArea | facility_key: yf8szb , group_by_record: True
2026-07-13T08:40:15Z  Voxel::CapturedArea | Athena DB: db_cupix_production, query id: cfa067ab-..., query: ALTER TABLE tb_tesla_reality_captures ADD IF NOT EXISTS PARTITION (facility_key = 'yf8szb');
2026-07-13T08:40:15Z  Voxel::CapturedArea | Athena query id: cfa067ab-..., state: SUCCEEDED
2026-07-13T08:40:16Z  Voxel::CapturedArea | Athena query id: cfa067ab-..., result: {"ResultSet": {"Rows": [], ...}}
2026-07-13T08:40:16Z  Voxel::CapturedArea | Athena DB: db_cupix_production, query id: 07533db6-..., query: WITH rc (...) SELECT rc.level_id, rc.record_id, COUNT(DISTINCT CONCAT(...)) AS "captured_area" FROM tb_raw_voxel AS v, rc WHERE v.model_id = rc.model_id ...
2026-07-13T08:40:48Z  (Rails side) failed to get captured area - error: 500 Internal Server Error

결정적 근거: 07533db6-... (본 SELECT 쿼리) 에 대한 state: 및 result: 로그가 로그 인덱스에 존재하지 않는다 (Datadog 검색으로 확인, "Found 0 logs" 유형 응답에는 해당 ID 로 어떤 후속 로그도 나오지 않음). 그러나 짝을 이룬 ALTER TABLE 쿼리(cfa067ab-...) 의 state: SUCCEEDED 로그는 존재. 즉 Lambda 는 SELECT 쿼리를 던지고 그 상태 전이 이전에 API Gateway 30s 타임아웃에 걸린 것.

타임 gap: event: 수신 시각(08:40:15) → Ruby 측 에러 로그(08:40:48) = 약 33초 — API Gateway 30s 통합 타임아웃과 일치.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	voxel-service Lambda 의 Athena 쿼리 지연 → API Gateway 30s 통합 타임아웃 → 500	(a) `event:` 시각과 Rails 에러 시각 간 gap ≈ 33s (b) API Gateway 라우트 timeout=30000ms 설정 확인 (`data-pipeline/cupix-data/services/voxel/main.tf:336`) (c) 문제 SELECT 쿼리(`07533db6-...`, `0161aea6-...`, `539bf4f0-...`, `ede2cf07-...`, `b11aa3d1-...`, `67074fbb-...`) 는 어떤 `state:` 후속 로그도 남기지 않음 (d) 짝인 ALTER TABLE 쿼리는 모두 `SUCCEEDED` 로그 정상	—	Confirmed
H2	Lambda 코드 예외(`parse_captured_area_result` KeyError 등) 로 인한 500	만약 `except Exception` 분기(captured_area.py:138) 로 갔다면 `handler_response` 가 실행되어 `handler_response - status_code: 500` 로그가 남았을 것	로그 검색에서 `handler_response` 문자열이 존재하지 않음 (해당 시간대)	Rejected
H3	Athena 쿼리 실패로 Lambda 가 명시적 500 반환 (line 108 / 132)	Line 62 의 `reason:` 로그와 line 108/132 의 `handler_response` 로그 조합이 남아야 함	해당 로그 없음. `state:` 조차 없음.	Rejected
H4	재발 중인 S3 PutObject IAM 권한 오류(`tesla-api-production-86ob` → `cupix-cupixworks-prod-data-stage-uswe2`) 가 이번 500 의 원인	동일 facility_key(`yf8szb`) 로 다른 시간대(01:31, 05:31, 09:31, 13:31)에 IAM Access Denied 발생	(a) 해당 오류는 `cupixworks-*` 서비스에서 발생, 이번 cluster 의 service (`cupixvista-api-worker`) 와 다름 (b) 오류 메시지 자체가 다름 (`... is not authorized to perform: s3:PutObject ...`) (c) 이번 500 은 voxel-service HTTP 응답이지 S3 예외가 아님	Rejected (별개 이슈)
H5	`Cupix::HttpClient.put` 재시도 부족 (500 미포함)	재시도 로직이 500 을 처리하지 않으므로 즉시 raise 됨	재시도 여부와 무관하게 upstream 500 자체는 해소되지 않음 — 재시도해도 같은 타임아웃 재현 가능	Inconclusive (완화책이지 근본 원인 아님)

Fix Recommendation#

즉시 조치 (Critical)#

voxel-service Lambda 의 Athena polling 을 backoff 로 완화: services/voxel/lambda/captured_area.py:49-52 의 busy-loop 에 time.sleep(0.5~1s) 을 넣어 athena.get_query_execution 호출 부하를 줄이고, Athena API rate limit 회피. 이 자체가 지연을 줄이지는 않지만 Athena API 리소스 확보 측면에서 필수. (동일 파일의 add_partition.py, merge.py 등 sibling 도 확인 필요)
API Gateway 통합 타임아웃과 클라이언트 정책 재설계: 근본 대응은 아래 두 축 중 하나로 진행 — (필요시 인프라 담당자와 조율)
1. PUT /api/v1/voxels/captured_area 를 비동기(202 Accepted → 폴링) 로 변경. Lambda 는 Athena start_query_execution 만 수행 후 query_execution_id 반환, Rails 측은 별도 GET /api/v1/voxels/captured_area/:qid 로 polling. 30s 타임아웃 자체를 회피.
2. API Gateway 타임아웃 자체를 상향(계정 quota 상 최대 29s HTTP API, REST 라면 quota increase 필요) 하는 대신, Athena 쿼리 리팩터링(파티션 pruning, tb_raw_voxel full-scan 최소화) 로 p99 응답을 25초 이내로 낮춘다.
Ruby 측 502/504 처럼 500 은 재시도 대상에 포함하지 않는 정책 유지: 근본 문제(30s 이내 완료 불가) 가 해결되기 전까지는 재시도해도 동일 결과. 재시도 추가는 지양.

단기 개선 (1주 이내)#

captured_area! 실패 후 captured_size_state 를 stale 로 명시적 표기: 현재 실패 시 Facility#captured_size 는 이전 값으로 남고 상태는 갱신 안 됨. UI 에서 stale 여부를 사용자에게 노출할 수 있도록 상태 컬럼 관리 필요.
RefreshCapturedSizeWorker 의 retry: 1 은 유지하되 재시도 간격을 exponential backoff 로 조정, 다음 실행에서라도 회복 가능하도록. 무한 재시도는 하지 않음(voxel-service 근본 원인이 해결돼야 성공).
Athena 쿼리 최적화: WITH rc AS (SELECT * FROM tb_tesla_reality_captures WHERE facility_key = '...') 절이 partition pruning 을 확실히 이용하도록 확인. 두 번째 JOIN 대상인 tb_raw_voxel 이 파티션 없이 스캔되는지 확인 필요.

장기 개선 (재발 방지)#

voxel-service 를 completely async 로 전환 (Step Functions / SQS + polling API). Athena 쿼리 시간이 예측 불가능한 워크로드는 동기 HTTP 응답에 부적합.
다중 tenant 배포에서 하나의 데이터베이스(db_cupix_production) 만 조회하는 부분(라인 29 f'db_{TENANT}_{SERVICE_ENV}') 이 cupixvista/cupix 간 데이터 분리 정책과 일치하는지 인프라 담당과 확인 (uncertain — needs verification, 이번 사고와 직접 인과는 없음).

Monitoring#

voxel-service captured_area 지연 히스토그램: Rails 요청 시작 로그(Requested) 와 완료 로그(Completed) 사이 시간 차이를 트래킹.

text

service:cupixvista-api-worker @class:"Cupix::VoxelService" @function:captured_area! status:error

voxel Lambda 로 들어간 요청 대비 성공적으로 state: 로그가 남지 않은 SELECT 쿼리 비율:

text

"Voxel::CapturedArea | Athena DB" -"ALTER TABLE"

(위 쿼리로 SELECT 발행 건수 파악 → 별도 state: SUCCEEDED 카운트와 비교)

API Gateway 5XX 알람 — 이 라우트 한정:

text

service:voxel-service @http.status_code:>=500 @http.route:"PUT /api/v1/voxels/captured_area"

Facility captured_size 갱신 실패율:

text

service:cupixvista-api-worker @class:Facility @function:calculate_captured_size status:error

Risk Assessment#

Risk level: medium — 사용자 데이터 유실은 없으며 재실행 시 복구 가능하지만, captured_size 는 청구/리포팅에 사용되는 지표이므로 stale 상태가 장시간 지속되면 신뢰도 저하.
예상 복잡도: standard — Lambda polling backoff 추가는 trivial. 근본 대응(async API 전환)은 critical 수준이며 인프라/프런트엔드 조율이 필요하므로 code-fix 자동화 범위에서 제외 권장.