ES /docs

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-apiGET /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#

  1. 2026-07-16 22:19:52 KSTsiteinsights-service Lambda 의 getElementRecords 가 캐시된 MongoDB 커넥션으로 countDocuments 를 호출하려다 write after end 로 실패, 500 반환. cupixworks-api 는 이 응답을 Cupix::Errors::System 으로 변환하여 502 로 사용자에게 전달 (본 RCA 대상 이벤트).
  2. 2026-07-16 22:25:28 KST — 동일 Lambda 의 bulkElementRecords 에서 Error [ERR_STREAM_WRITE_AFTER_END]: write after end 재발. 같은 warm container 의 캐시된 커넥션 상태 문제로 판단됨.
  3. 2026-07-16 22:25:30 KSTcupixworks-api 에서 bulk_element_records! 500 에러가 상위 서비스로 전파.
  4. 2026-07-16 22:19:53 ~ 23:28:06 KST — 이후 동일 엔드포인트의 요청들은 200 으로 정상 응답 (Datadog 로그에서 다수 확인). 재발 없음.

Error Log#

Datadog Logs

text
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):

app/controllers/api/v1/element_records_controller.rb:1-9ruby
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:

app/services/cupix/siteinsights_service.rb:118-129ruby
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:

applications/siteinsights-service/functions/api/ElementRecord.ts:88-107typescript
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:

applications/siteinsights-service/functions/api/ElementRecord.ts:218-269typescript
    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회, 이후 재사용 시 헬스 체크 없음:

applications/siteinsights-service/functions/libs/document_db.ts:44-104typescript
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 대상 이벤트):

text
service:cupixworks-api "failed to get element records"

결과 (2건):

json
{
  "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!"
}
json
{
  "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 근본 원인 로그:

text
service:siteinsights-service "getElementRecords" "Query failed"

결과 (정확히 같은 초):

json
{
  "timestamp": "2026-07-16 22:19:52",
  "status": "error",
  "message": "ElementRecord::getElementRecords | Query failed: write after end"
}

Datadog query — 형제 오류 (같은 원인, 6분 뒤):

text
service:siteinsights-service "write after end"

결과 (2건, 동일 근원):

json
{
  "timestamp": "2026-07-16 22:25:28",
  "status": "error",
  "message": "ElementRecord::bulkElementRecords | Failed: Error [ERR_STREAM_WRITE_AFTER_END]: write after end"
}
json
{
  "timestamp": "2026-07-16 22:19:52",
  "status": "error",
  "message": "ElementRecord::getElementRecords | Query failed: write after end"
}

대응되는 상위 API 로그 (형제):

json
{
  "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분 창에서 임계치 초과 시 알림.
text
sum:aws.lambda.errors{functionname:siteinsights-service-*}.as_count()
  • ERR_STREAM_WRITE_AFTER_END 로그 발생률:
text
logs("service:siteinsights-service \"write after end\"").index("*").rollup("count").by("service").last("5m") > 0
  • cupixworks-api → siteinsights downstream 502 응답률:
text
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 의 캐시 무효화 로직 추가는 소규모 변경이나, 유사 패턴을 쓰는 다른 서비스로의 수평 전개 및 회귀 테스트 추가가 필요.