CompleteService::handlingMessageErrors | Error and message object - {"error":{"response":{"statusCod

RCA: CompleteService::handlingMessageErrors | 504 Gateway Time-out

Overview#

What Happened#

2026-04-23 08:13:35 UTC에 cupixworks-any-complete-agent 서비스에서 job 1031025에 대한 PUT /api/v1/jobs/1031025 요청이 nginx로부터 504 Gateway Time-out 응답을 받았다. 이는 downstream API(cupixworks-api)에서 ActiveRecord::LockWaitTimeout이 발생하여 요청 처리가 지연되었고, nginx의 gateway timeout 임계값을 초과했기 때문이다. 동일 job에 대해 다수의 동시 PUT 요청이 발생하면서 MySQL row lock 경합이 원인이었다.

Quick Facts#

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

Timeline#

07:16:55 UTC — Job 1031025 최초 처리 시작 (ECS task stopped → postprocessor 호출), 07:18에 정상 완료 (stopped)
07:56:53 UTC — Job 1031025이 stopped → running으로 재트리거됨 (두 번째 처리 사이클 시작)
08:11:27 UTC — API 측에서 PUT /api/v1/jobs/1031025에 대해 ActiveRecord::LockWaitTimeout 502 에러 최초 발생
08:13:35 UTC — Complete-agent가 504 Gateway Time-out 수신 (본 인시던트)
08:13:36 UTC — API 측에서 동일 시각 LockWaitTimeout 502 추가 발생
08:13:40 UTC — 경합 해소 후 PUT 요청 성공 (200)
08:14:54 ~ 08:15:08 UTC — 후속 SQS 재시도에서 InvalidState: State not changed 400 에러 발생 (이미 상태 변경 완료)
08:18:09 UTC — 최종 PUT 성공, 처리 완료

Error Log#

Datadog Logs

text

CompleteService::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",...},"name":"HttpError"},"sqsMessage":{"MessageId":"2438e2e9-577f-44aa-9233-4ecb143e4dd3","Attributes":{"ApproximateReceiveCount":"8"}}}

Impact#

Service: cupixworks-any-complete-agent
발생 횟수: 1
최초 발생: 2026-04-23T08:13:35.439Z
최근 발생: 2026-04-23T08:13:35.439Z

동일 시간대에 job 1031025 외에도 capture 685931에 대한 504 timeout이 별도 발생하여 (08:28:33), API 측 성능 저하가 단일 job에 국한되지 않았음을 시사한다. SQS 메시지가 10회 이상 재전달되면서 불필요한 API 호출이 반복되었다.

Root Cause Summary#

Job 1031025가 정상 완료(stopped) 후 stopped → running으로 재트리거되면서 두 번째 처리 사이클이 시작되었다. 이 과정에서 complete-agent의 SQS 메시지가 여러 차례 재전달되어 동일 job에 대한 다수의 동시 PUT /api/v1/jobs/1031025 요청이 발생했다. API 측에서는 JobRepository#update가 @model.save!를 호출할 때 MySQL row lock을 획득하는데, 동시 요청들이 동일 row에 대해 lock을 경합하면서 ActiveRecord::LockWaitTimeout이 발생했다. 이로 인해 API 응답이 지연되어 nginx의 gateway timeout을 초과하였고, complete-agent에 504가 반환되었다. 504는 getApiErrorToDeleteMessage의 삭제 조건(400-500 범위)에 해당하지 않아 SQS 메시지가 삭제되지 않았고, 재전달 → lock 경합 → timeout의 악순환이 MaxReceiveCount(10)에 도달할 때까지 반복되었다.

Technical Analysis#

Code Path#

1. SQS 메시지 수신 및 처리 — Entry Point

BaseService가 SQS 큐에서 메시지를 수신하고 runByMessage에서 처리한다:

packages/base/src/base-service.ts:153-184typescript

protected runByMessage = async (message: AWS.SQS.Message) => {
    this._messageInProcess = message;
    const messageBody = message.Body;
    if (messageBody && CPUtils.isJsonString(messageBody)) {
        const msgObject = JSON.parse(messageBody);
        const targetId = Environment.DEBUG_MODE && Environment.CPX_MODEL_ID ? Environment.CPX_MODEL_ID : (msgObject.id ?? msgObject.model?.id);
        try {
            await TraceUtils.activateSpan(span, async () => {
                this.setLogMeta(msgObject);
                logger.info('BaseService::runByMessage | id: %d', targetId);
                await this.authenticateByMessage(msgObject);
                await this.run(targetId, msgObject);           // 서비스 로직 실행
                await this.cleanUpAnythingRelatedModel();
                await this.deleteByMessage(message);           // 성공 시 SQS 메시지 삭제
            });
        } catch (error) {
            TraceUtils.finishSpan(span, false, error);
            throw error;                                        // handlingMessageErrors로 전파
        }
    }
};

2. Job Update API 호출 — Failure Point

JobManager.updateCompleteActionJob에서 Tesla API로 PUT 요청을 보낸다:

packages/base/src/manager/job.manager.ts:79-102typescript

updateCompleteActionJob = async (actionName: string, state?: TESLA.UpdateJobRequest.StateEnum): Promise<void> => {
    const jobId = this.serverJob && this.serverJob.id;
    try {
        this.reset();
        const res = await this.cupixApi.job.update(jobId, {
            progress: 100,
            state: state,
            processing_status: actionName,
        });
        if (this.updateActionJob) {
            await this.cupixApi.job.completeAction(jobId, actionName);
        }
    } catch (error) {
        logger.warn('JobManager::updateCompleteActionJob | end - %s', error);
    }
};

3. Tesla SDK의 retry 로직

SDK는 504를 retriable status code로 분류하여 exponential backoff으로 최대 5회 재시도한다:

node_modules/@tesla/typescript-node-sdk/api/jobApi.js:47-105javascript

this.retriableStatusCodes = new Set([
    408, 429, 500, 502, 503,
    504 // Gateway Timeout
]);

this.cupixRetriableRequest = (func, retries) => new Promise((resolve, reject) => {
    const MaxRetries = 5;
    const _retries = retries != undefined ? retries : 0;
    const _retryInterval = Math.pow(2, _retries) * 1000;  // 1s, 2s, 4s, 8s, 16s
    func()
        .then(response => resolve(response))
        .catch(e => {
        if (_retries < MaxRetries && e && this.isCupixRetriableRequest(e)) {
            setTimeout(() => {
                this.cupixRetriableRequest(func, _retries + 1).then(resolve).catch(reject);
            }, _retryInterval);
        } else {
            reject(e);
        }
    });
});

SDK 재시도가 모두 실패하면 에러가 runByMessage의 catch로 전파되고, handlingMessageErrors가 호출된다.

4. Error 처리 — SQS 메시지 삭제 판단

getApiErrorToDeleteMessage가 상태 코드를 검사하여 SQS 메시지 삭제 여부를 결정한다:

packages/base/src/base-service.ts:240-276typescript

private getApiErrorToDeleteMessage = (error: any): any => {
    // ...
    const statusCode = response.statusCode ? Number(response.statusCode) : undefined;
    // ...
    if (statusCode != undefined && statusCode >= 400 && statusCode <= 500) {
        if (statusCode === 401) return;    // 401은 삭제 안 함
        return errorMsg;                    // 400-500 범위: 메시지 삭제
    }
    return;                                 // 504 > 500 → undefined 반환 → 메시지 삭제 안 함
};

504는 500 초과이므로 undefined를 반환한다. 이후 checkReceiveCountToDeleteMessage에서 ApproximateReceiveCount >= MaxReceiveCount(10)인지 확인하고, 미달 시 메시지가 SQS에 남아 재전달된다.

packages/base/src/base-service.ts:290-313typescript

private handlingMessageErrors = async (error: any): Promise<void> => {
    // ...
    const apiErrorObject = this.getApiErrorToDeleteMessage(error);
    if (apiErrorObject != undefined || this.checkReceiveCountToDeleteMessage()) {
        // 조건 충족 시에만 메시지 삭제 + 에러 상태 업데이트
        await this.deleteByMessage(this.messageInProcess);
        if (this._modelInProcess != undefined && this._modelInProcess.id > 0)
            await this.updateErrorState(this._modelInProcess);
    }
    // 조건 미충족: 메시지가 SQS에 남아 재전달됨
    logger.error('BaseService::handlingMessageErrors | Error and message object - %s', JSON.stringify(errorAndMessage));
};

5. API 측 — Lock 경합 원인

Tesla API에서 ActiveRecord::LockWaitTimeout이 rescue_from으로 502 응답으로 변환된다:

app/controllers/concerns/server_error_controller.rb:18-20ruby

rescue_from ActiveRecord::LockWaitTimeout,
            Errno::ENOMEM,
            RuntimeError, with: :badgateway_on_system_502_error

JobRepository#update에서 @model.save!가 MySQL row lock을 요구하는데, 동시 요청이 동일 job row를 갱신하려 하면서 lock wait가 발생한다:

app/repositories/job_repository.rb:46-50ruby

begin
  @model.save!
rescue StandardError => e
  raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'Invalid argument', message: e.message)
end

Log Evidence#

Datadog 쿼리 1: complete-agent 에러 로그

text

service:cupixworks-any-complete-agent status:error @environment:production

504 에러 발생 시각(08:13:35)의 전후 로그 시퀀스:

text

08:13:35.438 WARN  CupixAuth::handleError | Response statusCode: 504, body.result: undefined
08:13:35.439 WARN  CompleteService::getApiErrorToDeleteMessage | statusCode: 504
08:13:35.439 ERROR CompleteService::handlingMessageErrors | Error and message object - {"error":{"response":{"statusCode":504,...},"name":"HttpError"},"sqsMessage":{"MessageId":"2438e2e9-577f-44aa-9233-4ecb143e4dd3","Attributes":{"ApproximateReceiveCount":"8"}}}

SQS 메시지 재전달 후 상태 이미 변경되어 400 에러 발생:

text

08:14:54.405 WARN  CupixAuth::handleError | Response statusCode: 400, InvalidState
08:14:54.406 WARN  CompleteService::getApiErrorToDeleteMessage | statusCode: 400, "State not changed"
08:14:54.434 ERROR CompleteService::handlingMessageErrors | 400 InvalidState (ApproximateReceiveCount: 10)

Datadog 쿼리 2: API 측 job 1031025 로그

text

service:cupixworks-api 1031025

API 측에서 동일 시간대에 ActiveRecord::LockWaitTimeout 502가 반복 발생:

text

08:11:27.675 [502] PUT /api/v1/jobs/1031025 — ActiveRecord::LockWaitTimeout: Lock wait timeout exceeded
08:11:28.811 [502] PUT /api/v1/jobs/1031025 — ActiveRecord::LockWaitTimeout
08:13:36.444 [502] PUT /api/v1/jobs/1031025 — ActiveRecord::LockWaitTimeout (x2)
08:17:55.840 [502] PUT /api/v1/jobs/1031025 — ActiveRecord::LockWaitTimeout

API 측에서 504 에러 로그가 없는 것은 정상이다 — 504는 nginx가 upstream timeout 시 직접 반환한 것이며, API 프로세스가 응답을 완료하기 전에 nginx가 연결을 끊었다.

Datadog 쿼리 3: 동시간대 다른 504 발생 확인

text

service:cupixworks-any-complete-agent status:warn

text

08:28:33.723 WARN  504 timeout on PUT /api/v1/captures/685931 — 별도 리소스에서도 504 발생

이는 API/DB 성능 저하가 job 1031025에 국한되지 않고 broader한 문제였음을 시사한다.

SQS 메시지 재전달 이력

Job 1031025에 대한 runByMessage info 로그가 11회 관찰됨 (07:18 ~ 08:15). ApproximateReceiveCount가 8에서 10까지 증가하면서 최종적으로 MaxReceiveCount(10) 도달 후 메시지가 삭제되었다.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	API 측 MySQL row lock 경합으로 인한 `ActiveRecord::LockWaitTimeout` → nginx 504	API 로그에서 08:11~08:17 사이 동일 job에 대해 5건의 `LockWaitTimeout` 502 확인. 동시간대 job 상태 전환이 3-4회 중복 발생 (`stopping → stopped`). 504 시점(08:13:35)이 LockWaitTimeout 502 발생 시점(08:13:36)과 1초 이내로 일치.	—	Confirmed
H2	API 서버 자체의 과부하/다운으로 인한 504	08:28:33에 다른 리소스(capture 685931)에서도 504 발생하여 broader performance issue 가능성 있음	API 로그에서 08:13:40에 바로 200 OK 응답이 확인됨. lock 해소 후 즉시 정상 응답. API 서비스 자체의 헬스 이슈 증거 없음. 504는 특정 row lock 경합 시에만 발생.	Rejected
H3	Complete-agent 측 HTTP timeout 설정 미비로 요청이 과도하게 대기	Tesla SDK의 `request` 라이브러리에 명시적 timeout 설정이 없음 (`jobApi.js`의 `localVarRequestOptions`에 timeout 속성 부재)	timeout 미설정이 504의 직접 원인은 아님 — nginx가 먼저 timeout을 반환. 다만 불필요하게 긴 대기를 유발할 수 있는 부차적 이슈.	Inconclusive
H4	SQS 메시지 중복 전달이 동시 요청 → lock 경합의 원인	`ApproximateReceiveCount`가 8~10회까지 증가. `runByMessage` 로그가 11회 관찰됨. 504/502는 `getApiErrorToDeleteMessage`에서 삭제 대상이 아님(>500) → 메시지가 SQS에 남아 재전달 반복.	SQS 재전달 자체는 정상 동작이나, 504/502 에러 시 메시지를 삭제하지 않는 로직이 retry storm을 악화시킴.	Confirmed

Fix Recommendation#

즉시 조치 (Critical)#

없음. 이 에러는 일시적인 DB lock 경합으로 인한 transient 에러이며, SQS 재전달과 SDK retry를 통해 최종적으로 자동 해소되었다. 발생 건수가 1건이며 job 처리가 완료되었다.

단기 개선 (1주 이내)#

getApiErrorToDeleteMessage의 상태 코드 범위 확장 (base-service.ts:270)
- 현재 statusCode >= 400 && statusCode <= 500 조건은 502/503/504를 포함하지 않아, server-side transient error 시에도 SQS 메시지가 삭제되지 않고 재전달된다. 502(LockWaitTimeout으로 인한)는 재시도해도 같은 결과를 낳을 가능성이 높으므로, 특정 server error에 대해서도 메시지 삭제를 고려해야 한다.
- 단, 단순히 범위를 넓히면 실제 재시도가 필요한 transient error까지 삭제될 수 있으므로, 502 중 LockWaitTimeout 등 특정 에러만 삭제하는 방식이 안전하다.
Tesla SDK HTTP client에 timeout 설정 추가 (jobApi.js — SDK 빌드 소스)
- request 라이브러리의 localVarRequestOptions에 timeout 속성(예: 30초)을 설정하여, nginx timeout보다 먼저 client 측에서 timeout하도록 한다. 이렇게 하면 SDK retry 로직이 더 빨리 작동하여 불필요한 대기를 줄일 수 있다.

장기 개선 (재발 방지)#

Job update API에 optimistic locking 또는 advisory lock 도입 (Tesla 측)
- JobRepository#update에서 @model.save!가 row-level lock을 사용하는데, 동일 job에 대한 동시 요청이 많을 때 lock 경합이 발생한다. Optimistic locking (lock_version 컬럼)을 도입하면 lock wait 없이 충돌을 감지할 수 있다.
SQS 메시지 deduplication 또는 idempotency 강화
- 동일 job에 대한 SQS 메시지가 중복 처리되지 않도록 MessageDeduplicationId를 활용하거나, agent 측에서 job 상태를 먼저 확인(GET)한 후 이미 완료된 경우 PUT을 건너뛰는 로직을 추가한다.

Monitoring#

ActiveRecord::LockWaitTimeout 빈도를 모니터링하여 DB lock 경합 추세를 파악:

text

service:cupixworks-api status:error "LockWaitTimeout"

Complete-agent의 SQS 메시지 재전달 횟수(ApproximateReceiveCount >= 5) 모니터링:

text

service:cupixworks-any-complete-agent status:error "ApproximateReceiveCount"

Nginx 504 발생 빈도 추적:

text

service:cupixworks-any-complete-agent status:error 504

Risk Assessment#

Risk level: low
예상 복잡도: standard
근거: 발생 건수 1건, 자동 해소됨. 단, 동일 패턴이 DB 부하 시 반복될 수 있어 SQS 메시지 삭제 로직과 HTTP timeout 설정 개선이 권장됨.