flipper: Problems with version 0.22.0 - Rack::Timeout::RequestTimeoutException + ThreadError

Hey guys,

Recently we changed our Flipper version from 0.13.0 to 0.22.0 and we started to see a lot of Rack::Timeout::RequestTimeoutException and ThreadError in our application. I’m not sure yet but those problems seem to be related to an increase in the number of times we hit the cache to write/read data.

We noticed during a debug session that when I request a FF for the first time Flipper writes all of them in our cache including the keys flipper/v1/features and flipper/v1/get_all then when I try to request another FF (present in our cache), the debug logs prints like:

$ DEBUG -- : Cache write: flipper/v1/get_all ({:expires_in=>5 minutes, :unless_exist=>true})
$ DEBUG -- : Cache read: flipper/v1/features ({:expires_in=>5 minutes})
$ DEBUG -- : Cache fetch_hit: flipper/v1/features ({:expires_in=>5 minutes})
$ DEBUG -- : Cache read_multi: [ ALL MY FF's HERE ]
$ DEBUG -- : Cache read: flipper/v1/features ({:expires_in=>5 minutes})
$ DEBUG -- : Cache fetch_hit: flipper/v1/features ({:expires_in=>5 minutes})
$ DEBUG -- : Cache read: flipper/v1/feature/<my FF here> ({:expires_in=>5 minutes})
$ DEBUG -- : Cache fetch_hit: flipper/v1/feature/<my FF here> ({:expires_in=>5 minutes})
$ DEBUG -- : Cache read: flipper/v1/feature/<my FF here> ({:expires_in=>5 minutes})
$ DEBUG -- : Cache fetch_hit: flipper/v1/feature/<my FF here> ({:expires_in=>5 minutes})

Notes:

1. The FF I’m requesting is already written in the cache
2. It seems to request everything again, write again
3. Notice that the last read and fetch_hit lines repeat for the same FF

Metrics

This is a metric from the Memcache instance that illustrates what happened when the new version was delivered in production. It’s an average of “Set” command in 5 minutes.

The same pattern repeats for the “Get” command.

One other interesting thing to notice is the pattern once more when looking at the occurrences of Cache * operations in our log files.

My environment

# Gemfile

ruby '~> 2.5.1'

gem 'puma', '~> 3.7.0'
gem 'rails', '5.2.3'
gem 'rack', '2.1.3'

# application/config/initializers/flipper.rb

# frozen_string_literal: true

require 'flipper'
require 'flipper/adapters/active_record'
require 'flipper/adapters/active_support_cache_store'

class CustomFlipperCacheStore < Flipper::Adapters::ActiveSupportCacheStore
  def get(feature)
    # Allow % of actors to be used without cache
    return @adapter.get(feature) if feature.key.end_with?('_some_pattern')

    super
  end
end

Flipper.configure do |config|
  config.adapter do
    CustomFlipperCacheStore.new(
      Flipper::Adapters::ActiveRecord.new,
      Rails.cache,
      expires_in: 5.minutes
    )
  end
end

Logs

Rack::Timeout::RequestTimeoutException: Request ran for longer than 60000ms

  from flipper/adapters/active_support_cache_store.rb:136:in `read_many_features'
  from flipper/adapters/active_support_cache_store.rb:91:in `get_all'
  from flipper/adapters/memoizable.rb:108:in `get_all'
  from flipper/dsl.rb:200:in `preload_all'
  from flipper/middleware/memoizer.rb:73:in `memoized_call'
  from flipper/middleware/memoizer.rb:42:in `call'

ThreadError: deadlock; recursive locking

from flipper/adapters/active_support_cache_store.rb:129:in `read_feature_keys'
from flipper/adapters/active_support_cache_store.rb:90:in `get_all'
from flipper/adapters/memoizable.rb:108:in `get_all'
from flipper/dsl.rb:200:in `preload_all'
from flipper/middleware/memoizer.rb:73:in `memoized_call'
from flipper/middleware/memoizer.rb:42:in `call'

I’m looking for any insight that could help us to work around this problem. 😃 Thanks