RCA: StandardError - Waited 7 sec, 0/10 available

Overview#

What Happened#

2026-07-01 11:47 KST부터 production cupixworks-worker (Sidekiq) 인스턴스에서 Elasticsearch 클라이언트의 ConnectionPool이 고갈되어 Waited 7 sec, 0/10 available 에러가 반복적으로 발생. Feed._index_document, EditingSplitWorker.perform, CreateSitetrackEditingEntitiesWorker.perform 등 다양한 클래스에서 ES 인덱싱이 실패했고 약 3시간 동안 49회 이상 관측됨. 원인은 신규 배포(c527a441)에 포함된 EditingSplitService의 재-split 재귀 스케줄링이 특정 editing들에서 종료 조건을 만족하지 못하고 5초 주기로 EditingSplitWorker를 계속 재-enqueue 하여 ES 커넥션을 소진시킨 것.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-30 15:15 KST — c527a441 배포. EditingSplitService#split! 끝에 "post-split cap" 재확인 로직 및 EditingSplitWorker.perform_in(5.seconds, editing.id) 재-enqueue 추가.
2. 2026-07-01 11:47 KST — 클러스터 77863ae7 최초 발생 (Feed._index_document "Index error - Waited 7 sec, 0/10 available").
3. 2026-07-01 13:11 KST — sibling 클러스터 e15e7ba7 최초 발생 (CreateSitetrackEditingEntitiesWorker on sitetrack_id: 20474 — 하위 EditingSplitWorker 폭주에 휘말림).
4. 2026-07-01 14:27 KST — 본 클러스터 최근 발생 (누적 49회).
5. 2026-07-01 14:29~14:47 KST — Post-split cap still exceeded, scheduling re-split warn 로그가 3개 editing (1178504, 1177289, 1186375)에서 각각 post_split_count 6540/5880/3630으로 5~6초마다 반복 관측 — 재-split 루프 실증.

Error Log#

Datadog Logs

StandardError - Waited 7 sec, 0/10 available

실제 error 로그 예시 (Datadog):

{
  "timestamp": "2026-07-01T05:30:55.710Z",
  "status": "error",
  "class": "Feed",
  "function": "_index_document",
  "message": "Index error - Waited 7 sec, 0/10 available",
  "host": "ip-10-1-18-149.us-west-2.compute.internal",
  "pid": 1511179,
  "version": "production-us-west-2-20260630T0615Z0-c527a441-cupixworks"
}

Impact#

• Service: cupixworks-worker
• 발생 횟수: 49
• 최초 발생: 2026-07-01 11:47 KST
• 최근 발생: 2026-07-01 14:27 KST

Root Cause Summary#

EditingSplitService#split!가 배포 c527a441에서 도입한 "post-split cap" 재확인 로직이, do_split! 호출 후 editing의 element_id distinct count를 다시 세고 MAX_ELEMENTS_PER_EDITING (=1000) 을 여전히 초과하면 EditingSplitWorker.perform_in(5.seconds, editing.id) 로 자신을 재-enqueue 한다. 그러나 3개 editing(1178504, 1177289, 1186375)에서 do_split!이 원본 editing의 element_id 개수를 실제로 낮추지 못하는 상태가 존재하고 (관측된 post_split_count가 6540/5880/3630으로 5초 간격의 여러 회차에서 동일 값 유지), 이로 인해 종료 조건 없이 5초마다 동일 worker가 재-enqueue 된다. 각 재-split은 compute_split_groups 단계에서 ElementTrace 조회·grouping과 여러 ActiveRecord 트랜잭션을 수행하며, 그 안팎에서 elasticsearch-model의 ConnectionPool::Wrapper.new(size: 10, timeout: 7) (config/initializers/elasticsearch.rb:17) 커넥션을 소모한다. 3개 editing × 5초 주기 × Sidekiq concurrency로 인해 ES pool이 지속적으로 10/10 사용 중 상태가 되고, 다른 _index_document / EditingSplitWorker 호출들이 7초 대기 후 ConnectionPool::TimeoutError로 실패한다.

Technical Analysis#

Code Path#

• Entry point (에러가 rescue 되는 곳): app/models/concerns/searchable.rb:34 (Searchable#_index_document)
• Root-cause enqueue loop: app/services/cupix/editing_split_service.rb:104-113 (배포 스냅샷 c527a441)
• Failure point: config/initializers/elasticsearch.rb:17 (ConnectionPool::Wrapper.new(size: 10, timeout: 7)) — 이 pool 이 고갈되면서 .client 호출이 7초 뒤 타임아웃하여 ConnectionPool::TimeoutError("Waited 7 sec, 0/10 available") 발생.

에러가 rescue 되어 로그로 나오는 지점:

    def _index_document
      return if @skip_index_document == true

      indexed_json = __elasticsearch__.as_indexed_json
      base_request = {
        id: __elasticsearch__.id,
        body: indexed_json
      }

      results = __elasticsearch__.client.index(base_request.merge(index: __elasticsearch__.index_name))
      Cupix::Logger.debug(results.to_json, class: self.class.name, function: __method__)

      # NOTE: dual write to tmp_index while reindexing
      if (tmp_index = self.class.fetch_tmp_index_name)
        __elasticsearch__.client.index(base_request.merge(index: tmp_index))
      end
    rescue StandardError => e
      Cupix::Logger.error("Index error - #{e.message}", class: self.class.name, function: __method__)
      BulkIndexWorker.perform_async(self.class.name, [id], 'index')
    end

pool 정의 (10 커넥션, 7초 대기가 정확히 에러 메시지와 일치):

Elasticsearch::Model.client = ConnectionPool::Wrapper.new(size: 10, timeout: 7) {
  Elasticsearch::Client.new(
    host: ENV.fetch('RAILS_ES_HOST') { 'localhost' },
    port: ENV.fetch('RAILS_ES_PORT') { DEFAULT_RAILS_ES_PORT },
    user: ENV['RAILS_ES_USER'],
    password: ENV['RAILS_ES_PASSWORD'],
    transport_options: {
      request: {
        timeout: 10
      }
    }
  ) do |faraday|
    # https://www.elastic.co/guide/en/elasticsearch/client/ruby-api/7.17/transport.html
    if Rails.env.development?
      faraday.response :logger, Logger.new($stdout, level: :info)
    end
  end
}

ConnectionPool을 고갈시키는 재-enqueue 루프 (배포 스냅샷 c527a441):

        result = do_split!

        Cupix::Logger.info('Split finished',
                           class: self.class.name,
                           function: __method__,
                           editing_id: editing.id,
                           result_count: result.is_a?(Array) ? result.size : nil,
                           elapsed_ms: ((Time.current - start_time) * 1000).round)

        editing.reload
        post_count = ::ElementTrace.where(editing_id: editing.id, purpose: PURPOSE_STATUS_UPDATE).distinct.count(:element_id)
        if post_count > MAX_ELEMENTS_PER_EDITING
          Cupix::Logger.warn('Post-split cap still exceeded, scheduling re-split',
                             class: self.class.name,
                             function: __method__,
                             editing_id: editing.id,
                             post_split_count: post_count)
          ::EditingSplitWorker.perform_in(5.seconds, editing.id)
        end

• 기대 동작: do_split!이 editing을 여러 조각으로 나누어 원본 editing의 element_id distinct count가 1000 이하로 떨어져야 하고, 그 결과 post-split 재확인에서 조건 불성립 → 루프 종료.
• 실제 동작: 3개 editing에서 count가 각각 6540/5880/3630으로 고정된 채 변화 없이 5초마다 재-enqueue. 종료 조건이 없어 무한 루프. 이 worker가 항상 실행 중이므로 _index_document 및 하위 ES 호출이 pool 슬롯을 얻지 못해 7초 후 timeout.

splittable?는 동일 임계값(actual_count > MAX_ELEMENTS_PER_EDITING)을 사용하므로 재실행 시에도 true 판정 → 다시 do_split! 진입:

    def splittable?
      unless sqa_geo_grouping_enabled?
        Cupix::Logger.info('Splittable=false (geo_grouping disabled)',
                           class: self.class.name,
                           function: __method__,
                           editing_id: editing.id)
        return false
      end

      unless editing.editing_type == 'siteinsights'
        ...
        return false
      end

      actual_count = ::ElementTrace.where(editing_id: editing.id, purpose: PURPOSE_STATUS_UPDATE).distinct.count(:element_id)
      result = actual_count > MAX_ELEMENTS_PER_EDITING
      ...
      result
    end

즉 do_split!이 원본 editing의 element 수를 줄이지 못하는 조건이 계속 성립하면 재-enqueue와 splittable? 판정이 서로를 만족시키는 상태로 lock-step 진동이 되고, 이 재-enqueue 자체에는 재시도 카운트 상한이나 progress 척도가 없어 자연 종료가 불가능하다.

Log Evidence#

Datadog 쿼리 (본 클러스터):

service:cupixworks-worker status:error @environment:production "StandardError - Waited 7 sec, 0/10 available"

에러 로그의 host / version / pid:

{
  "@timestamp": "2026-07-01T05:30:55.710Z",
  "message": "Index error - Waited 7 sec, 0/10 available",
  "status": "error",
  "class": "Feed",
  "function": "_index_document",
  "host": "ip-10-1-18-149.us-west-2.compute.internal",
  "pid": 1511179,
  "version": "production-us-west-2-20260630T0615Z0-c527a441-cupixworks"
}

동일 시간대 재-split 루프의 warn 로그 (Post-split cap still exceeded, scheduling re-split) Datadog 쿼리:

service:cupixworks-worker @environment:production "Post-split cap"

관측된 로그 순서 (editing_id / post_split_count / 타임스탬프):

editing_id=1178504 post_split_count=6540 @2026-07-01T05:46:36.376Z
editing_id=1178504 post_split_count=6540 @2026-07-01T05:46:48.384Z
editing_id=1178504 post_split_count=6540 @2026-07-01T05:46:54.390Z
editing_id=1178504 post_split_count=6540 @2026-07-01T05:47:08.398Z
editing_id=1178504 post_split_count=6540 @2026-07-01T05:47:16.406Z
editing_id=1178504 post_split_count=6540 @2026-07-01T05:47:22.411Z
editing_id=1177289 post_split_count=5880 @2026-07-01T05:46:30.371Z ... (5~6s 간격 반복)
editing_id=1186375 post_split_count=3630 @2026-07-01T05:46:30.371Z ... (5~6s 간격 반복)

• 세 editing 모두 post_split_count가 여러 회차에 걸쳐 동일 값을 유지 → do_split!이 원본 editing의 element 수를 줄이지 못하는 상태로 재-enqueue 만 반복.
• 재-enqueue 주기(5초)와 pool timeout(7초)이 근접해 pool이 회복될 시간 창이 좁음.

sibling 클러스터 (같은 host, 같은 pool, 같은 원인):

Datadog 쿼리:

service:cupixworks-worker @environment:production "sitetrack_id: 20474"

{
  "timestamp": "2026-07-01T04:11:20Z",
  "status": "info",
  "class": "CreateSitetrackEditingEntitiesWorker",
  "message": "start creating editing entities on sitetrack_id: 20474"
}
{
  "timestamp": "2026-07-01T04:11:28Z",
  "status": "error",
  "class": "CreateSitetrackEditingEntitiesWorker",
  "message": "error on sitetrack_id: 20474 - Waited 7 sec, 0/10 available"
}

상관 관계: CreateSitetrackEditingEntitiesWorker가 완료 후 EditingSplitWorker.perform_async(editing_id)를 enqueue (app/workers/create_sitetrack_editing_entities_worker.rb:82-86) — 이 worker가 폭주하면서 ES pool을 점유. 그 결과 상위 워커도 pool 획득에 실패해 같은 에러로 실패.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 재-enqueue 루프 종료 조건 추가: app/services/cupix/editing_split_service.rb:104-113 (c527a441 스냅샷) 의 EditingSplitWorker.perform_in(5.seconds, editing.id) 재-enqueue 지점에서 다음 중 하나 이상을 필수화한다.
  • 재시도 카운트 상한: EditingSplitWorker.perform 인자 또는 Redis 카운터로 재-split 시도 횟수(예: ≤ 5회)를 추적하고 초과 시 warn/error 로그와 함께 재-enqueue 중단.
  • 진행 여부 확인: 이번 회차 post_split_count가 직전 회차와 동일하면 (즉 실제로 분할이 진행되지 않았다면) 재-enqueue 하지 않고 종료. 값이 감소한 경우에만 계속 재시도.
  • backoff 확대: 5초 고정 대신 exponential backoff(예: 5s → 30s → 120s)로 pool 점유율을 완화. 이는 임시 mitigation으로만 유효하며 위의 종료 조건과 함께 적용해야 함.
• hotfix 배포 전 우회 조치(운영): 문제 editing 3건(1178504, 1177289, 1186375)에 대해 dead letter/파킹 등으로 재-enqueue를 즉시 멈춘다. 실제 데이터 삭제/이동은 편집 팀 확인 후 진행.

단기 개선 (1주 이내)#

• 왜 do_split!이 실효 분할을 못 하는지 조사: do_split! (editing_split_service.rb:142-344)에서 원본 editing의 ElementTrace.editing_id 는 특정 경로(예: final_groups.first 처리 경로 update_editing_stats_by_element_ids / update_editing_stats — 이는 통계만 갱신하고 원본의 ET editing_id를 옮기지 않는 것으로 보임)에서 그대로 남을 수 있다. 이 경우 원본의 distinct count(:element_id)가 줄지 않아 무한 재-split 조건이 성립. 첫 그룹도 새 editing으로 옮기거나 원본을 실효 chunk에 맞게 재정의하는 방향으로 수정.
• 재-enqueue 결정과 실측 진행 로그: Split finished 로그에 post_count_before / post_count_after (또는 이전 회차 대비 delta)를 추가해 다음 회차가 유효한지 판단할 수 있게 한다.
• ES ConnectionPool 사이즈/타임아웃 재검토: 현재 size: 10, timeout: 7 (config/initializers/elasticsearch.rb:17). Sidekiq concurrency 대비 과소 여부를 확인. 다만 근본 해결이 아니므로 첫 두 조치와 병행.

장기 개선 (재발 방지)#

• 모든 self-recurring worker 패턴 감사: perform_in(..., self.arguments) 형태로 재-enqueue 하는 worker에서 (1) 최대 재시도 상한, (2) 진행 척도(progress metric), (3) exponential backoff 세 가지를 표준 checklist로 강제.
• Editing split 상태를 sitetrack pipeline dashboard에 노출: editing_id별 split 회차 수와 element_id count 변화를 시계열로 관측해 루프를 조기 탐지.
• ES 클라이언트 사용 지점의 pool 계측: Elasticsearch::Model.client 호출 지점에 ConnectionPool 활용률 metric을 dogstatsd로 게시 (pool.available, pool.wait_ms).

Monitoring#

• 재-split 루프 감시 (Datadog dashboard timeseries widget):

sum:trace.sidekiq.job.hits{service:cupixworks-worker,resource_name:EditingSplitWorker,env:production}.as_count()

• ES pool timeout 발생율:

sum:logs.hits{service:cupixworks-worker,status:error,env:production,message:"Waited 7 sec"}.as_count()

• Post-split cap warn 발생율 (재-enqueue가 감소해야 함):

sum:logs.hits{service:cupixworks-worker,status:warn,env:production,message:"Post-split cap still exceeded"}.as_count()

• 알림 임계값 제안: Post-split cap warn이 5분간 20회 이상 지속되면 재-split 루프 의심 → PagerDuty warn.

Risk Assessment#

• Risk level: high — 재-enqueue 루프가 종료 조건 없이 pool 을 지속 점유하면 _index_document 실패가 다른 도메인(Feed, Pano, Task 등 Searchable을 포함한 모든 모델)의 ES 색인에 파급된다. 이미 sibling cluster로 CreateSitetrackEditingEntitiesWorker가 실패하고 있어 sitetrack 처리 지연으로 이어질 수 있음.
• 예상 복잡도: standard — 종료 조건(재시도 상한/진행 척도)은 소규모 변경. 다만 "do_split!이 왜 진행되지 않는가" 근본 원인 조사에는 데이터 기반 검토가 필요.