Redis semaphore locks can't be released

Question

I am using the redis-semaphore gem, version 0.3.1.

For some reason, I occasionally can't release a stale Redis lock. From my analysis it seems to happen if my Docker process crashed after the lock was created.

I have described my debugging process below and would like to know if anyone can suggest how to further debug.

Assume that we want to create a redis lock with this name:

name = "test"

We insert this variable in two different terminal windows. In the first, we run:

def lock_for_15_secs(name)
  job = Redis::Semaphore.new(name.to_sym, redis: NonBlockingRedis.new(), custom_blpop: true, :stale_client_timeout => 15)
  if job.lock(-1) == "0"
    puts "Locked and starting"
    sleep(15)
    puts "Now it's stale, try to release in another process"
    sleep(15)
    puts "Now trying to unlock"
    unlock = job.unlock
    puts unlock == false ? "Wuhuu, already unlocked" : "Hm, should have been unlocked by another process, but wasn't"
  end
end
lock_for_15_secs(name)

In the second we run:

def release_and_lock(name)
  job     = Redis::Semaphore.new(name.to_sym, redis: NonBlockingRedis.new(), custom_blpop: true, :stale_client_timeout => 15)
  release = job.release_stale_locks!
  count   = job.available_count
  puts "Release reponse is #{release.inspect} and available count is #{count}"
  if job.lock(-1) == "0"
    puts "Wuhuu, we can lock it"
    job.unlock
  else
    puts "Hmm, we can't lock it"
  end
end
release_and_lock(name)

This usually plays out as expected. For 15 seconds, the second terminal can't relase the lock, but when run after 15 seconds, it releases. Below is the output from release_and_lock(name).

Before 15 seconds have passed:

irb(main):1:0> release_and_lock(name)
Release reponse is {"0"=>"1580292557.321834"} and available count is 0
Hmm, we can't lock it
=> nil

After 15 seconds have passed:

irb(main):2:0> release_and_lock(name)
Release reponse is {"0"=>"1580292557.321834"} and available count is 1
Wuhuu, we can lock it
=> 1
irb(main):3:0> release_and_lock(name)
Release reponse is {} and available count is 1
Wuhuu, we can lock it

But whenever I see that a stale lock isn't released, and I run release_and_lock(name) to diagnose, this is returned:

irb(main):4:0> release_and_lock(name)
Release reponse is {} and available count is 0
Hmm, we can't lock it

And at this point my only option is to flush redis:

require 'non_blocking_redis'
non_blocking_redis = NonBlockingRedis.new()
non_blocking_redis.flushall

P.s. My NonBlockingRedis inherits from Redis:

class Redis
  class Semaphore
    def initialize(name, opts = {})
      @custom_opts          = opts
      @name                 = name
      @resource_count       = opts.delete(:resources) || 1
      @stale_client_timeout = opts.delete(:stale_client_timeout)
      @redis                = opts.delete(:redis) || Redis.new(opts)
      @use_local_time       = opts.delete(:use_local_time)
      @custom_blpop         = opts.delete(:custom_blpop) # false=queue, true=cancel
      @tokens               = []
    end

    def lock(timeout = 0)
      exists_or_create!
      release_stale_locks! if check_staleness?
      token_pair    = @redis.blpop(available_key, timeout, @custom_blpop)
      return false if token_pair.nil?
      current_token = token_pair[1]
      @tokens.push(current_token)
      @redis.hset(grabbed_key, current_token, current_time.to_f)
      if block_given?
        begin
          yield current_token
        ensure
          signal(current_token)
        end
      end
      current_token
    end
    alias_method :wait, :lock
  end
end

class NonBlockingRedis < Redis

  def initialize(options = {})
    if options.empty?
      options = {
        url: Rails.application.secrets.redis_url,
        db:  Rails.application.secrets.redis_sidekiq_db,
        driver: :hiredis,
        network_timeout: 5
      }
    end

    super(options)
  end

  def blpop(key, timeout, custom_blpop)
    if custom_blpop
      if timeout == -1
        result = lpop(key)
        return result if result.nil?
        return [key, result]
      else
        super(key, timeout)
      end
    else
       super
    end
  end

  def lock(timeout = 0)
    exists_or_create!
    release_stale_locks! if check_staleness?
    token_pair = @redis.blpop(available_key, timeout, @custom_blpop)
    return false if token_pair.nil?
    current_token = token_pair[1]
    @tokens.push(current_token)
    @redis.hset(grabbed_key, current_token, current_time.to_f)
    if block_given?
      begin
        yield current_token
      ensure
        signal(current_token)
      end
    end
    current_token
  end
  alias_method :wait, :lock
end

require 'non_blocking_redis'

Answer 1

😜 An awesome bug 👏

The bug

I think it happens if you kill the process when it does lpop on the SEMAPHORE:test:AVAILABLE

Most probably here https://github.com/dv/redis-semaphore/blob/v0.3.1/lib/redis/semaphore.rb#L67

To replicate it

NonBlockingRedis.new.flushall

release_and_lock('test');

NonBlockingRedis.new.lpop('SEMAPHORE:test:AVAILABLE')

Now initially you have:

SEMAPHORE:test:AVAILABLE                0
SEMAPHORE:test:VERSION          1
SEMAPHORE:test:EXISTS           1

After the above code you get:

SEMAPHORE:test:VERSION          1
SEMAPHORE:test:EXISTS           1

The code checks the SEMAPHORE:test:EXISTS and then expects to have SEMAPHORE:test:AVAILABLE / SEMAPHORE:test:GRABBED

Solution

From my brief check I don't think it is possible to make the gem work without a modification. I tried adding an expiration: but somehow it managed to disable the expiration for SEMAPHORE:test:EXISTS

NonBlockingRedis.new.ttl('SEMAPHORE:test:EXISTS') # => -1 and it should have been e.g. 20 seconds and going down

So.. maybe a fix will be

class Redis
  class Semaphore
    def exists_or_create!
      token = @redis.getset(exists_key, EXISTS_TOKEN)

      if token.nil? || all_tokens.empty?
        create!
      else
        # Previous versions of redis-semaphore did not set `version_key`.
        # Make sure it's set now, so we can use it in future versions.

        if token == API_VERSION && @redis.get(version_key).nil?
          @redis.set(version_key, API_VERSION)
        end

        true
      end
    end
  end
end

the all_tokens is https://github.com/dv/redis-semaphore/blob/v0.3.1/lib/redis/semaphore.rb#L120

I'll open a PR to the gem shortly -> https://github.com/dv/redis-semaphore/pull/66 maybe 🤷‍♂️

Note 1

Not sure how you use the NonBlockingRedis but it is not in use in Redis::Semaphore. You do lock(-1) which does in the code lpop. Also the code never calls your lock.

Random

Here is a helper to dump the keys

class Test
  def self.all
    r = NonBlockingRedis.new
    puts r.keys('*').map { |k|
      [
        k,
        ((r.hgetall(k) rescue r.get(k)) rescue r.lrange(k, 0, -1).join(' | '))
      ].join("\t\t")
    }
  end
end

> Test.all

SEMAPHORE:test:AVAILABLE                0
SEMAPHORE:test:VERSION          1
SEMAPHORE:test:EXISTS           1

For completeness here is how it looks when you have grabbed the lock

SEMAPHORE:test:VERSION          1
SEMAPHORE:test:EXISTS           1
SEMAPHORE:test:GRABBED          {"0"=>"1583672948.7168388"}