BaseService::handlingMessageErrors | Error and message object - {"error":{"response":{"statusCode":5

RCA: BaseService::handlingMessageErrors 504 Gateway Time-out (captures/732626/meta/mark)

Overview#

What Happened#

cupixworks-capture-preprocessor-agent 가 SQS 메시지를 처리하는 중 api-tesla.cupix.internal 로 PUT /api/v1/captures/732626/meta/mark 요청을 보냈고, 2026-07-11 02:29 KST 에 nginx 로부터 HTTP 504 Gateway Time-out 을 받아 BaseService::handlingMessageErrors 에서 error 로그가 남았다. 같은 capture(732626) 에 대한 API 요청은 그 직전 약 5분간 매 요청마다 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 로 502 를 반환해 왔고, 504 는 nginx 가 upstream(Rails) 응답 지연을 끊으면서 발생한 tail 이벤트로 확인된다.

Quick Facts#

Field	Value
exception.class	`HttpError` (agent side) — 원인은 `ActiveRecord::LockWaitTimeout` (Rails side)
exception.message	`504 Gateway Time-out` / `Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction`
top_frame (agent)	`packages/base/src/base-service.ts:311` (`BaseService::handlingMessageErrors`)
top_frame (api)	`app/controllers/concerns/metable_controller.rb:42-69` (`MetableController#update_meta_by_key`)
deploy	확인되지 않음 — 로그에 배포 SHA 없음
env	`production`, region `us-west-2`, tenant `cupix`

Affected Teams#

Team / Domain	Error Count	Impact
clark-vdc (capture-preprocessor-agent)	1	SQS 메시지 처리 실패, 재시도 필요
fortis (동일 서비스, TransferManager)	2	같은 서비스에서 504 로 download 실패 — 사이드-이펙트로 추정 (관련 클러스터 `cc6978c4-d452-4a79-add1-93bc84e8e0e4`)
cupixworks-api (tesla)	30+ (전체 endpoint)	17:24–17:32 UTC 사이 다수 endpoint 에서 `LockWaitTimeout` — 시스템 전역의 MySQL row-lock 경합

Timeline#

2026-07-11 02:10 KST — TransferManager::downloadFile 에서 504 발생 (sibling cluster cc6978c4, first_seen 2026-07-10T17:10:18Z)
2026-07-11 02:11 KST — status-board 가 서비스 열화 인시던트 오픈 (2026-07-10-svc-cupixworks-capture-preprocessor-agent--unknown-1)
2026-07-11 02:23 KST — capture 732626 에서 첫 Mysql2::Error::TimeoutError 발생 (PUT /api/v1/captures/732626, 2026-07-10T17:23:11Z)
2026-07-11 02:24 KST — PUT /api/v1/captures/732626/meta/mark 첫 502 (17:24:08Z)
2026-07-11 02:25–02:28 KST — 동일 endpoint 4회 연속 502, 매번 Lock wait timeout exceeded
2026-07-11 02:29 KST — 6번째 재시도에서 nginx 가 upstream timeout 으로 504 반환. Agent 가 BaseService::handlingMessageErrors 로그 남김 (first_seen/last_seen = 2026-07-10T17:29:16.651Z)
2026-07-11 02:30–02:32 KST — 다른 endpoint (/api/v1/panos/*/check_uploading, /api/v1/jobs/*/actions/postprocessor/complete) 도 LockWaitTimeout 폭증 — 시스템 전역 이벤트

Error Log#

Datadog Logs

text

BaseService::handlingMessageErrors | Error and message object - {"error":{"response":{"statusCode":504,"body":"<html>\r
<head><title>504 Gateway Time-out</title></head>\r
<body>\r
<center><h1>504 Gateway Time-out</h1></center>\r
<hr><center>nginx</center>\r
</body>\r
</html>\r
","headers":{"date":"Fri, 10 Jul 2026 17:29:16 GMT",...,"server":"nginx"},"request":{"uri":{"host":"api-tesla.cupix.internal","pathname":"/api/v1/captures/732626/meta/mark","path":"/api/v1/captures/732626/meta/mark?fields%5B0%5D=prop&fields%5B1%5D=skat","href":"http://api-tesla.cupix.internal/api/v1/captures/732626/meta/mark?fields%5B0%5D=prop&fields%5B1%5D=skat"},"method":"PUT","headers":{"User-Agent":"cupix-agent","X-CUPIX-AUTH":"session_token:69v5qht7q87u,session_id:11405574","content-length":40}}},"body":{},"statusCode":504,"name":"HttpError"},"sqsMessage":{"MessageId":"8ecd4d46-a491-47e3-b05d-0776ab5a7e0f","Attributes":{"ApproximateReceiveCount":"1"}}}

Impact#

Service: cupixworks-capture-preprocessor-agent
Team: clark-vdc
발생 횟수: 1 (이 fingerprint 기준)
최초 발생: 2026-07-11 02:29 KST
최근 발생: 2026-07-11 02:29 KST
연쇄 영향: 같은 5분 창(17:24–17:29 UTC) 에서 tesla API 가 capture 732626 관련 요청 6건 실패, 이후 다른 리소스(panos, jobs) 로 확산되어 17:32 UTC 까지 약 30+ 건의 LockWaitTimeout 관측

Root Cause Summary#

Agent 는 SQS 메시지 처리의 마지막 단계로 tesla API 에 PUT /api/v1/captures/732626/meta/mark 를 호출해 capture 의 meta JSON 컬럼(prop, skat 키) 을 갱신한다. 그런데 요청 순간 capture 732626 의 row 에 InnoDB row lock 이 걸려있어 MetableController#update_meta_by_key 의 @model.save 가 MySQL default innodb_lock_wait_timeout (50s) 동안 대기 후 ActiveRecord::LockWaitTimeout 을 반환했다. Rails 는 502 로 응답했지만, agent side 는 재시도 없이 계속 밀어붙였고 그 사이 nginx 의 upstream read timeout 이 먼저 만료되어 최종 응답이 504 Gateway Time-out 으로 반환된 것이 이 클러스터의 직접 원인이다.

락 소유자는 이 로그만으로는 특정되지 않지만 (①같은 창에 다른 endpoint 도 대량으로 LockWaitTimeout, ②captures/732626/publish skipped: error_code(TES10009) exist 로 skat 마스터 로직이 관련 상태 갱신을 시도, ③여러 endpoint 에 걸친 전역 이벤트), 개별 capture 의 row lock 이 아니라 captures 테이블과 관련한 상위 트랜잭션의 장기 점유 또는 DB primary 리소스(커넥션/CPU/replication) 포화가 근본 원인일 가능성이 높다.

Technical Analysis#

Code Path#

Agent side — SQS 메시지 처리 중 API 호출 실패가 handlingMessageErrors 로 흘러 들어온다.

applications/agents/packages/base/src/base-service.ts:107-115typescript

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

applications/agents/packages/base/src/base-service.ts:290-312typescript

private handlingMessageErrors = async (error: any): Promise<void> => {
    const errorAndMessage = {
        error: error,
        sqsMessage: {}
    };
    if (this.messageInProcess) {
        errorAndMessage.sqsMessage = {
            MessageId: this.messageInProcess.MessageId,
            Attributes: this.messageInProcess.Attributes
        };
        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));
    resetLogMeta();
};

Failure point (Rails/API side): PUT /api/v1/captures/:id/meta/*meta_key 라우트가 MetableController#update_meta_by_key 로 매핑되고, 내부에서 @model.save 가 InnoDB row lock 대기 후 LockWaitTimeout 을 뱉는다.

config/routes.rb:317-321ruby

get 'meta', action: :meta
put 'meta', action: :update_meta
get 'meta/*meta_key', action: :show_meta_by_key
put 'meta/*meta_key', action: :update_meta_by_key

app/controllers/concerns/metable_controller.rb:42-69ruby

def update_meta_by_key
  if !@model.updatable_by?(current_user) && (@review.present? && !@review.updatable_by?(current_user))
    raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied')
  end

  begin
    parsed_meta = JSON.parse(request.raw_post)
    @model.meta[params[:meta_key]] = parsed_meta
    @model.skip_entrypoint_flush = true if @model.respond_to?(:skip_entrypoint_flush)
    @model.save                                             # ← 여기서 InnoDB row lock 대기 후 LockWaitTimeout
    # ...
  rescue Cupix::Errors::Parameter => e
    raise Cupix::Errors::Parameter.new(code: 'ARG10004', reason: e.to_s, message: e.message)
  else
    render_json 200, @model.meta[params[:meta_key]]
  end
end

기대 동작: @model.save 가 즉시 커밋되어 200 반환, agent 가 SQS 메시지 삭제. 실제 동작: @model.save 가 innodb_lock_wait_timeout (기본 50s) 동안 lock 대기 후 ActiveRecord::LockWaitTimeout 발생 → Rails 는 502 반환, 6번째 재시도에서는 nginx upstream read timeout 이 먼저 만료되어 504 로 회신.

Log Evidence#

Datadog 쿼리 1 — 원본 에러:

text

service:cupixworks-capture-preprocessor-agent status:error @environment:production "BaseService::handlingMessageErrors"

시간 범위: 1783700940000 – 1783708200000 (2026-07-10T16:29Z – 2026-07-10T18:30Z). 결과: 1건, 2026-07-10T17:29:16.651Z.

Datadog 쿼리 2 — 동일 capture 의 tesla API 로그:

text

service:cupixworks-api ("captures/732626" OR 732626)

시간 범위: 2026-07-10T17:00:00Z – 2026-07-10T17:32:00Z. 결과 12건 중 실패 로그(요약):

text

17:23:11.875Z  [400] PUT /api/v1/captures/732626                       Cupix::Errors::Parameter (Mysql2::Error::TimeoutError)
17:24:08.881Z  [502] PUT /api/v1/captures/732626/meta/mark             ActiveRecord::LockWaitTimeout
17:25:06.964Z  [502] PUT /api/v1/captures/732626/meta/mark             ActiveRecord::LockWaitTimeout
17:26:04.126Z  [502] PUT /api/v1/captures/732626/meta/mark             ActiveRecord::LockWaitTimeout
17:27:01.134Z  [502] PUT /api/v1/captures/732626/meta/mark             ActiveRecord::LockWaitTimeout
17:28:00.278Z  [502] PUT /api/v1/captures/732626/meta/mark             ActiveRecord::LockWaitTimeout
# → 다음 재시도가 nginx upstream timeout 을 초과, 504 로 client 로 전달
17:29:16.651Z  agent 로그: BaseService::handlingMessageErrors ... statusCode:504

각 502 사이 간격이 ~58초로 일정한 점 (innodb_lock_wait_timeout=50s + 약간의 request 오버헤드 + 재시도 지연) 이 락 대기 후 에러 → 즉시 재시도 패턴을 뒷받침한다.

Datadog 쿼리 3 — 시스템 전역 확산:

text

service:cupixworks-api "Lock wait timeout"

시간 범위: 2026-07-10T16:30:00Z – 2026-07-10T18:00:00Z. 결과 227건. 17:29 UTC 이후 LockWaitTimeout 이 여러 리소스로 확산:

text

17:29:02Z  [502] PUT /api/v1/jobs/1188293/actions/postprocessor/complete   LockWaitTimeout
17:29:50Z  [502] PUT /api/v1/jobs/1188283/actions/postprocessor/complete   LockWaitTimeout
17:30:06Z  [502] PUT /api/v1/panos/93012772/check_uploading                LockWaitTimeout
17:30:14Z  [502] PUT /api/v1/panos/93012799/check_uploading                LockWaitTimeout
17:30:20Z  [502] PUT /api/v1/jobs/1188256/actions/postprocessor/running    LockWaitTimeout
17:30:22Z  [502] PUT /api/v1/panos/93012788/check_uploading                LockWaitTimeout
17:31:12Z  [502] PUT /api/v1/jobs/1188256/actions/postprocessor/running    LockWaitTimeout
17:32:36Z  [502] PUT /api/v1/jobs/1188268/actions/postprocessor/complete   LockWaitTimeout

여러 endpoint 에서 동시에 발생하는 것은 개별 row lock 문제가 아니라 DB primary 자체의 리소스 포화 또는 다른 endpoint 와 공유되는 상위 트랜잭션(예: capture ↔ pano ↔ job 을 함께 조인/락하는 배치) 이 원인일 가능성을 시사한다.

Datadog 쿼리 4 — 관련 worker 활동:

text

service:cupixworks-worker 732626

시간 범위: 2026-07-10T16:50:00Z – 2026-07-10T17:32:00Z. 결과 1건:

text

17:25:34.423Z  capture 732626 publish skipped: error_code(TES10009) exist   function:publish_on_finish?

publish_on_finish? 은 skat/preprocessor 결과를 confirm 하는 로직으로 추정되지만, 해당 로그 한 건만으로 락 소유자를 특정할 수는 없다 — 락 소유 트랜잭션은 로그로 확정 불가, 추가 검증 필요.

Sibling cluster 상관관계: cc6978c4-d452-4a79-add1-93bc84e8e0e4 (TransferManager::downloadFile ... code: 504, message: Gateway Time-out) 이 17:10–17:11 UTC 에 2회 발생. 두 클러스터는 status-board 상 같은 서비스 열화 인시던트 (2026-07-10-svc-cupixworks-capture-preprocessor-agent--unknown-1) 로 묶여 있다.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	Agent 가 호출한 tesla API 가 InnoDB row lock 대기 → `LockWaitTimeout` → 재시도 시 nginx upstream read timeout 초과로 504 반환	같은 capture 에 5회 연속 `Mysql2::Error::TimeoutError` 502, 재시도 간격 ~58s 로 `innodb_lock_wait_timeout=50s` 와 일치, 6번째 시도가 504 로 회신 (Datadog 쿼리 2)	—	Confirmed
H2	nginx 자체(리버스 프록시) 장애	응답 헤더에 `server: nginx`, body 가 nginx default 504 페이지	nginx 는 upstream (Rails) 응답이 없어 timeout 을 낸 것뿐, nginx 자체 로그/에러 지표 없음. 직전 502 들이 정상적으로 Rails 에서 응답 → nginx 정상 동작	Rejected
H3	Agent 코드의 SQS 재시도 로직 버그	없음	`handlingMessageErrors` 는 SQS `ApproximateReceiveCount` 기반으로 delete 여부만 결정 (`base-service.ts:290-312`), 504 는 upstream 이슈로 발생한 external error	Rejected
H4	Capture 732626 개별 row 만의 문제 (특정 대용량 meta payload 등)	request `content-length: 40` — payload 는 40 바이트로 소형	같은 창에서 panos/jobs 등 다른 endpoint 에도 `LockWaitTimeout` 확산 (Datadog 쿼리 3)	Rejected
H5	DB primary 리소스 포화 또는 상위 배치 트랜잭션의 장기 점유가 근본 원인	227건 `LockWaitTimeout` 이 여러 endpoint 에 걸쳐 발생, `capture`, `pano`, `job` 리소스 모두 영향	락 소유 트랜잭션을 직접 지목하는 로그(예: 슬로우 쿼리, 특정 worker 의 `SELECT ... FOR UPDATE`) 는 확보 못함	Inconclusive — needs verification

Fix Recommendation#

즉시 조치 (Critical)#

DB 측 조사가 우선: Datadog RDS/MySQL performance dashboard 에서 2026-07-10 17:20–17:35 UTC 창의 (a) innodb_row_lock_time, (b) active transaction count, (c) long-running query, (d) CPU/IO 를 확인하고 락 소유자를 특정한다. 파일 수정 아님, 인프라/DBA 조사 항목.
Agent side 재시도 로직: 502 응답 시 agent 가 즉시 재시도 하지 않도록 backoff 를 확인/도입. 현재 packages/base/src/base-service.ts:113 에 CPUtils.sleep(500) (500ms) 만 있는데, tesla API 로부터의 502/5xx 에 대해서는 exponential backoff + jitter 를 넣는 방향을 검토 (구체 구현은 별도 티켓).

단기 개선 (1주 이내)#

update_meta_by_key 의 트랜잭션 범위 축소: app/controllers/concerns/metable_controller.rb:42-69 의 @model.save 는 단일 record 업데이트지만, Capture 모델의 after_save 콜백/observer 가 다른 테이블에 확장되어 락을 넓게 잡을 가능성이 있다. Capture 모델의 저장 콜백 체인 감사 (bundle exec rails runner "puts Capture._save_callbacks.map(&:filter)" 등) 필요.
innodb_lock_wait_timeout 조정: 기본 50s 는 nginx upstream read timeout 과 겹쳐 502 가 504 로 승격되는 원인이 된다. Rails 측 lock wait 값을 nginx timeout 보다 짧게(예: 5–10s) 낮추고 애플리케이션에서 명시적으로 재시도하도록 하는 방안 검토.
Agent 재시도 backoff: HTTP 5xx 계열에 대해 클라이언트에서 exponential backoff (1s → 2s → 4s ...) + max attempts 로 설정하여, 동일 락에 반복적으로 재시도해 rescue 트래픽을 만드는 것을 방지.

장기 개선 (재발 방지)#

captures.meta JSON 컬럼의 hot-row 문제 해결: 같은 row 에 다수의 subsystem (skat, prop, thumbnail 등) 이 write 하면 자연스럽게 경합. 필드별 별도 테이블 또는 문서형 저장소 이관, 혹은 optimistic concurrency + merge 전략 도입.
svc:cupixworks-capture-preprocessor-agent::unknown 인시던트의 root_cause_type 확정: 현재 status-board 에서 unknown 으로 열려 있음. RCA 확정 후 db_lock_contention 또는 유사 태그로 재분류하여 다음 발생 시 즉시 상관 관계 파악.
DB primary write throughput 스케일 검토: 락 확산 규모(다수 endpoint × 30+ 이벤트) 로 미루어 write path 스케일링 또는 read replica 활용 확장, 배치 write 병합 등 아키텍처 레벨 검토.

Monitoring#

알림: service:cupixworks-api "Lock wait timeout" 이 5분에 10건 이상 발생 시 page.
알림: service:cupixworks-capture-preprocessor-agent status:error @environment:production "BaseService::handlingMessageErrors" 이 5분에 3건 이상.

Datadog release dashboard timeseries widget 용 쿼리:

text

logs("service:cupixworks-api \"Lock wait timeout\" env:production").index("*").rollup("count").by("resource_name")

text

logs("service:cupixworks-capture-preprocessor-agent status:error @environment:production \"BaseService::handlingMessageErrors\"").index("*").rollup("count")

text

logs("service:cupixworks-api status:info \"@error.class:ActiveRecord::LockWaitTimeout\" env:production").index("*").rollup("count")

Metric 관련:

text

avg:mysql.innodb.row_lock_waits{env:production}.as_rate()

text

avg:mysql.innodb.row_lock_time{env:production}

Risk Assessment#

Risk level: medium — 단발 이벤트지만, 근본 원인이 개별 코드 버그가 아니라 DB 락 경합/캐패시티 이슈로 보이며 227건 규모 로 다수 endpoint 에 영향. 재발 시 SLA 위험.
예상 복잡도: standard — agent 재시도 backoff / innodb_lock_wait_timeout 조정은 소규모 변경. hot-row 재설계는 별도 트랙.