subscribe_with_timeout taking longer than expected to timeout

[willcosgrove]

subscribe_with_timeout seems to be taking longer than the timeout value specified to raise a timeout error. After playing around with it for a bit, it appears to be waiting read_timeout + timeout where the read_timeout is the read timeout set on the redis client, and timeout is the timeout set in the subscribe_with_timeout call.

I was under the impression that subscribe_with_timeout would effectively replace the read_timeout set for the client, not add to it. Is there a reason why that can't be done, or why it was done this way?

I'm by no means an expert in low level networking libraries, so I could be way off base 😄

[willcosgrove]

Some more detective work:

Running this in a console

r.subscribe_with_timeout(8, "bar") { |on|
  on.subscribe { |*args|
    puts args.inspect
    puts r.client.instance_variable_get("@client")
                 .instance_variable_get("@connection")
                 .instance_variable_get("@sock")
                 .instance_variable_get("@timeout")
  }
}

Gives me this output

["bar", 1]
8
["bar", 1]
5.0
Redis::TimeoutError: Connection timed out
from /Users/will/.gem/ruby/2.4.1/gems/redis-3.3.5/lib/redis/connection/ruby.rb:90:in `rescue in _read_from_socket'

And here is the corresponding monitor output from redis-cli

127.0.0.1:6379> monitor
OK
1524677800.706447 [0 [::1]:63550] "subscribe" "bar"
1524677808.724794 [0 [::1]:63551] "subscribe" "bar"

So two subscriptions are happening, one with the timeout specified by subscribe_with_timeout and one with the default client timeout (which should actually be pulling from read_timeout instead of timeout, which is fixed in #709 but not yet merged)

[willcosgrove]

It looks like this is exactly this issue: #668

I agree with @alexnavis that timeout errors should probably not be considered for the reconnect/retry logic.

[willcosgrove]

If anyone is looking for a non-hacky solution to this, the best I've found is to use the without_reconnect method which takes a block, and all nested redis calls will be executed with no reconnect logic.

redis.without_reconnect do
  redis.subscribe_with_timeout(5, "my_channel") do |on|
    # ...
  end
end

Ideally, I would love to see a fix that prevents timeouts from being considered for retries. Probably by subclassing the BaseConnectionError to a new RetryableConnectionError and then changing the subclasses of BaseConnectionError to RetryableConnectionError where applicable. And finally, only rescuing RetryableConnectionError in Client#ensure_connected.

I would be happy to open a PR that does this. But there are quite a few PRs open already, that have been open for quite some time, so I'm not inclined to believe it will get merged. If activity picks up, and the above seems like a good fix to the maintainers, I'm happy to code it up.

[mad-eel]

@willcosgrove Do you know if it's resolved somewhere? I just had this issue where I've noticed that when calling subscribe_with_timeout with 5 as a timeout, it actually takes 10 seconds to timeout. It's very confusing and incorrect in regards to what README says.

[chuchuva]

Readme provides a way to disable reconnecting:

redis = Redis.new(reconnect_attempts: 0)
redis.subscribe_with_timeout(5, "news") do |on|
  on.message do |channel, message|
    # ...
  end
end

This makes the subscribe_with_timeout method to time out after 5 seconds.

[byroot]

This is solved in 5.0.