RCA: BaseService::handlingMessageErrors | sqsMessage empty error

Overview#

What Happened#

2026-08-06 23:59 KST, cupixworks-any-thumbnail-agent (production, us-west-2, team penn-co) 가 SQS 메시지로 bim 20811 의 썸네일 생성을 시도했다. tesla API 에서 bim 을 조회했으나 403 ENT4000 "Bim not found" 가 돌아와 처리가 중단됐다. agent 는 메시지를 정상 삭제하고 종료했으나, 최종 에러 로그가 실제 에러 내용 없이 error: 에서 끊긴 채 기록됐다. 두 가지 사실이 겹친 클러스터다. underlying trigger 는 이미 삭제된 bim 을 조회한 noise 이고, 로그가 비어 보이는 것은 develop 브랜치에 배포된 observability bug 다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-08-06 23:59:57 KST — BaseService::runByMessage | id: 20811 로 bim 20811 썸네일 메시지 처리 시작
2. 2026-08-06 23:59:57 KST — CupixAuth::setSession 세션 설정, ThumbnailService::newModel | model id: 20811, type: Bim
3. 2026-08-06 23:59:57 KST — tesla API GET /api/v1/bims/20811 이 403 ENT4000 "Bim not found" 반환 → CPBim::getBimById | end - reason: Bim not found
4. 2026-08-06 23:59:57 KST — getApiErrorToDeleteMessage 가 403 을 삭제 가능한 에러로 판정, deleteMessage | end 로 메시지 삭제
5. 2026-08-06 23:59:57 KST — 최종 handlingMessageErrors 로그가 error: 공란으로 기록 (observability bug)

Error Log#

Datadog Logs

BaseService::handlingMessageErrors | sqsMessage - {"MessageId":"3b784e36-4a79-4e1b-b8df-967110b8d157","Attributes":{"ApproximateReceiveCount":"1"}}, error:

Impact#

• Service: cupixworks-any-thumbnail-agent
• Team: penn-co
• 발생 횟수: 1
• 최초 발생: 2026-08-06 23:59 KST
• 최근 발생: 2026-08-06 23:59 KST

Root Cause Summary#

이 클러스터는 두 개의 별개 사실이 하나의 로그로 표면화된 것이다. Underlying trigger 는 noise 다. thumbnail-agent 가 SQS 메시지를 받아 bim 20811 의 썸네일을 생성하려 했으나, 그 시점에 bim 이 이미 삭제/미존재 상태여서 tesla API 가 403 ENT4000 "Bim not found" 를 반환했다. CPBim::getBimById 는 ARG10002 만 흡수하고 ENT4000 은 reject 하므로 에러가 위로 전파돼 handlingMessageErrors 로 들어갔고, getApiErrorToDeleteMessage 가 이를 삭제 가능한 에러로 판정해 메시지를 정상 삭제했다. 사용자 영향은 없다. 로그가 error: 에서 비어 보이는 것은 develop 브랜치의 observability bug 다. base-service.ts:318 의 포맷 문자열은 %s 지정자가 하나뿐인데 splat 인자를 둘 전달한다. 두 번째 인자인 error 객체는 winston splat 이 numeric key 로 저장하고, cplogger.ts 의 filterNumericKeys 가 JSON 직렬화 직전 numeric key 를 전부 제거해 에러 내용이 통째로 유실된다.

Technical Analysis#

Code Path#

Entry point: SQS 메시지 수신 후 run 실행.

			this._countWaitedToStopTask = 0;
			try {
				await this.runByMessages();
			} catch (error) {
				await this.handlingMessageErrors(error);
			}

썸네일 처리는 ThumbnailService::newModel 로 CPBim 모델을 만들고, 모델 초기화 시 getBimById 로 tesla API 를 호출한다.

		this._serverModel = await this.getBimById(this.modelId);
		if (this._serverModel == undefined) return false;

Failure point 은 getBimById 의 catch 블록이다. ARG10002 만 resolve(undefined) 로 흡수하고, ENT4000 을 포함한 나머지는 reject(ec) 로 전파한다.

			.catch(ec => {
				const body = ec?.response?.body;
				if (body) {
					const code = body.result?.code;
					const reason = body.result?.reason ? body.result.reason : body.result?.message;
					logger.warn('CPBim::getBimById | end - reason: %s', reason);
					if (code === 'ARG10002') return resolve(undefined);
				}
				reject(ec);
			});

전파된 에러는 handlingMessageErrors 로 들어간다. getApiErrorToDeleteMessage 가 403 을 삭제 가능한 에러로 판정하면 메시지를 삭제하고, 마지막에 최종 에러 로그를 남긴다.

			const apiErrorObject = this.getApiErrorToDeleteMessage(error);
			if (apiErrorObject != undefined || this.checkReceiveCountToDeleteMessage()) {
				try {
					errorAndMessage.error = apiErrorObject;
					this.cupixAuth.handleError(error);
					await this.deleteByMessage(this.messageInProcess);

Observability bug 는 이 최종 로그 라인이다. 포맷 문자열에 %s 가 하나인데 splat 인자를 둘 넘긴다.

		logger.error('BaseService::handlingMessageErrors | sqsMessage - %s, error:',
			JSON.stringify(errorAndMessage.sqsMessage), errorAndMessage.error);

winston format.splat() 이 첫 인자를 %s 로 소비하고, 두 번째 인자인 errorAndMessage.error 는 numeric key 로 info 에 저장한다. errorSafeFormat 은 splat 내부의 Error 를 {name, message, stack} 로 정규화하지만 여전히 numeric key 아래에 둔다.

						winston.format.printf((info) => {
							const { level, message, label, timestamp, stack, ...rest } = info;
							const cleanRest = filterNumericKeys(rest);

							return JSON.stringify({
								timestamp,
								level,
								label,
								message,
								...(stack ? { stack } : {}),
								...cleanRest
							});
						})

JSON transport 의 printf 가 filterNumericKeys(rest) 로 numeric key 를 전부 제거한다. 결과적으로 error 인자가 통째로 삭제돼 최종 메시지가 error: 에서 끊기고 attributes.error 는 존재하지 않는다.

export const filterNumericKeys = (obj: any): any => {
	const filtered: any = {};
	Object.keys(obj).forEach(key => {
		if (!/^\d+$/.test(key)) {
			filtered[key] = obj[key];
		}
	});
	return filtered;
};

기대 동작은 최종 로그에 에러 내용이 실리는 것이다. 실제 동작은 에러가 유실돼 error: 공란만 남는 것이다. master 브랜치 (base-service.ts:318) 는 'BaseService::handlingMessageErrors | Error and message object - %s', JSON.stringify(errorAndMessage) 로 단일 인자를 직렬화하므로 이 유실이 없다. commit f9860dc41 (TSLA-13277 "pass error to logger as splat instead of JSON.stringify", develop only) 이 이 포맷을 도입했다. git merge-base --is-ancestor f9860dc41 origin/develop = YES, origin/master = NO.

Log Evidence#

bim 20811 로 시간순 추적한 결과가 전체 트리거 체인을 보여준다.

Datadog query:

service:cupixworks-any-thumbnail-agent @bim.id:20811

핵심 로그 (시간 오름차순, 전부 2026-08-06 23:59:57 KST):

info  BaseService::runByMessage | id: 20811
info  CupixAuth::setSession | session_id: 763e56fddd276b123da43a225bcb7d2845e231dd
info  ThumbnailService::newModel | model id: 20811, type: Bim
warn  CPBim::getBimById | end - reason: Bim not found
warn  BaseService::getApiErrorToDeleteMessage | error msg - {"statusCode":403,...,"bodyResult":{"code":"ENT4000","type":"Cupix::Errors::NotFound","reason":"Bim not found","message":"Bim not found"},"modelId":20811}
warn  CupixAuth::handleError | Response statusCode: 403, requestUriHref: http://api-tesla.cupix.internal/api/v1/bims/20811?..., body.result: {"code":"ENT4000","type":"Cupix::Errors::NotFound","reason":"Bim not found","message":"Bim not found"}
info  AwsQueueManager::deleteMessage | begin - queue url: https://sqs.us-west-2.amazonaws.com/002596530511/cupix-tesla-thumbnail-agent-production
info  BaseService::cleanUpAnythingRelatedModel | path: /tmp/workspace/20811
info  AwsQueueManager::deleteMessage | end - message id: 3b784e36-4a79-4e1b-b8df-967110b8d157
error BaseService::handlingMessageErrors | sqsMessage - {"MessageId":"3b784e36-4a79-4e1b-b8df-967110b8d157","Attributes":{"ApproximateReceiveCount":"1"}}, error:

대표 에러 로그의 raw attribute 에서 error 필드가 아예 없고 (splat 유실 확증), version 태그도 없다 (DD_VERSION 미주입, 혼재 배포 판별에 version 태그 사용 불가).

혼재 배포와 트리거 빈도 (14d, us-west-2 production):

service:cupixworks-any-thumbnail-agent "sqsMessage -"            → 181건 (develop 포맷)
service:cupixworks-any-thumbnail-agent "Error and message object" → 144건 (master 포맷)
service:cupixworks-any-thumbnail-agent "Bim not found"           → 465건
service:cupixworks-any-thumbnail-agent "getApiErrorToDeleteMessage" "ENT4000"  → 147건
service:cupixworks-any-thumbnail-agent "getApiErrorToDeleteMessage" "ARG10002" → 3건

두 포맷이 병존한다는 사실이 develop/master 혼재 롤링 배포를 확증한다. ENT4000 이 삭제 가능 에러 판정의 지배적 원인이며 (147 대 3), ApproximateReceiveCount:"1" 은 재시도 루프가 아닌 첫 수신에서 삭제됨을 보인다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• applications/agents/packages/base/src/base-service.ts:318-319 의 포맷 지정자와 splat 인자 개수를 일치시킨다. 현재 %s 하나에 인자 둘을 넘겨 두 번째 error 인자가 유실된다. error 를 로그에 실으려면 지정자를 하나 더 두거나 (... error: %s), master 처럼 단일 객체를 직렬화하는 방식으로 정렬한다. 이 수정은 진단성 회복이 목적이며 트리거 자체 (403) 는 noise 이므로 코드 변경 대상이 아니다.

단기 개선 (1주 이내)#

• develop/master 로그 포맷 혼재를 해소한다. 두 브랜치가 서로 다른 handlingMessageErrors 포맷을 배포 중이라 Datadog 알림/집계 fingerprint 가 분열된다. f9860dc41 (TSLA-13277) 계열을 정렬 배포하거나 master 로 통일한다.
• cplogger.ts:45-53 filterNumericKeys 가 splat 진단 정보를 삼키는 부작용을 재검토한다. 현재는 포맷 실수를 조용히 감추는 안전망 반대 방향으로 작동한다.

장기 개선 (재발 방지)#

• 로그에 DD_VERSION 을 주입해 version 태그로 develop/master 배포를 구분할 수 있게 한다 (cplogger.ts:109 는 process.env.DD_VERSION || '1.0.0' 를 쓰나 실제 로그에 태그가 없다).
• agent 로거 포맷 문자열에 대한 lint 규칙 또는 spec 을 추가해 %s 지정자 개수와 splat 인자 개수 불일치를 CI 에서 잡는다.

Monitoring#

develop 포맷 empty-error 로그 발생 추이 (수정 배포 후 감소해야 함):

service:cupixworks-any-thumbnail-agent status:error "sqsMessage -"

underlying trigger (삭제된 bim 썸네일 요청) 추이:

service:cupixworks-any-thumbnail-agent "Bim not found"

master/develop 포맷 병존 확인 (혼재 배포 해소 시 한쪽이 0 으로 수렴):

service:cupixworks-any-thumbnail-agent "Error and message object"

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial

underlying trigger 는 noise 이므로 코드 수정 불필요. observability bug 수정은 로거 포맷 문자열 한 줄 정렬로, breaking change 위험이 없다.