failed to get element records - error: 500 Internal Server Error
RCA: failed to get element records - error: 500 Internal Server Error
Overview#
What Happened#
2026-07-16 22:19:52 KST에 cupixworks-api 의 GET /api/v1/siteinsights/element_records 요청 1건이 502로 응답했다. Cupix::SiteinsightsService.get_element_records! 가 downstream siteinsights-service Lambda 를 호출했으나 Lambda 가 500을 반환했고, 그 원인은 캐시된 MongoDB(DocumentDB) 커넥션에서 발생한 ERR_STREAM_WRITE_AFTER_END(write after end) 였다. 6분 뒤(22:25:28 KST) 동일 Lambda 의 bulkElementRecords 에서도 같은 원인의 오류가 재현되어, 단일 호출 실패가 아닌 warm container 의 커넥션 상태 문제로 확인된다.
Quick Facts#
| Field | Value |
|---|---|
| exception.class | Cupix::Errors::System |
| exception.message | failed to get element records - error: 500 Internal Server Error |
| top_frame | app/services/cupix/siteinsights_service.rb:122 |
| downstream root cause | ERR_STREAM_WRITE_AFTER_END in siteinsights-service Lambda (MongoDB driver) |
| top_frame (downstream) | applications/siteinsights-service/functions/api/ElementRecord.ts:254 |
| error_code | SYS20000 |
| http status | 502 (API 응답), 500 (Lambda 응답) |
| env | production, us-west-2 |
Affected Teams#
| Team / Domain | Error Count | Impact |
|---|---|---|
| siteinsights (element_records) | 2 | 6분 간격으로 GET /element_records 1회 및 PUT /element_records/bulk 1회 실패. 사용자 관점에서는 element_records 조회/저장이 각 1회 502 로 실패. 재시도 시 성공 (인접 200 응답 다수 확인). |
Timeline#
- 2026-07-16 22:19:52 KST —
siteinsights-serviceLambda 의getElementRecords가 캐시된 MongoDB 커넥션으로countDocuments를 호출하려다write after end로 실패, 500 반환.cupixworks-api는 이 응답을Cupix::Errors::System으로 변환하여 502 로 사용자에게 전달 (본 RCA 대상 이벤트). - 2026-07-16 22:25:28 KST — 동일 Lambda 의
bulkElementRecords에서Error [ERR_STREAM_WRITE_AFTER_END]: write after end재발. 같은 warm container 의 캐시된 커넥션 상태 문제로 판단됨. - 2026-07-16 22:25:30 KST —
cupixworks-api에서bulk_element_records!500 에러가 상위 서비스로 전파. - 2026-07-16 22:19:53 ~ 23:28:06 KST — 이후 동일 엔드포인트의 요청들은 200 으로 정상 응답 (Datadog 로그에서 다수 확인). 재발 없음.
Error Log#
failed to get element records - error: 500 Internal Server Error
Impact#
- Service:
cupixworks-api - 발생 횟수: 1 (이 클러스터), 동일 근원의 형제 오류 1건 (
bulk_element_records!22:25:30 KST) - 최초 발생: 2026-07-16 22:19:52 KST
- 최근 발생: 2026-07-16 22:19:52 KST
Root Cause Summary#
siteinsights-service Lambda 는 module scope 에 docDBCollection (MongoDB Collection 참조) 를 캐싱하여 warm container 사이에서 재사용한다. 그러나 캐시 재사용 경로에는 커넥션 헬스 체크(ping 등)가 없고, 오직 처음 연결 시 한 번만 ping 을 수행한다. 그 결과 DocumentDB 측 socket 이 idle timeout / failover / 네트워크 스파이크 등으로 이미 닫힌 상태에서도 캐시된 Collection 을 그대로 반환하며, 다음 쿼리가 종료된 stream 에 write 를 시도해 Node.js MongoDB driver 가 ERR_STREAM_WRITE_AFTER_END 를 발생시킨다. getElementRecords 는 이 예외를 catch 하여 500 을 반환하고, 상위 cupixworks-api 는 이를 Cupix::Errors::System 으로 감싼 뒤 502 로 응답한다. 6분 뒤 같은 Lambda 컨테이너에서 bulkElementRecords 도 동일 오류를 재현한 것이 이 가설을 확정한다.
Technical Analysis#
Code Path#
Entry point (API):
class Api::V1::ElementRecordsController < Api::V1::ApiController
rescue_from Cupix::Errors::System, with: :redirect_to_502_error
def index
si_query_option = Cupix::QueryOption::Siteinsights.new(get_query_option, params)
element_records = Cupix::SiteinsightsService.get_element_records!(si_query_option, fields: @fields, current_user: @current_user, current_team: @current_team)
render_json 200, element_records
end
Downstream call and error wrapping:
response = Cupix::HttpClient.get("#{Cupix::Siteinsights.service_url}/element_records?#{params.to_param}")
JSON.parse(response.body)['result']
rescue RestClient::Exception => e
Cupix::Logger.error("failed to get element records - error: #{e.message}", class: self.name, function: __method__, facility_key: query_option.facility_key, params: params)
raise Cupix::Errors::System.new(code: 'SYS20000', reason: "failed to get element records - error: #{e.message}")
Lambda handler entry / cached collection reuse:
const modelName = 'ElementRecord';
const databaseName = process.env.DATABASE_NAME || 'cupix_cupixworks_development';
const collectionName = process.env.COLLECTION_NAME || 'element_records';
let docDBCollection: Collection | undefined;
export const handler: Handler = async (event: APIGatewayProxyEvent, context: Context) => {
if (context) context.callbackWaitsForEmptyEventLoop = false;
CPLogger.info(`Begin with event: ${JSON.stringify(event)}`, { class: modelName, function: 'handler' });
if (!docDBCollection) {
CPLogger.info(`docDBCollection is not connected. Connecting...`, { class: modelName, function: 'handler' });
docDBCollection = await connectToDatabase(databaseName, collectionName);
}
Failure point — countDocuments / find 가 이미 닫힌 socket 에 write:
const totalEntries = await collection.countDocuments(matchFilter);
const elementRecords = await collection
.find(matchFilter, queryOption)
.skip((page - 1) * perPage)
.limit(perPage)
.toArray();
// ... 정상 경로
} catch (error: unknown) {
const message = error instanceof Error ? error.message : String(error);
CPLogger.error(`Query failed: ${message}`, {
class: modelName,
function: action,
facility: { key: facilityKey },
page: page,
per_page: perPage,
error: message,
});
return {
statusCode: 500,
body: JSON.stringify({ error: message }),
};
}
Cache logic — ping 은 최초 연결 시 1회, 이후 재사용 시 헬스 체크 없음:
export const connectToDatabase = async (
databaseName: string,
collectionName: string,
agentName = 'siteinsights-service',
): Promise<Collection> => {
try {
if (docDBCollection) {
CPLogger.info('Reusing existing collection', { class: 'DocDB', function: 'connectToDatabase' });
return docDBCollection;
}
// ... 최초 연결 경로
docDBClient = new MongoClient(
`mongodb+srv://${dbUsername}:${dbPassword}@${srvEndpoint}?retryWrites=true&w=majority&appName=${agentName}`,
{
// ...
connectTimeoutMS: 5000,
socketTimeoutMS: 150000,
serverSelectionTimeoutMS: 15000,
readPreference: 'secondaryPreferred',
},
);
// ...
await docDBClient.connect();
await docDBClient.db(databaseName).command({ ping: 1 });
docDBCollection = docDBClient.db(databaseName).collection(collectionName);
기대 동작: 각 요청마다 살아있는 커넥션으로 쿼리 수행 (또는 driver 가 자동 재연결하여 투명하게 성공).
실제 동작: warm container 재사용 시, 캐시된 docDBCollection 은 이미 닫힌 하위 socket 을 통해 write 를 시도하여 ERR_STREAM_WRITE_AFTER_END 발생. serverClosed / timeout 이벤트는 로깅만 되고 docDBCollection 캐시를 무효화하지 않음.
Log Evidence#
Datadog query — cupixworks-api 에러 (RCA 대상 이벤트):
service:cupixworks-api "failed to get element records"
결과 (2건):
{
"timestamp": "2026-07-16 22:19:52",
"status": "error",
"message": "failed to get element records - error: 500 Internal Server Error",
"class": "Cupix::SiteinsightsService",
"function": "get_element_records!"
}
{
"timestamp": "2026-07-16 22:19:52",
"status": "info",
"message": "[502] GET /api/v1/siteinsights/element_records (Api::V1::ElementRecordsController#index)",
"error": {
"reason": "failed to get element records - error: 500 Internal Server Error",
"code": "SYS20000",
"message": "failed to get element records - error: 500 Internal Server Error",
"class": "Cupix::Errors::System"
}
}
Datadog query — downstream Lambda 근본 원인 로그:
service:siteinsights-service "getElementRecords" "Query failed"
결과 (정확히 같은 초):
{
"timestamp": "2026-07-16 22:19:52",
"status": "error",
"message": "ElementRecord::getElementRecords | Query failed: write after end"
}
Datadog query — 형제 오류 (같은 원인, 6분 뒤):
service:siteinsights-service "write after end"
결과 (2건, 동일 근원):
{
"timestamp": "2026-07-16 22:25:28",
"status": "error",
"message": "ElementRecord::bulkElementRecords | Failed: Error [ERR_STREAM_WRITE_AFTER_END]: write after end"
}
{
"timestamp": "2026-07-16 22:19:52",
"status": "error",
"message": "ElementRecord::getElementRecords | Query failed: write after end"
}
대응되는 상위 API 로그 (형제):
{
"timestamp": "2026-07-16 22:25:30",
"status": "error",
"message": "failed to bulk element records - error: 500 Internal Server Error",
"class": "Cupix::SiteinsightsService",
"function": "bulk_element_records!"
}
주변 정상 트래픽 확인 — 같은 엔드포인트 200 응답 다수 (예: 22:20:33 ~ 23:28:06 KST 사이 30건 이상 200) → 지속 장애가 아닌 warm container 커넥션 상태 문제로 판단.
Hypotheses Considered#
| # | Hypothesis | Evidence for | Evidence against | Verdict |
|---|---|---|---|---|
| H1 | siteinsights-service Lambda 의 캐시된 MongoDB 커넥션이 stale 상태에서 write 되어 ERR_STREAM_WRITE_AFTER_END 발생, 500 반환. cupixworks-api 는 이를 502 로 래핑. |
Lambda 로그 Query failed: write after end 가 API 500 과 동일 초(22:19:52 KST)에 존재. 6분 뒤 동일 컨테이너 재사용으로 추정되는 bulkElementRecords 도 같은 ERR_STREAM_WRITE_AFTER_END 재발. 캐시 재사용 경로(ElementRecord.ts:104-107, document_db.ts:50-54)에 헬스 체크 부재. serverClosed/timeout 이벤트가 캐시를 무효화하지 않음. |
— | Confirmed |
| H2 | DocumentDB 자체의 광범위한 장애 또는 지속적 성능 저하 | 22:19:52 KST 근방에 siteinsights-service 에러 spike. |
같은 엔드포인트로 22:20 이후 다수 200 응답 정상 (Datadog 로그 30+ 건). 이후 1시간 이상 재발 없음. 지속적 outage 라면 정상 응답이 나올 수 없음. status-board 에도 dep:* active 인시던트 없음. |
Rejected |
| H3 | Cupix::HttpClient 타임아웃 또는 재시도 로직 결함으로 Lambda 는 성공했으나 API 가 500 으로 해석 |
RestClient::Exception 을 catch 하는 rescue 가 있음 (siteinsights_service.rb:121). |
Lambda 측 500 로그가 존재하고 메시지가 정확히 "500 Internal Server Error" 로 일치. Lambda 는 실제로 500 body 를 반환. | Rejected |
| H4 | Rails 서비스 코드의 파라미터 검증 실패 (Cupix::Errors::Parameter) |
get_element_records! 는 facility_key blank 시 ARG10000 을 raise (siteinsights_service.rb:101). |
로그의 error code 는 SYS20000, message 는 downstream 500 이며 ARG10000 아님. |
Rejected |
Fix Recommendation#
즉시 조치 (Critical)#
- 파일:
applications/siteinsights-service/functions/libs/document_db.ts:50-54 - 접근: 캐시된
docDBCollection을 반환하기 전에docDBClient.db(databaseName).command({ ping: 1 })을 수행하여 커넥션 헬스를 검증하고, ping 실패 시docDBClient/docDBCollection을 초기화하고 새로 연결하도록 변경. 또는 이미 등록된serverClosed/timeout이벤트 핸들러(document_db.ts:85-90)에서docDBCollection = undefined(및 필요 시docDBClient재생성 트리거) 로 캐시를 명시적으로 무효화. 후자가 정상 경로에 latency overhead 를 주지 않아 더 선호됨. - 근거: stale-connection 재사용이 원인임을 로그로 확인했고, driver 이벤트 훅은 이미 존재하지만 캐시를 무효화하지 않음. 이벤트 핸들러 안에서 캐시를 리셋하면 다음 호출이 자동으로 fresh 커넥션을 만들어 문제가 사라진다.
단기 개선 (1주 이내)#
- retry with reconnect at handler level:
applications/siteinsights-service/functions/api/ElementRecord.ts:104-107의 lazy-init 이후 첫 쿼리에서ERR_STREAM_WRITE_AFTER_END/MongoNetworkError/MongoServerSelectionError계열 예외를 감지하면closeConnection()후 1회 재시도.postValidation,postStaleElements,bulkElementRecords,updateElementRecord,getLastSyncedAt등 다른 핸들러도 동일 패턴을 공유하므로 wrapper 로 통합. - 동일 코드 확산 점검: siteinsights-service 외에도
functions/libs/document_db.ts와 동일 캐싱 패턴을 쓰는 다른 service(예:applications/*/libs/document_db*) 가 있는지 확인해 같은 결함이 있으면 한꺼번에 수정.Grep대상 예:docDBCollection캐시 변수명,Reusing existing collection로그 문자열. - cupixworks-api 측 재시도:
Cupix::HttpClient.get(...)호출부(siteinsights_service.rb:118)에서 downstream 500 이 idempotent GET 이면 짧은 backoff 후 1회 재시도. 다만 downstream 수정이 우선이며, 여기서는 side effect 없는 GET 에만 적용해야 함.
장기 개선 (재발 방지)#
- MongoClient 옵션 재검토:
maxIdleTimeMS,heartbeatFrequencyMS를 명시적으로 설정하여 driver 가 dead socket 을 조기에 감지하도록 함. 현재는socketTimeoutMS: 150000만 설정되어 있어 idle detection 은 driver 기본값에 의존. - connection pool metric 수집: MongoDB driver 의 CMAP 이벤트(
connectionCreated,connectionClosed,connectionCheckOutFailed)를 CloudWatch metric 으로 export 하여 stale-connection 발생 시점을 추적 가능하게 함. - integration smoke test: DocumentDB failover 시나리오를 staging 에서 재현하는 chaos test 추가 (Route 53 CNAME primary swap 유도).
Monitoring#
메트릭/알림 추가 제안:
- Lambda 500 응답률 (siteinsights-service): 5분 창에서 임계치 초과 시 알림.
sum:aws.lambda.errors{functionname:siteinsights-service-*}.as_count()
ERR_STREAM_WRITE_AFTER_END로그 발생률:
logs("service:siteinsights-service \"write after end\"").index("*").rollup("count").by("service").last("5m") > 0
- cupixworks-api → siteinsights downstream 502 응답률:
logs("service:cupixworks-api \"failed to get element records\" OR \"failed to bulk element records\" OR \"failed to get last_synced_at of ElementRecord\"").index("*").rollup("count").by("service").last("5m")
- DocumentDB CNAME 이 가리키는 primary endpoint 변경 감지: Route 53 health check 또는 별도 dashboard.
Risk Assessment#
- Risk level: low (현재 시점 기준). 총 관측된 사용자 영향은 15분 이내 2건. 다만 warm-container 캐시 이슈는 잠재적 재발성이 있어 방치 시 DocumentDB 유지보수/failover 시마다 재현될 수 있음.
- 예상 복잡도: standard.
document_db.ts의 캐시 무효화 로직 추가는 소규모 변경이나, 유사 패턴을 쓰는 다른 서비스로의 수평 전개 및 회귀 테스트 추가가 필요.