Broken Pipe and EOFErrors

[leequarella]

We recently switched from Sidekiq 6.5.8 to 7.1 (where there was a change to use redis-client) and have noticed a significant increase in errors, all coming from RedisClient. All errors follow one of three forms:

RedisClient::ConnectionError: EOFError
/app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/ruby_connection.rb:101:in `rescue in read': EOFError (RedisClient::ConnectionError)

RedisClient::ConnectionError: Broken pipe
/app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/ruby_connection.rb:88:in `rescue in write_multi': Broken pipe (RedisClient::ConnectionError)

RedisClient::ConnectionError: Broken pipe
/app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/ruby_connection.rb:76:in `rescue in write': Broken pipe (RedisClient::ConnectionError)
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/ruby_connection.rb:73:in `write'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/connection_mixin.rb:30:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client.rb:211:in `block (2 levels) in call'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/middlewares.rb:16:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/contrib/redis/trace_middleware.rb:23:in `block in call'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/trace_operation.rb:192:in `block in measure'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/span_operation.rb:150:in `measure'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/trace_operation.rb:192:in `measure'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/tracer.rb:380:in `start_span'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/tracer.rb:160:in `block in trace'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/context.rb:45:in `activate!'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/tracer.rb:159:in `trace'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing.rb:18:in `trace'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/contrib/redis/trace_middleware.rb:13:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client.rb:210:in `block in call'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client.rb:626:in `ensure_connected'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client.rb:209:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/decorator.rb:26:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-ent-7.1.0/lib/sidekiq-ent/scripting.rb:21:in `block in call'
	from /app/vendor/bundle/ruby/3.2.0/gems/connection_pool-2.4.0/lib/connection_pool.rb:107:in `block (2 levels) in with'
	from /app/vendor/bundle/ruby/3.2.0/gems/connection_pool-2.4.0/lib/connection_pool.rb:106:in `handle_interrupt'
	from /app/vendor/bundle/ruby/3.2.0/gems/connection_pool-2.4.0/lib/connection_pool.rb:106:in `block in with'
	from /app/vendor/bundle/ruby/3.2.0/gems/connection_pool-2.4.0/lib/connection_pool.rb:103:in `handle_interrupt'
	from /app/vendor/bundle/ruby/3.2.0/gems/connection_pool-2.4.0/lib/connection_pool.rb:103:in `with'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-ent-7.1.0/lib/sidekiq-ent/scripting.rb:20:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-ent-7.1.0/lib/sidekiq-ent/senate.rb:148:in `update_leader'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-ent-7.1.0/lib/sidekiq-ent/senate.rb:124:in `election'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-ent-7.1.0/lib/sidekiq-ent/senate.rb:103:in `cycle'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.1.0/lib/sidekiq/component.rb:10:in `watchdog'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.1.0/lib/sidekiq/component.rb:19:in `block in safe_thread'
/app/vendor/ruby-3.2.1/lib/ruby/3.2.0/openssl/buffering.rb:415:in `syswrite_nonblock': Broken pipe (Errno::EPIPE)
	from /app/vendor/ruby-3.2.1/lib/ruby/3.2.0/openssl/buffering.rb:415:in `write_nonblock'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/ruby_connection/buffered_io.rb:64:in `block in write'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/ruby_connection/buffered_io.rb:63:in `loop'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/ruby_connection/buffered_io.rb:63:in `write'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/ruby_connection.rb:74:in `write'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/connection_mixin.rb:30:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client.rb:211:in `block (2 levels) in call'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/middlewares.rb:16:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/contrib/redis/trace_middleware.rb:23:in `block in call'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/trace_operation.rb:192:in `block in measure'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/span_operation.rb:150:in `measure'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/trace_operation.rb:192:in `measure'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/tracer.rb:380:in `start_span'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/tracer.rb:160:in `block in trace'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/context.rb:45:in `activate!'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/tracer.rb:159:in `trace'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing.rb:18:in `trace'
	from /app/vendor/bundle/ruby/3.2.0/gems/ddtrace-1.11.1/lib/datadog/tracing/contrib/redis/trace_middleware.rb:13:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client.rb:210:in `block in call'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client.rb:626:in `ensure_connected'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client.rb:209:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/redis-client-0.14.1/lib/redis_client/decorator.rb:26:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-ent-7.1.0/lib/sidekiq-ent/scripting.rb:21:in `block in call'
	from /app/vendor/bundle/ruby/3.2.0/gems/connection_pool-2.4.0/lib/connection_pool.rb:107:in `block (2 levels) in with'
	from /app/vendor/bundle/ruby/3.2.0/gems/connection_pool-2.4.0/lib/connection_pool.rb:106:in `handle_interrupt'
	from /app/vendor/bundle/ruby/3.2.0/gems/connection_pool-2.4.0/lib/connection_pool.rb:106:in `block in with'
	from /app/vendor/bundle/ruby/3.2.0/gems/connection_pool-2.4.0/lib/connection_pool.rb:103:in `handle_interrupt'
	from /app/vendor/bundle/ruby/3.2.0/gems/connection_pool-2.4.0/lib/connection_pool.rb:103:in `with'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-ent-7.1.0/lib/sidekiq-ent/scripting.rb:20:in `call'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-ent-7.1.0/lib/sidekiq-ent/senate.rb:148:in `update_leader'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-ent-7.1.0/lib/sidekiq-ent/senate.rb:124:in `election'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-ent-7.1.0/lib/sidekiq-ent/senate.rb:103:in `cycle'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.1.0/lib/sidekiq/component.rb:10:in `watchdog'
	from /app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.1.0/lib/sidekiq/component.rb:19:in `block in safe_thread'

#116 seemed possibly related, but it looks like Sidekiq already defaults to having reconnect_attempts set to 1 so maybe a dead end there.

I've struggled to figure out what the actual cause is. Any ideas what direction to head on this?

[byroot]

Yes, AFAIK, sidekiq does set reconnect_attempts: 1. But perhaps it's depends how you configure it?

Also I don't have the code to sidekiq-ent handy, but perhaps it's a problem similar to sidekiq/sidekiq#5834. I'll have a look tomorrow to see if I can see something fishy.

FYI @mperham

[byroot]

Question, is the vast majority coming from watchdog / senate.rb, or is it all over the place?

[leequarella]

Question, is the vast majority coming from watchdog / senate.rb, or is it all over the place?

Seems to be all over the place.

[casperisfine]

Ok, so I had a look but couldn't spot anything wrong. Sidekiq 7.x does default to reconnect_attempts: 1 with no delay, which match redis-rb 4.x behavior.

I really fail to see what could have made the difference on your setup. Is the Sidekiq upgrade the only thing you shipped?

Any ideas what direction to head on this?

I'd say the very first step would be to double check reconnects do happen on your setup. I'd suggest forking the gem to add some logs here:

redis-client/lib/redis_client.rb

Lines 642 to 644 in ae29d65

	if !@disable_reconnection && config.retry_connecting?(tries, error)
	tries += 1
	retry

I suspect it's fine, but you never know.

Then I assume you use some third party Redis provider? It's possible that they're failing over of things like that. Any pattern on the errors? Is it a constant stream or is there some spikes?

If so, you may need to try exponential backoff retries: https://github.com/redis-rb/redis-client#exponential-backoff

[imarquezc]

Any updates on this issue? I'm experiencing the same after upgrading to sidekiq to 7.1.2 (which relies in redis-client 0.14.1).

I'm deploying on Heroku-22
Rails version: 7.0.6 (also happened on 6.1.7.3)

❯ heroku redis:info 
=== redis-cubic-41951 (REDIS_URL)
Plan:                   Premium 0
Status:                 available
Created:                2022-03-07 16:17 
Version:                6.2.12
Timeout:                300
Maxmemory:              noeviction
Maintenance:            not required
Maintenance window:     Mondays 19:00 to 23:00 UTC
Persistence:            AOF
HA Status:              Available
Requires TLS:           Yes
Keyspace Notifications: Disabled

[byroot]

I wonder if this could have been solved by #126.

But that does require a forking setup in which redis-client is used before fork, which isn't super common. I think sidekiq enterprise does support that? Have you have feature enabled?

[brianclin]

I've also been getting a lot of RedisClient::ConnectionError: Broken pipe errors.
It seems to have happened after I enabled TLS on Redis.
I'm using sidekiq 7.1 and redis 6.X on GCP.

RedisClient::ConnectionError: Broken pipe
/usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/ruby_connection.rb:76:in `rescue in write': Broken pipe (RedisClient::ConnectionError)
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/ruby_connection.rb:73:in `write'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/connection_mixin.rb:30:in `call'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client.rb:224:in `block (2 levels) in call'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/middlewares.rb:16:in `call'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/contrib/redis/trace_middleware.rb:23:in `block in call'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/trace_operation.rb:191:in `block in measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/span_operation.rb:149:in `measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/trace_operation.rb:191:in `measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:379:in `start_span'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:159:in `block in trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/context.rb:45:in `activate!'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:158:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing.rb:18:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/contrib/redis/trace_middleware.rb:13:in `call'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client.rb:223:in `block in call'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client.rb:643:in `ensure_connected'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client.rb:222:in `call'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/decorator.rb:26:in `call'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:57:in `zpopbyscore'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:38:in `block (2 levels) in enqueue_jobs'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:33:in `each'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:33:in `block in enqueue_jobs'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/config.rb:164:in `block in redis'
	from /usr/local/bundle/gems/connection_pool-2.4.1/lib/connection_pool.rb:110:in `block (2 levels) in with'
	from /usr/local/bundle/gems/connection_pool-2.4.1/lib/connection_pool.rb:109:in `handle_interrupt'
	from /usr/local/bundle/gems/connection_pool-2.4.1/lib/connection_pool.rb:109:in `block in with'
	from /usr/local/bundle/gems/connection_pool-2.4.1/lib/connection_pool.rb:106:in `handle_interrupt'
	from /usr/local/bundle/gems/connection_pool-2.4.1/lib/connection_pool.rb:106:in `with'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/config.rb:161:in `redis'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/component.rb:28:in `redis'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:32:in `enqueue_jobs'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:107:in `enqueue'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/contrib/sidekiq/server_internal_tracer/scheduled_poller.rb:27:in `block in enqueue'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/trace_operation.rb:191:in `block in measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/span_operation.rb:149:in `measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/trace_operation.rb:191:in `measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:379:in `start_span'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:159:in `block in trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/context.rb:45:in `activate!'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:158:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing.rb:18:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/contrib/sidekiq/server_internal_tracer/scheduled_poller.rb:14:in `enqueue'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:99:in `block in start'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/component.rb:10:in `watchdog'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/component.rb:19:in `block in safe_thread'
/usr/local/lib/ruby/3.2.0/openssl/buffering.rb:415:in `syswrite_nonblock': Broken pipe (Errno::EPIPE)
	from /usr/local/lib/ruby/3.2.0/openssl/buffering.rb:415:in `write_nonblock'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/ruby_connection/buffered_io.rb:64:in `block in write'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/ruby_connection/buffered_io.rb:63:in `loop'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/ruby_connection/buffered_io.rb:63:in `write'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/ruby_connection.rb:74:in `write'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/connection_mixin.rb:30:in `call'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client.rb:224:in `block (2 levels) in call'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/middlewares.rb:16:in `call'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/contrib/redis/trace_middleware.rb:23:in `block in call'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/trace_operation.rb:191:in `block in measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/span_operation.rb:149:in `measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/trace_operation.rb:191:in `measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:379:in `start_span'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:159:in `block in trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/context.rb:45:in `activate!'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:158:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing.rb:18:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/contrib/redis/trace_middleware.rb:13:in `call'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client.rb:223:in `block in call'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client.rb:643:in `ensure_connected'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client.rb:222:in `call'
	from /usr/local/bundle/gems/redis-client-0.17.0/lib/redis_client/decorator.rb:26:in `call'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:57:in `zpopbyscore'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:38:in `block (2 levels) in enqueue_jobs'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:33:in `each'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:33:in `block in enqueue_jobs'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/config.rb:164:in `block in redis'
	from /usr/local/bundle/gems/connection_pool-2.4.1/lib/connection_pool.rb:110:in `block (2 levels) in with'
	from /usr/local/bundle/gems/connection_pool-2.4.1/lib/connection_pool.rb:109:in `handle_interrupt'
	from /usr/local/bundle/gems/connection_pool-2.4.1/lib/connection_pool.rb:109:in `block in with'
	from /usr/local/bundle/gems/connection_pool-2.4.1/lib/connection_pool.rb:106:in `handle_interrupt'
	from /usr/local/bundle/gems/connection_pool-2.4.1/lib/connection_pool.rb:106:in `with'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/config.rb:161:in `redis'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/component.rb:28:in `redis'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:32:in `enqueue_jobs'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:107:in `enqueue'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/contrib/sidekiq/server_internal_tracer/scheduled_poller.rb:27:in `block in enqueue'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/trace_operation.rb:191:in `block in measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/span_operation.rb:149:in `measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/trace_operation.rb:191:in `measure'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:379:in `start_span'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:159:in `block in trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/context.rb:45:in `activate!'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/tracer.rb:158:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing.rb:18:in `trace'
	from /usr/local/bundle/gems/ddtrace-1.12.1/lib/datadog/tracing/contrib/sidekiq/server_internal_tracer/scheduled_poller.rb:14:in `enqueue'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/scheduled.rb:99:in `block in start'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/component.rb:10:in `watchdog'
	from /usr/local/bundle/gems/sidekiq-7.1.3/lib/sidekiq/component.rb:19:in `block in safe_thread'

[slai11]

I'm seeing a similar behaviour too (both EOFError and Broken pipe). I'm using sidekiq 7.1.6, redis-client 0.18.0 and redis 6.X (auth enabled).

More info in https://gitlab.com/gitlab-com/gl-infra/production/-/issues/17158#note_1659816466.

We are fairly confident the upgrade caused the incident but unsure of exactly why. We did a roll-back of the release containing the sidekiq 7 upgrade and the problem (redis errors + sidekiq apdex issues) went away. We subsequently re-deployed the release but this time without the sidekiq 7 upgrade commit and the metrics were all fine.

[casperisfine]

@slai11 I'd love to get to the bottom of that issue, but without experiencing it myself, it's pretty much impossible.

But if you figure out a repro, please share I'll be happy to squash that bug.

[CaioIcy]

We've been seeing the same issue: Redis 6.X with TLS, redis-client 0.18, connection_pool 2.4.1

It happens to all our Redis connections, including caching & Sidekiq. I've tried messing with reconnect_attempts and timeout but this did not seem to help. Also, it seems to correlate with fetching larger data when it is the Rails.cache

I've tried to reproduce it but so far no luck. This comment seems the closest I could find to an explanation, so maybe it could help to link it here: mperham/connection_pool#177 (comment).

[davidgm0]

I believe we're also getting the same here with redis-client 0.18.0 and connection_pool 2.4.1. We're also using TLS. It's only happening with a job that uses activejob-uniqueness and redlock though:

Redlock::LockAcquisitionError: failed to acquire lock on 'Too many Redis errors prevented lock acquisition:
RedisClient::ConnectionError: Broken pipe'
/usr/local/bundle/gems/redlock-2.0.6/lib/redlock/client.rb:323:in `lock_instances'
/usr/local/bundle/gems/redlock-2.0.6/lib/redlock/client.rb:275:in `block in try_lock_instances'
/usr/local/bundle/gems/redlock-2.0.6/lib/redlock/client.rb:271:in `times'
/usr/local/bundle/gems/redlock-2.0.6/lib/redlock/client.rb:271:in `try_lock_instances'
/usr/local/bundle/gems/redlock-2.0.6/lib/redlock/client.rb:79:in `lock'
/usr/local/bundle/gems/activejob-uniqueness-0.3.1/lib/active_job/uniqueness/strategies/base.rb:24:in `lock'

[le0pard]

sidekiq/sidekiq#5929 (comment) - provided more info about case.

So basically it happening with no load on sidekiq daemon and some threads get timeout error (some, not all of them in sidekiq). redis.rb had no such issues in previous sidekiq <= 6

[stanhu]

I'm not sure yet if I reproduced this specific issue, but today I set up a Google Cloud Memorystore instance with Redis 6.2.13 and TLS enabled. Then I ran:

require 'redis-client'
redis_config = RedisClient.config(host: 'redacted-redis-hostname', port: 6378, ssl: true, password: 'redacted-password')
redis = redis_config.new_client
redis.call("PING")
=> "PONG"

I waited an hour or so, and sent another PING, but this time I got the EPIPE:

irb(main):015:0> redis.call("PING")
/opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client/ruby_connection.rb:76:in `rescue in write': Broken pipe (RedisClient::ConnectionError)
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client/ruby_connection.rb:73:in `write'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client/connection_mixin.rb:30:in `call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client.rb:256:in `block (2 levels) in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client/middlewares.rb:16:in `call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client.rb:255:in `block in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client.rb:675:in `ensure_connected'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client.rb:254:in `call'
        from (irb):15:in `<main>'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/irb-1.3.5/exe/irb:11:in `<top (required)>'
        from /opt/gitlab/embedded/bin/irb:23:in `load'
        from /opt/gitlab/embedded/bin/irb:23:in `<main>'
/opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/openssl-3.1.0/lib/openssl/buffering.rb:415:in `syswrite_nonblock': Broken pipe (Errno::EPIPE)
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/openssl-3.1.0/lib/openssl/buffering.rb:415:in `write_nonblock'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client/ruby_connection/buffered_io.rb:64:in `block in write'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client/ruby_connection/buffered_io.rb:63:in `loop'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client/ruby_connection/buffered_io.rb:63:in `write'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client/ruby_connection.rb:74:in `write'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client/connection_mixin.rb:30:in `call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client.rb:256:in `block (2 levels) in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client/middlewares.rb:16:in `call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client.rb:255:in `block in call'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client.rb:675:in `ensure_connected'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/redis-client-0.18.0/lib/redis_client.rb:254:in `call'
        from (irb):15:in `<main>'
        from /opt/gitlab/embedded/lib/ruby/gems/3.0.0/gems/irb-1.3.5/exe/irb:11:in `<top (required)>'
        from /opt/gitlab/embedded/bin/irb:23:in `load'
        from /opt/gitlab/embedded/bin/irb:23:in `<main>'

Naturally, I was curious if Google's 10-minute VPC timeout was kicking in, but the issue didn't seem to occur if I attempted a PING after 10 minutes. In addition, I also verified with Wireshark that TCP keepalives appear to be sent and acked every 15 seconds, so it doesn't appear that the TCP connection is going idle.

I also checked that the Redis TIMEOUT config parameter defaults to 0.

I'm not sure why the socket appears to be closing like this, so I'll continue to investigate.