RCA: ConnectionPool::TimeoutError: Waited 5 sec, 0/5 available

Overview#

What Happened#

cupixworks-api (tesla Rails/Puma web process) 에서 Sidekiq client 의 Redis connection pool 이 소진되어 ConnectionPool::TimeoutError: Waited 5 sec, 0/5 available 가 발생했다. Error Tracking 기준 2025-06-16 최초 발생 후 2026-07-18 까지 13개월간 7599건이 누적된 만성 저빈도 조건이다. 풀 크기 5, checkout timeout 5초로, Redis 지연이 튀는 순간 Puma 스레드가 5초를 대기하다 예외를 던지는 패턴이다.

Quick Facts#

Affected Teams#

영향은 개별 HTTP 요청 단위이며, 풀 소진이 해소되면 자동 복구된다.

Timeline#

1. 2025-06-16 23:21 KST — Error Tracking 최초 발생 (first_seen, representative sample).
2. 2026-07-18 21:57 KST — 최근 발생 (last_seen). 이후 14일 retention 창 밖.
3. 2026-08-04 (RCA) — 코드 분석 완료. Datadog 로그는 retention 창(now-14d) 내 매칭 0건.

Error Log#

Datadog Logs

Waited 5 sec, 0/5 available

Impact#

• Service: cupixworks-api
• 발생 횟수: 7599
• 최초 발생: 2025-06-16 23:21 KST
• 최근 발생: 2026-07-18 21:57 KST

Root Cause Summary#

config/initializers/sidekiq.rb 의 Sidekiq.configure_client 블록이 config.redis 에 url 만 지정하고 size(pool 크기) 와 pool_timeout 을 지정하지 않는다. Sidekiq 7.x 는 client redis pool 크기를 명시하지 않으면 Sidekiq.default_configuration[:concurrency] 값으로 만드는데, web(Puma) 프로세스에서는 이 값이 기본 5다. 따라서 job 을 enqueue 하는 웹 프로세스의 Sidekiq client Redis pool 은 크기 5, connection_pool 의 기본 checkout timeout 은 5초다. Redis(ElastiCache) 지연이 튀거나 한 요청이 여러 perform_async 를 연달아 호출하면 5개 연결이 모두 점유되고, 대기 스레드는 5초 뒤 ConnectionPool::TimeoutError: Waited 5 sec, 0/5 available 를 던진다. 메시지의 0/5 available 는 pool 크기 5를, Waited 5 sec 는 5초 checkout timeout 을 그대로 반영한다.

Technical Analysis#

Code Path#

• Entry point: 웹 요청이 perform_async 로 job 을 enqueue → Sidekiq client 가 Redis pool 에서 연결 checkout.
• Client pool 설정: config/initializers/sidekiq.rb:66-68.

Sidekiq.configure_client do |config|
  config.redis = { url: "redis://#{ENV['ELASTICACHE_ADDRESS'] || 'localhost'}:6379" }
end

size 와 pool_timeout 이 없으므로 Sidekiq 7.x 는 client pool 을 크기 default_configuration[:concurrency](웹 프로세스 기본값 5), timeout 5초로 생성한다.

• Puma 스레드 수도 동일하게 5로 설정되어 있다.

max_threads_count = ENV.fetch('RAILS_MAX_THREADS', 5)
min_threads_count = ENV.fetch('RAILS_MIN_THREADS', max_threads_count)
threads min_threads_count, max_threads_count

• Failure point: connection_pool 이 5초 안에 연결을 확보하지 못하면 ConnectionPool::TimeoutError 를 raise.

기대 동작: enqueue 시 Redis 연결을 즉시 확보하고 job 을 push. 실제 동작: Redis latency 스파이크로 연결 반납이 지연되고, Puma 5스레드가 동시에 enqueue(또는 한 요청이 다수 perform_async 를 loop) 하면 pool(5) 이 소진되어 대기 스레드가 5초 후 실패.

• 참고: Rails.cache 의 Redis pool 은 별도로 크기 40이 명시되어 있어(lib/active_support/cache/cupix_cache_store.rb:13) 이 에러와 무관하다. 0/5 available 는 cache pool(40) 이 아니라 Sidekiq client pool(5) 임을 특정하는 결정적 단서다.

super(
  url: options.delete(:url),
  expires_in: options.delete(:expires_in) || 2.hours,
  pool: { size: options.delete(:pool_size) || 40, timeout: 5 }
)

Log Evidence#

Datadog 로그(error/warn/info, 14일 retention)를 다음 쿼리로 검색했으나 매칭이 없다. last_seen(2026-07-18)이 retention 창 밖이라 현재 메시지를 로그로 재검증할 수 없다.

service:cupixworks-api "ConnectionPool::TimeoutError"

service:cupixworks-api "Waited 5 sec"

"0/5 available"

service:cupixworks-worker "ConnectionPool"

세 쿼리 모두 now-14d to now 범위에서 Found 0 logs. 이는 이 이슈가 Error Tracking 에만 존재하고(메시지·스택 그룹핑), 최근 14일 내 신규 발생이 없거나 error-level 로그로 남지 않았음을 의미한다. Representative Error 는 first_seen 샘플로 stale 하지만, 메시지 형태(Waited N sec, X/Y available)는 connection_pool gem 이 고정 포맷으로 생성하므로 root cause 특정에는 충분하다.

• Gemfile.lock 확인: sidekiq (7.3.9), connection_pool (2.5.0), redis (4.8.1), redis-client (0.24.0).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• config/initializers/sidekiq.rb:66-68 의 Sidekiq.configure_client 에 client Redis pool 크기와 checkout timeout 을 명시한다. 웹 프로세스의 job enqueue 동시성(Puma RAILS_MAX_THREADS)과 요청당 perform_async 호출 수를 고려해 pool 크기를 Puma 스레드 수 이상으로 잡고, 대기 timeout 도 늘린다. 방향만 제시하며 구체 수치는 실측 동시성 기반으로 결정한다.

 Sidekiq.configure_client do |config|-  config.redis = { url: "redis://#{ENV['ELASTICACHE_ADDRESS'] || 'localhost'}:6379" }+  config.redis = {+    url: "redis://#{ENV['ELASTICACHE_ADDRESS'] || 'localhost'}:6379",+    size: ENV.fetch('SIDEKIQ_CLIENT_POOL_SIZE', 10).to_i,+    pool_timeout: 5+  } end

• Puma 스레드 수를 RAILS_MAX_THREADS 로 상향한 배포가 있다면 client pool 크기도 함께 상향해 정합을 맞춘다. pool < 스레드 수 조건에서 이 에러가 구조적으로 재발한다.

단기 개선 (1주 이내)#

• 한 요청에서 다수 job 을 loop 로 perform_async 하는 경로가 있는지 점검한다. 있다면 push_bulk(Sidekiq batch enqueue)로 연결 점유 시간을 줄인다.
• 이 에러를 error-level 로 남겨 Datadog 로그로 추적 가능하게 하고, 재발 시 last_seen 기준 로그 검증이 가능하도록 한다(현재는 Error Tracking 에만 존재).

장기 개선 (재발 방지)#

• ElastiCache(Redis) latency 를 상시 모니터링하고 스파이크와 이 예외 발생을 상관 분석한다. Redis 지연이 근본 트리거이면 노드 스펙/네트워크 측면의 개선이 필요하다.
• Sidekiq client pool 크기를 Puma 스레드 수에 자동 연동하는 설정 규약을 문서화해, 스레드 수 변경 시 pool 미조정으로 인한 회귀를 막는다.

Monitoring#

Sidekiq/Redis pool 소진 및 관련 웹 프로세스 예외 추이:

service:cupixworks-api "ConnectionPool::TimeoutError"

Redis(ElastiCache) 연결 대기·지연 상관 확인용 웹 프로세스 에러 전반:

service:cupixworks-api status:error

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard

Noise Verdict#

bug — Sidekiq client Redis pool 크기(5)가 명시되지 않아 Puma 스레드 수와 정합이 맞지 않는 설정 결함으로, config/initializers/sidekiq.rb 에 size/pool_timeout 을 명시하는 코드 수정으로 해소 가능한 진짜 버그다.