BaseService::handlingMessageErrors | Error and message object - {"error":{"statusCode":403,"requestU

RCA: BaseService::handlingMessageErrors — Capture not found (ENT4000)

Overview#

What Happened#

2026-06-24 14:57:34 KST에 cupixworks-capture-preprocessor-agent가 SQS 메시지를 처리하며 capture 720817을 조회하려다 cupixworks-api로부터 403 / ENT4000 (Capture not found) 응답을 받았다. 사용자가 동일 capture에 대해 같은 SQS 작업이 enqueue된 직후 PUT /captures/720817/trash 호출로 capture를 휴지통으로 보냈고, 약 4분 뒤 agent가 이미 in-flight였던 메시지를 꺼내어 처리하던 중 발생한 race condition이다.

Quick Facts#

Field	Value
exception.class	`Cupix::Errors::NotFound`
exception.code	`ENT4000`
exception.message	`Capture not found`
http.status	`403`
top_frame	`packages/base/src/base-service.ts:311` (`BaseService::handlingMessageErrors`)
api endpoint	`GET /api/v1/captures/720817`
env	production, `us-west-2`, tenant `cupix`, team `updatedemo`

Affected Teams#

Team / Domain	Error Count	Impact
updatedemo (capture 720817)	1	사용자가 직접 trash한 capture의 잔여 preprocessor job 1건이 실패로 마감 (SQS 메시지 삭제됨). 사용자 영향 없음.
다른 팀 (24h 같은 패턴)	6	`74587`, `74567`, `74547`, `74440`, `44706`, `74417` — 모두 동일한 `403/ENT4000` 시그니처. 별도 클러스터로 추적되지 않은 같은 race condition 사례.

Timeline#

2026-06-24 14:52:44 KST — capture 720817 생성 (created_at: 2026-06-24T05:52:44.682Z, Kibana)
2026-06-24 14:52:59 KST — [200] PUT /api/v1/captures/720817 (update), [200] GET /api/v1/captures/720817 — preprocessor job이 enqueue됨
2026-06-24 14:53:37 KST — [204] PUT /api/v1/captures/720817/trash — 사용자가 capture를 휴지통으로 이동
2026-06-24 14:57:34 KST — agent가 SQS 메시지(d8014f41-..., ApproximateReceiveCount=1)를 dequeue, GET /api/v1/captures/720817 호출 → [403] ENT4000 Capture not found 응답
2026-06-24 14:57:34 KST — getApiErrorToDeleteMessage가 statusCode 403을 deletable error로 분류, SQS 메시지 삭제 + error 레벨 로그 출력

Error Log#

Datadog Logs

text

BaseService::handlingMessageErrors | Error and message object - {"error":{"statusCode":403,"requestUriHref":"http://api-tesla.cupix.internal/api/v1/captures/720817?fields%5B0%5D=id&...","bodyResult":{"code":"ENT4000","type":"Cupix::Errors::NotFound","reason":"Capture not found","message":"Capture not found"},"modelId":1148998},"sqsMessage":{"MessageId":"d8014f41-4dd5-4089-b1cc-86c7340ac2a7","Attributes":{"ApproximateReceiveCount":"1"}}}

Impact#

Service: cupixworks-capture-preprocessor-agent
Team: updatedemo
발생 횟수: 1 (해당 클러스터) / 24시간 내 동일 패턴 7건
최초 발생: 2026-06-24 14:57:34 KST
최근 발생: 2026-06-24 14:57:34 KST

기능적 사용자 영향은 없음 — 사용자가 명시적으로 trash한 리소스의 후속 처리가 실패하는 것이 의도된 결과다. agent는 SQS 메시지를 정상적으로 삭제하여 재시도 루프에 빠지지 않는다. 다만 운영 로그 노이즈와 알람 fatigue를 유발한다.

Root Cause Summary#

User-initiated trash와 in-flight preprocessor SQS 작업 간 race condition. cupixworks-api는 untrashed scope (trashed_at IS NULL)로 capture를 조회하므로, capture가 trash된 후 agent가 메시지를 dequeue하면 BaseRepository.show의 query.merge(scope).first가 nil을 반환하고 self.where(attrs).in_trash.present? 분기에서 Cupix::Errors::NotFound(code: 'ENT4000')을 raise한다. ClientErrorController는 이 예외를 not_found_403_error로 매핑하여 HTTP 403을 응답하고, agent의 getApiErrorToDeleteMessage는 4xx/5xx를 deletable로 분류하여 SQS 메시지를 삭제한 뒤 handlingMessageErrors에서 error 레벨로 기록한다. 즉 동작 자체는 의도대로지만, 정상 운영 시나리오(사용자 trash)가 status:error 로그로 노출되는 것이 문제다.

Technical Analysis#

Code Path#

Entry point (agent): packages/base/src/base-service.ts:108 — runByMessages() 진입

packages/base/src/base-service.ts:106-115typescript

this._countWaitedToStopTask = 0;
try {
    await this.runByMessages();
} catch (error) {
    await this.handlingMessageErrors(error);
}
this.resetMessages();
await CPUtils.sleep(500);
await this.checkingQueue();

API 호출 단계: packages/base/src/base-service.ts:153-185 — runByMessage가 메시지를 디코드하고 authenticateByMessage → run(targetId, msgObject)을 호출. preprocessor의 run 구현이 GET /api/v1/captures/{id}?fields[...]=...을 호출하다 4xx 응답에서 throw.

Error classification (agent): packages/base/src/base-service.ts:240-276

packages/base/src/base-service.ts:255-275typescript

const statusCode = response.statusCode ? Number(response.statusCode) : undefined;
const requestUriHref = response.request?.uri?.href;
const bodyResult = response.body?.result;
// ...
const errorMsg = {
    statusCode: statusCode,
    requestUriHref: requestUriHref,
    bodyResult: bodyResult,
    modelId: modelId
};
logger.warn('BaseService::getApiErrorToDeleteMessage | error msg - %s', JSON.stringify(errorMsg));

if (statusCode != undefined && statusCode >= 400 && statusCode <= 500) {
    if (statusCode === 401) return;
    return errorMsg;
}

400-500 응답(401 제외)을 deletable로 분류하므로 403 ENT4000은 정상 처리된다.

Failure logging: packages/base/src/base-service.ts:290-313

packages/base/src/base-service.ts:300-312typescript

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));

여기서 logger.error가 호출되어 Datadog에 status:error로 적재된다. 클러스터의 대표 메시지가 바로 이 라인이다.

Origin (API): app/repositories/base_repository.rb:306-357

app/repositories/base_repository.rb:342-356ruby

scope = current_class.visibility_scope(visibility)
model = query.merge(scope).first

if model.nil? && current_user.present? && current_user.team.domain == 'admin'
    unless (::UserRepository.new(model: current_user).group_codes & %w[administrator senior_editing_engineers]).empty?
        model = self.where(attrs).merge(scope).first
    end
end

if model.nil?
    if self.where(attrs).in_trash.present?
        raise Cupix::Errors::NotFound.new(code: 'ENT4000', reason: "#{current_class.name} not found")
    else
        raise Cupix::Errors::NotFound.new(code: 'ARG10002', reason: "#{current_class.name} not found")
    end
end

기본 visibility는 Cyclable.visibility[:UNTRASHED]이므로 trashed capture는 결과에서 제외된다. in_trash.present?가 true이면 ENT4000이 raise된다.

Trashable scope:

app/models/concerns/trashable.rb:9-22ruby

def self.untrashed
    where(trashed_at: nil, purged_at: nil)
end

def self.trashed
    where.not(trashed_at: nil).where(purged_at: nil)
end
# ...
def self.in_trash
    trashed
end

HTTP status mapping: app/controllers/concerns/client_error_controller.rb:27,57-59

app/controllers/concerns/client_error_controller.rb:26-71ruby

rescue_from Cupix::Errors::PermissionDenied, with: :permission_denied_403_error
rescue_from Cupix::Errors::NotFound, with: :not_found_403_error
# ...
def not_found_403_error(exception)
    raise_error(403, exception)
end

Cupix::Errors::NotFound가 의도적으로 403으로 매핑된다 (404가 아니라). 이것이 statusCode: 403, bodyResult.type: Cupix::Errors::NotFound 조합의 원인.

Log Evidence#

Datadog 쿼리 (preprocessor agent + capture id):

text

service:cupixworks-capture-preprocessor-agent (720817)

text

service:cupixworks-api "captures/720817"

API 측 라이프사이클 (cupixworks-api Datadog, KST):

text

2026-06-24 14:52:59  [200] PUT /api/v1/captures/720817 (Api::V1::CapturesController#update)
2026-06-24 14:52:59  [200] GET /api/v1/captures/720817 (Api::V1::CapturesController#show)
2026-06-24 14:53:37  [204] PUT /api/v1/captures/720817/trash (Api::V1::CapturesController#trash)
2026-06-24 14:57:35  [403] GET /api/v1/captures/720817 (Api::V1::CapturesController#show)
                     error.code=ENT4000 error.class=Cupix::Errors::NotFound reason="Capture not found"

Agent 측 동일 시점 로그 (KST):

json

{
  "timestamp": "2026-06-24 14:57:34",
  "status": "warn",
  "message": "BaseService::getApiErrorToDeleteMessage | error msg - {\"statusCode\":403,\"requestUriHref\":\"http://api-tesla.cupix.internal/api/v1/captures/720817?...\",\"bodyResult\":{\"code\":\"ENT4000\",\"type\":\"Cupix::Errors::NotFound\",\"reason\":\"Capture not found\",\"message\":\"Capture not found\"},\"modelId\":1148998}"
}

json

{
  "timestamp": "2026-06-24 14:57:34",
  "status": "warn",
  "message": "CupixAuth::handleError | Response statusCode: 403, requestUriHref: http://api-tesla.cupix.internal/api/v1/captures/720817?..., body.result: {\"code\":\"ENT4000\",\"type\":\"Cupix::Errors::NotFound\",\"reason\":\"Capture not found\",\"message\":\"Capture not found\"}"
}

Kibana로 capture 상태 확인 (production-us):

text

index=captures, id=720817
state: "processing"
trashed_at: null   ← Elasticsearch 인덱스가 stale (DB는 trash 상태)
created_at: 2026-06-24T05:52:44.682Z
team: { id: 643, domain: "updatedemo" }

ES 인덱스에 trashed_at이 아직 반영되지 않았으나, api 응답이 ENT4000을 반환했고 14:53:37 KST에 PUT /trash가 [204] 성공으로 기록된 사실이 trash 발생을 증명한다.

24시간 패턴 (다른 capture에서도 동일 시그니처, KST):

text

2026-06-24 10:43:47   capture 74417   modelId 37302   ApproximateReceiveCount 1
2026-06-24 14:57:34   capture 720817  modelId 1148998 ApproximateReceiveCount 1   ← 본 클러스터
2026-06-24 16:00:40   capture 44706   modelId 35619   ApproximateReceiveCount 1
2026-06-24 16:00:52   capture 74440   modelId 37328   ApproximateReceiveCount 1
2026-06-24 18:46:47   capture 74547   modelId 37329   ApproximateReceiveCount 1
2026-06-24 18:57:47   capture 74567   modelId 37330   ApproximateReceiveCount 1
2026-06-24 19:16:46   capture 74587   modelId 37331   ApproximateReceiveCount 1

전부 ApproximateReceiveCount=1 — 재시도가 아니라 첫 dequeue 즉시 실패. dlq retry 문제가 아닌 단발성 race condition임을 보여준다.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	사용자가 preprocessor 작업 enqueue 직후 capture를 trash하여 in-flight 메시지 처리 시점에 trashed 상태가 되었다	`[204] PUT /captures/720817/trash` 14:53:37 KST → 4분 후 14:57:34 KST에 agent dequeue 후 403; `ApproximateReceiveCount=1`이라 retry 시간차도 아님; `base_repository.rb:352-353`이 `in_trash.present?`에서 `ENT4000` raise하는 분기 일치	—	Confirmed
H2	인증/권한 만료로 인한 403 (`Cupix::Errors::PermissionDenied`)	응답 statusCode가 403	bodyResult.type이 `Cupix::Errors::NotFound`이고 code가 `ENT4000` — `permission_denied_403_error`가 아닌 `not_found_403_error` 경로. `client_error_controller.rb:27` 매핑이 이 조합을 NotFound로 식별	Rejected
H3	capture가 hard delete되어 ES와 DB 모두에 없는 상태	—	Kibana ES에 id=720817 문서가 존재하고 `state: processing`. `purged_at` 등 hard delete 마커도 없음. `base_repository.rb:355`라면 `ARG10002`였을 텐데 실제는 `ENT4000` (trash 분기)	Rejected
H4	API가 인증 실패로 capture를 못 찾았다	—	preprocessor agent의 동일 시점 `cupixApi` 호출이 `[200]`을 받은 다른 endpoint도 있을 것이고, 응답 body가 `ENT4000` 식별 가능한 구조라는 점은 인증이 정상 통과했음을 의미 (`unauthorized_401_error`는 401 반환)	Rejected
H5	agent 측 retry 폭주가 원인	—	`ApproximateReceiveCount: 1` — 첫 receive에서 즉시 실패. retry 없음. `MaxReceiveCount`에 도달하지 않은 단발성 이벤트	Rejected

Fix Recommendation#

즉시 조치 (Critical)#

특별한 코드 결함은 없다. 현재 동작은 의도된 결과이며 데이터/사용자 영향은 없다. 단, 로그 레벨이 운영 노이즈를 유발하므로 다음 한 가지만 권장:

packages/base/src/base-service.ts:311 — handlingMessageErrors의 마지막 logger.error(...) 호출을 예상 가능한 에러(trash race 등 4xx ENT4000/ARG10002)와 그 외 에러를 구분해야 한다.
- bodyResult.code가 ENT4000/ARG10002 (NotFound 계열)이고 statusCode 403/404인 경우 logger.warn으로 다운그레이드.
- 그 외 5xx, 미분류 4xx, undefined 에러는 현행 logger.error 유지.
- 근거: 메모리 노트 — "Assess error severity during RCA. Cross-region tokens, rate limits, and transient network issues may warrant warn-level logging, not error." 사용자 trash는 정상 운영 시나리오로 동일 카테고리에 속함.

단기 개선 (1주 이내)#

getApiErrorToDeleteMessage(base-service.ts:240)에서 deletable로 분류된 에러는 호출자에게 { severity: 'warn', ... } 메타를 함께 반환하거나, handlingMessageErrors 시그니처를 변경해 apiErrorObject.severity에 따라 log level을 선택하도록 한다.
preprocessor의 run() 진입부에서 capture를 조회하기 전에 SQS 메시지 enqueue 시각과 현재 시각 차이를 측정/로깅하면 race window가 큰 케이스를 모니터링하기 쉬워진다 (선택).

장기 개선 (재발 방지)#

API 측에서 trash 시점에 in-flight preprocessor 작업을 적극적으로 cancel하거나, SQS 메시지에 expected_state (e.g. trashed_at IS NULL at enqueue time) 토큰을 포함해 agent가 silent skip 할 수 있는 contract를 도입.
또는 capture trash 트랜잭션에서 관련 SQS 메시지를 visibility timeout 0으로 만들거나 DLQ로 라우팅하는 헬퍼 추가.
preprocessor SQS queue에 message age 메트릭을 노출해 race window를 추적.

Monitoring#

추가할 메트릭/알림:

cupixworks-capture-preprocessor-agent의 handlingMessageErrors error 로그 빈도가 baseline 대비 급증하는지 추적. 시그니처별 (statusCode + bodyResult.code) 그룹핑.
trash race 비율: [204] PUT /captures/*/trash 후 N분 이내 동일 capture로 [403] ENT4000 발생 비율.

text

service:cupixworks-capture-preprocessor-agent status:error "handlingMessageErrors"

text

service:cupixworks-capture-preprocessor-agent "ENT4000" "Capture not found"

text

service:cupixworks-api @http.status_code:403 "ENT4000" "captures"

Risk Assessment#

Risk level: low
예상 복잡도: trivial (로그 레벨 다운그레이드 한정)
코드 변경 없이 종료해도 운영상 안전 — getApiErrorToDeleteMessage가 이미 deletable로 분류하여 SQS 메시지가 정상 소진되고, capture는 trash 상태로 의도대로 유지됨.