ES /docs

BaseService::handlingMessageErrors | Error and message object - {"error":{"response":{"statusCode":5

RCA: BaseService::handlingMessageErrors | 504 Gateway Timeout on PUT /api/v1/captures/685890

Overview#

What Happened#

2026-04-23 08:17:30 UTC에 cupixworks-capture-postprocessor-agent가 api-tesla.cupix.internal로 capture 685890의 상태를 업데이트하는 PUT 요청 중 504 Gateway Timeout이 발생했다. AWS ALB/nginx가 upstream API 서버의 응답을 기다리다 타임아웃된 것으로, 같은 시간대 API 서버의 PUT 요청 처리 시간이 64~117초까지 증가한 것이 원인이다. 단발성 이벤트이며, 후속 요청(08:17:56Z)은 정상 처리되었다.

Quick Facts#

Field Value
exception.class HttpError
exception.message 504 Gateway Time-out
top_frame BaseService::handlingMessageErrors (base-service.ts:311)
env production, us-west-2

Affected Teams#

Team / Domain Error Count Impact
thehyundai 1 capture 685890 postprocessing 중 일시적 지연. 후속 retry로 자동 복구됨

Timeline#

  1. 07:22:18Z — capture 685890 첫 번째 postprocessor 실행 (job 1031039), 정상 완료
  2. 08:03:57Z — refinement 재큐잉 (job 1031167 생성)
  3. 08:06:15Z — refinement_state → error 전환
  4. 08:06:19Z — 두 번째 postprocessor 실행 시작 (job 1031039)
  5. 08:15:10Z — API PUT 응답 시간 63,753ms 관측
  6. 08:17:12Z — API PUT 응답 시간 117,295ms (DB 시간 117,164ms) 관측
  7. 08:17:30Z — PUT /api/v1/captures/685890 요청에 504 Gateway Timeout 발생
  8. 08:17:56Z — 동일 엔드포인트 PUT 요청 정상 처리 (200, 85,326ms)

Error Log#

Datadog Logs

text
BaseService::handlingMessageErrors | Error and message object - {"error":{"response":{"statusCode":504,"body":"<html>\r\n<head><title>504 Gateway Time-out</title></head>\r\n<body>\r\n<center><h1>504 Gateway Time-out</h1></center>\r\n<hr><center>nginx</center>\r\n</body>\r\n</html>\r\n"...},"sqsMessage":{"MessageId":"8cfb04e8-866f-43ca-9ec4-23fbbf55b28c","Attributes":{"ApproximateReceiveCount":"1"}}}

Impact#

  • Service: cupixworks-capture-postprocessor-agent
  • Team: thehyundai
  • 발생 횟수: 1
  • 최초 발생: 2026-04-23T08:17:30.825Z
  • 최근 발생: 2026-04-23T08:17:30.825Z

Root Cause Summary#

AWS ALB/nginx 레이어에서 upstream API 서버(cupixworks-api)의 응답 지연으로 인해 504 Gateway Timeout이 발생했다. API 서버는 capture 685890에 대한 PUT 요청을 처리하면서 DB 시간이 117초까지 치솟았는데, 이는 Capture 모델의 save! 호출 시 트리거되는 다수의 after_save/after_commit 콜백(Elasticsearch 인덱싱, review state 무효화, state machine 전환 등)과 43개 이상의 필드를 직렬화하는 응답 생성이 복합적으로 작용한 결과다. ALB의 idle timeout(기본 60초)을 초과하여 nginx가 504를 반환했고, postprocessor agent의 retryable 래퍼가 capture update 호출에 적용되지 않아 에러가 바로 상위 핸들러로 전파되었다. 다만, getApiErrorToDeleteMessage의 조건(statusCode >= 400 && statusCode <= 500)에 504가 해당하지 않아 SQS 메시지가 삭제되지 않았고, SQS visibility timeout 후 자동 재처리되어 복구되었다.

Technical Analysis#

Code Path#

1. SQS 메시지 수신 및 처리 시작

Agent가 SQS 큐에서 메시지를 수신하여 runByMessage()를 실행한다.

applications/agents/packages/base/src/base-service.ts:105-114typescript
} else {
    this._countWaitedToStopTask = 0;
    try {
        await this.runByMessages();
    } catch (error) {
        await this.handlingMessageErrors(error);
    }
    this.resetMessages();
    await CPUtils.sleep(500);
    await this.checkingQueue();
}

2. Capture Update API 호출 (retry 미적용)

Postprocessor가 capture 상태 업데이트를 위해 capture.api.update()를 호출한다. 이 메서드는 retryable 래퍼 없이 Tesla SDK를 직접 호출한다.

applications/agents/packages/api/src/api/capture.api.ts:56-60typescript
@SkipInDebug()
async update(captureId: number, updateCaptureRequest: TESLA.UpdateCaptureRequest): Promise<TESLA.Capture> {
    const api = await this.api();
    const res = await api.updateCapture(captureId, Fields.CaptureFields, updateCaptureRequest);
    return unwrapAttributes(res);
}

retryable 래퍼는 cupix-auth.ts:59-77에 정의되어 있지만, capture update 호출 경로에서는 사용되지 않는다. 따라서 504 에러 발생 시 즉시 예외가 throw된다.

applications/agents/packages/api/src/authentication/cupix-auth.ts:59-77typescript
retryable = <T>(f: () => Promise<T>, retries?: number): Promise<T> => new Promise((resolve, reject) => {
    const _retries = retries != undefined ? retries : 0;
    f()
        .then(response => resolve(response))
        .catch(e => {
            if (e && e.statusCode > 500 && _retries < Constants.MaxRetries) {
                const pathName = e.response && e.response.request && e.response.request.url && e.response.request.url.pathname
                    ? e.response.request.url.pathname : 'Unknown';
                const delay = Math.pow(2, _retries) * 1000;
                logger.warn(`CupixAuth::retryable | pathname: ${pathName}, code: ${e.statusCode}, try: ${_retries + 1} - run after ${delay / 1000} seconds`);
                setTimeout(() => {
                    this.retryable(f, _retries + 1).then(resolve).catch(reject);
                }, delay);
            } else {
                reject(e);
            }
        });
});

3. 에러 핸들링 - 504는 SQS 메시지를 삭제하지 않음

getApiErrorToDeleteMessage는 statusCode 범위 400~500만 API 에러로 인식한다. 504는 이 범위 밖이므로 undefined를 반환하고, SQS 메시지 삭제가 스킵된다.

applications/agents/packages/base/src/base-service.ts:270-275typescript
if (statusCode != undefined && statusCode >= 400 && statusCode <= 500) {
    if (statusCode === 401) return;
    return errorMsg;
}
return;

handlingMessageErrors에서 getApiErrorToDeleteMessage가 undefined를 반환하고, ApproximateReceiveCount가 1이므로 checkReceiveCountToDeleteMessage도 false를 반환한다(MaxReceiveCount=10 미만). 따라서 메시지는 삭제되지 않고 SQS로 반환되어 재처리 가능하다.

applications/agents/packages/base/src/base-service.ts:290-313typescript
private handlingMessageErrors = async (error: any): Promise<void> => {
    const errorAndMessage = {
        error: error,
        sqsMessage: {}
    };
    if (this.messageInProcess) {
        errorAndMessage.sqsMessage = {
            MessageId: this.messageInProcess.MessageId,
            Attributes: this.messageInProcess.Attributes
        };
        const apiErrorObject = this.getApiErrorToDeleteMessage(error);
        if (apiErrorObject != undefined || this.checkReceiveCountToDeleteMessage()) {
            try {
                errorAndMessage.error = apiErrorObject;
                await this.deleteByMessage(this.messageInProcess);
                if (this._modelInProcess != undefined && this._modelInProcess.id > 0) await this.updateErrorState(this._modelInProcess);
            } catch (error) {
                logger.error('BaseService::handlingMessageErrors | Errors in error handling', error);
            }
        }
    }
    logger.error('BaseService::handlingMessageErrors | Error and message object - %s', JSON.stringify(errorAndMessage));
    resetLogMeta();
};

4. 다운스트림 API 서버 — capture update의 느린 처리

Tesla API의 capture update 엔드포인트는 save! 호출 시 다수의 콜백을 트리거한다:

app/repositories/capture_repository.rb:182-194ruby
def update(params = {})
  super
  set_parameters(params)
  begin
    @model.save!
  rescue StandardError => e
    raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'Invalid argument', message: e.message)
  end
  @model
end

save! 호출 시 트리거되는 주요 콜백:

app/models/concerns/searchable.rb:16-18ruby
after_commit on: [:update] do
  _update_document
end
app/models/concerns/stale_review/capture.rb:10-11ruby
around_save :touch_reviews_after_save, unless: :skip_touch_reviews?
after_save :touch_record_after_save, unless: :skip_touch_reviews?

Datadog 로그에서 확인된 바, 이 시간대에 PUT 응답 시간이 63~117초에 달했으며, DB 시간이 대부분을 차지했다(117,295ms 중 117,164ms가 DB).

Log Evidence#

Datadog에서 capture 685890 관련 로그를 검색했다.

검색 쿼리:

text
service:cupixworks-capture-postprocessor-agent 685890
text
service:cupixworks-api 685890

Agent 측 로그 (3건):

json
{
  "timestamp": "2026-04-23T08:17:30.825Z",
  "level": "error",
  "message": "BaseService::handlingMessageErrors | Error and message object",
  "statusCode": 504,
  "request": "PUT http://api-tesla.cupix.internal/api/v1/captures/685890"
}
json
{
  "timestamp": "2026-04-23T08:17:30.824Z",
  "level": "warn",
  "message": "BaseService::getApiErrorToDeleteMessage | error msg",
  "statusCode": 504,
  "requestUriHref": "http://api-tesla.cupix.internal/api/v1/captures/685890?fields[0]=id&...",
  "modelId": 1031039
}
json
{
  "timestamp": "2026-04-23T07:22:47.394Z",
  "level": "info",
  "message": "BaseService::cleanUpAnythingRelatedModel | path: /tmp/workspace/685890"
}

API 측 로그 — 504 직전/직후 PUT 요청 처리 시간:

text
08:15:10.918Z | [200] PUT /api/v1/captures/685890 | duration: 63,753ms
08:17:12.972Z | [200] PUT /api/v1/captures/685890 | duration: 117,295ms (db_time: 117,164ms)
08:17:30.825Z | [504 on agent side — no API-side log recorded]
08:17:56.578Z | [200] PUT /api/v1/captures/685890 | duration: 85,326ms (db_time: 83,846ms)

504 시점의 요청은 API 서버에서 완료 로그가 없다 — ALB가 upstream 응답 전에 연결을 종료한 것이다.

동일 시간대 다른 서비스 504 검색:

text
service:cupixworks-api status:error @timestamp:[2026-04-23T08:16:00Z TO 2026-04-23T08:19:00Z]

결과: 0건. API 서버 측에서는 504를 기록하지 않았다 (ALB 레이어에서 발생했으므로).

동일 시간대 postprocessor agent 전체 에러 검색: 504는 이 시간대에 1건만 발생했다. 같은 시간대 S3 업로드 실패(TransferManager::failTask), HTTP 400(Resource not uploaded) 등 다른 유형의 에러가 다수 발생하고 있어 시스템 전반적으로 높은 부하 상태였다.

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 API 서버의 capture update 처리가 ALB timeout을 초과하여 504 발생 API 로그에서 동일 엔드포인트 PUT 응답이 63~117초 (DB 시간 117,164ms). 504 시점에는 API 완료 로그 없음. AWSALB 쿠키가 504 응답에 포함됨 — Confirmed
H2 Agent-side HTTP client의 자체 timeout으로 인한 504 504 응답 body에 nginx HTML이 포함되어 서버 측 timeout 확인 Agent SDK에 명시적 timeout 설정이 없어 client-side timeout이 아님 Rejected
H3 네트워크 일시 장애로 인한 504 단발성 발생(1건) 동일 시간대 전후 PUT 요청은 정상(200) 처리. 504 직후 26초 후 동일 요청 성공. 다른 서비스에서 504 미발생 Rejected
H4 DB 레벨의 lock contention으로 인한 쿼리 지연 API 로그에서 DB 시간이 전체 응답 시간의 99%+ 차지 (117,164ms / 117,295ms). Capture save! 시 다수의 after_save 콜백이 DB 작업 발생 구체적인 lock 대기 로그는 확인 불가 Inconclusive

Fix Recommendation#

즉시 조치 (Critical)#

  • 필요 없음. 단발성 이벤트이며 SQS 재처리로 자동 복구되었다. capture 685890은 08:17:56Z에 정상 처리 완료.

단기 개선 (1주 이내)#

  • capture.api.update()에 retryable 래퍼 적용: applications/agents/packages/api/src/api/capture.api.ts:56-60에서 api.updateCapture() 호출을 this.auth.retryable()로 감싸서 5xx 에러 시 자동 retry (exponential backoff)가 동작하도록 한다. 이미 retryable 메커니즘이 cupix-auth.ts:59-77에 구현되어 있으므로 적용만 하면 된다.
  • getApiErrorToDeleteMessage의 statusCode 범위 검토: base-service.ts:270의 조건 statusCode >= 400 && statusCode <= 500은 501~599 에러를 API 에러로 인식하지 못한다. 504 같은 서버 에러에서 SQS 메시지를 즉시 삭제하지 않는 것은 현재 올바른 동작(재처리 가능)이지만, 의도적 설계인지 검토가 필요하다.

장기 개선 (재발 방지)#

  • Tesla API capture update 성능 최적화: capture_repository.rb:188의 save! 호출이 트리거하는 콜백(Elasticsearch 인덱싱, review state 무효화, state machine 전환)을 비동기화하거나, agent 전용 lightweight update 엔드포인트를 제공하여 응답 시간을 단축한다.
  • ALB idle timeout 조정: 현재 기본값(60초)이 capture update의 실제 처리 시간(60120초)보다 짧다. ALB timeout을 120180초로 상향하거나, API 측 처리 시간을 60초 이내로 최적화한다.

Monitoring#

  • Capture update API 응답 시간 모니터링:
text
service:cupixworks-api @http.url:"/api/v1/captures/*" @http.method:PUT @duration:>60000
  • Postprocessor agent 504 에러 추적:
text
service:cupixworks-capture-postprocessor-agent status:error "504"
  • ALB 504 비율 메트릭:
text
aws.applicationelb.httpcode_elb_5xx{load_balancer:*tesla*}

Risk Assessment#

  • Risk level: low
  • 예상 복잡도: trivial — 단발성 이벤트이며 SQS 재처리로 자동 복구됨. retryable 래퍼 적용은 기존 인프라 활용으로 간단한 변경.