Race condition and stale data in #unsubscribe

[mattmacleod]

Related to #305 and #323 – I see unusual behaviour in #unsubscribe when two messages are published in quick succession.

This can be reproduced using @sixfeetover's example script:

# supervisor.rb
require 'redis'

class Supervisor

  def initialize
    @redis = Redis.new
    @redis.set 'foo', 'bar'
    puts "Gem Version: #{Redis::VERSION}"
    puts "Redis Version: #{@redis.info['redis_version']}"
    puts "Foo: #{@redis.get('foo')}"
  end

  def wait_for_workers
    @redis.subscribe('my-channel') do |on|
      on.message do |channel, message|
        puts "Got message: #{message}"
        if message == 'stop'
          @redis.unsubscribe 'my-channel'
        end
      end
    end
  end

  def run_test
    wait_for_workers
    puts "Foo should be bar, and its value is: #{@redis.get('foo').inspect}"
    puts @redis.echo "anything at all"
  end
end

s = Supervisor.new
s.run_test

Subsequently, issuing two closely-spaced PUBLISH commands from Redis causes incorrect data to be returned for subsequent reads. For example, using Ruby:

→ ruby -e 'require "redis"; redis = Redis.new; 2.times { redis.publish("my-channel", :stop) }'

Results in the following output:

Gem Version: 3.2.1
Redis Version: 3.0.0
Foo: bar
Got message: stop
Got message: stop
Foo should be bar, and its value is: ["unsubscribe", "my-channel", 0]
bar

As expected, this is caused by multiple UNSUBSCRIBE commands being issued to Redis, as per this monitor output from the above command:

1434657665.424394 [0 127.0.0.1:55255] "info"
1434657665.424923 [0 127.0.0.1:55255] "get" "foo"
1434657665.425147 [0 127.0.0.1:55255] "subscribe" "my-channel"
1434657667.272459 [0 127.0.0.1:55256] "publish" "my-channel" "stop"
1434657667.272732 [0 127.0.0.1:55256] "publish" "my-channel" "stop"
1434657667.272759 [0 127.0.0.1:55255] "unsubscribe" "my-channel"
1434657667.272987 [0 127.0.0.1:55255] "unsubscribe" "my-channel"
1434657667.273114 [0 127.0.0.1:55255] "get" "foo"
1434657667.273282 [0 127.0.0.1:55255] "echo" "anything at all"

This appears to be caused by the pattern of calling #unsubscribe from within the message callback – however, it doesn't seem correct that a client can call #unsubscribe again after already being successfully unsubscribed!

I'd expect this to be handled by the check at https://github.com/redis/redis-rb/blob/master/lib/redis.rb#L2042, but I think there's a race condition somewhere in SubscribedClient#subscription – I just haven't been able to figure out exactly what's happening yet.

I'll keep investigating, but wanted to raise the issue just now in case there's something obvious I might be missing!