Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Support RedisCacheStore (new in Rails 5.2) #281

Closed
brian-kephart opened this issue Feb 14, 2018 · 22 comments
Closed

Support RedisCacheStore (new in Rails 5.2) #281

brian-kephart opened this issue Feb 14, 2018 · 22 comments

Comments

@brian-kephart
Copy link
Contributor

After upgrading my app to Rails 5.2.0rc1, I'm occasionally getting the following error:
Redis::CommandError: ERR value is not an integer or out of range

Google says this error is caused by not passing the raw option when writing to Redis, then later incrementing the key. This appears to be fixed in this library for other forms of Redis caching, but not for the new ActiveSupport::Cache::RedisCacheStore.

Previous (working) config:
Ruby 2.5.0
Rails 5.1.4
ReadThisStore
Hiredis (driver)

Current (non-working) config:
Ruby 2.5.0
Rails 5.2.0rc1
RedisCacheStore
Hiredis (driver)

@grzuy
Copy link
Collaborator

grzuy commented May 16, 2018

Hi Brian,

I am trying to understand exactly where this issue is coming from.

Can you share what your rack-attack configuration looks like after upgrading to rails 5.2?
And if possible also the stacktrace for the Redis::CommandError: ERR value is not an integer or out of range exception?

Thank you!

@brian-kephart
Copy link
Contributor Author

Unfortunately, I don't have a stack trace handy as my error logger dumps them after 30 days.

Basically, none of the store proxies match an ActiveSupport::RedisCacheStore, so the default read/write/increment methods (from lib/rack/attack/cache.rb) are being used.

The increment command fails on Redis unless the value was written using the raw option. See here.

The RedisStoreProxy class takes care of this option for previous implementations of Redis caching. It doesn't quite work for the ActiveSupport::RedisCacheStore because:

  1. The self.handle? method doesn't return true for the new cache store, and even if it did...
  2. the interface is slightly different.

Probably the best way to understand this is to look at the RedisStoreProxy class and see which methods it redefines compared to the Cache class. These behaviors need to be implemented for ActiveSupport::RedisCacheStore. That is what I did in #340.

I hope that clears it up a bit. Let me know if you have any other questions.

@brian-kephart
Copy link
Contributor Author

Sorry, forgot to include the config:

class Rack::Attack
  if Rails.env.production?
    ### Configure Cache ###

    # If you don't want to use Rails.cache (Rack::Attack's default), then
    # configure it here.
    #
    # Note: The store is only used for throttling (not blacklisting and
    # whitelisting). It must implement .increment and .write like
    # ActiveSupport::Cache::Store

    # Rack::Attack.cache.store = ActiveSupport::Cache::MemoryStore.new

    ### Throttle Spammy Clients ###

    # If any single client IP is making tons of requests, then they're
    # probably malicious or a poorly-configured scraper. Either way, they
    # don't deserve to hog all of the app server's CPU. Cut them off!
    #
    # Note: If you're serving assets through rack, those requests may be
    # counted by rack-attack and this throttle may be activated too
    # quickly. If so, enable the condition to exclude them from tracking.

    # Throttle all requests by IP (60rpm)
    #
    # Key: "rack::attack:#{Time.now.to_i/:period}:req/ip:#{req.ip}"
    throttle('req/ip', :limit => 300, :period => 2.minutes) do |req|
      req.ip # unless req.path.start_with?('/assets')
    end

    ### Prevent Brute-Force Login Attacks ###

    # The most common brute-force login attack is a brute-force password
    # attack where an attacker simply tries a large number of emails and
    # passwords to see if any credentials match.
    #
    # Another common method of attack is to use a swarm of computers with
    # different IPs to try brute-forcing a password for a specific account.

    # Throttle POST requests to /login by IP address
    #
    # Key: "rack::attack:#{Time.now.to_i/:period}:logins/ip:#{req.ip}"
    throttle('logins/ip', :limit => 5, :period => 20.seconds) do |req|
      if req.path == '/login' && req.post?
        req.ip
      end
    end

    # Throttle POST requests to /login by email param
    #
    # Key: "rack::attack:#{Time.now.to_i/:period}:logins/email:#{req.email}"
    #
    # Note: This creates a problem where a malicious user could intentionally
    # throttle logins for another user and force their login requests to be
    # denied, but that's not very common and shouldn't happen to you. (Knock
    # on wood!)
    throttle("logins/email", :limit => 5, :period => 20.seconds) do |req|
      if req.path == '/login' && req.post?
        # return the email if present, nil otherwise
        req.params['email'].presence
      end
    end

    ### Custom Throttle Response ###

    # By default, Rack::Attack returns an HTTP 429 for throttled responses,
    # which is just fine.
    #
    # If you want to return 503 so that the attacker might be fooled into
    # believing that they've successfully broken your app (or you just want to
    # customize the response), then uncomment these lines.
    # self.throttled_response = lambda do |env|
    #  [ 503,  # status
    #    {},   # headers
    #    ['']] # body
    # end

    # Block requests bad URLs
    # Rack::Attack.blocklist('block URLs') do |req|
    #   req.path.match /(wp-*|php|\.asp|cgi-bin|\/feed\/|wordpress|hubfs)/
    # end
  end
end

@grzuy
Copy link
Collaborator

grzuy commented May 17, 2018

Hi Brian,

Thanks for sharing those details!

I do understand the issue with incrementing non-raw value. Despite that, still trying to understand how would you hit that exception while using latest rack-attack version.

@grzuy
Copy link
Collaborator

grzuy commented May 17, 2018

I added acceptance test cases that use ActiveSupport::Cache::RedisCacheStore as a cache backend and wasn't able to reproduce the issue. See #341.

Can you think of a test case that is able to reproduce it?

@brian-kephart
Copy link
Contributor Author

I just looked at the new tests. It seems like they should have caught the problem if ActiveSupport 5.2 was installed. The new cache store suppresses Redis errors by default, so maybe we need to make them noisy in the test. Something like:

NOISY_ERROR_HANDLER = ->(method:, returning:, exception:) { Raise "ERROR" }
Rack::Attack.cache.store = ActiveSupport::Cache::RedisCacheStore.new(error_handler: NOISY_ERROR_HANDLER)

That still doesn't explain the correct throttling response in the test, though.

I wonder if this has something to do with the gem dependencies. The new cache store doesn't depend on the redis-store or redis-activesupport gems. They're not in my Gemfile.lock. When I fire up a Rails console and run defined?(::Redis::Store) the result is nil. Without that constant defined, the RedisStoreProxy won't be used, which means the increment operation should fail.

Maybe the presence of these gems in the testing environment causes the existing RedisStoreProxy to work with the new store without adding the new proxy.

As far as reproducing it, that should be possible in production by setting up any Rails 5.2 app with the new store. In a testing environment, though, I'll have to give it some thought.

@brian-kephart
Copy link
Contributor Author

brian-kephart commented May 18, 2018

Ok, I made a test app and reproduced the error. Stack trace:

Redis::CommandError (ERR value is not an integer or out of range):
  
redis (4.0.1) lib/redis/client.rb:119:in `call'
redis (4.0.1) lib/redis.rb:735:in `block in incrby'
redis (4.0.1) lib/redis.rb:45:in `block in synchronize'
/Users/briankephart/.rvm/rubies/ruby-2.5.1/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
redis (4.0.1) lib/redis.rb:45:in `synchronize'
redis (4.0.1) lib/redis.rb:734:in `incrby'
activesupport (5.2.0) lib/active_support/cache/redis_cache_store.rb:255:in `block (3 levels) in increment'
activesupport (5.2.0) lib/active_support/cache/redis_cache_store.rb:26:in `with'
activesupport (5.2.0) lib/active_support/cache/redis_cache_store.rb:255:in `block (2 levels) in increment'
activesupport (5.2.0) lib/active_support/cache/redis_cache_store.rb:439:in `failsafe'
activesupport (5.2.0) lib/active_support/cache/redis_cache_store.rb:254:in `block in increment'
activesupport (5.2.0) lib/active_support/cache.rb:663:in `block in instrument'
activesupport (5.2.0) lib/active_support/notifications.rb:170:in `instrument'
activesupport (5.2.0) lib/active_support/cache.rb:663:in `instrument'
activesupport (5.2.0) lib/active_support/cache/redis_cache_store.rb:253:in `increment'
activesupport (5.2.0) lib/active_support/cache/strategy/local_cache.rb:109:in `block in increment'
activesupport (5.2.0) lib/active_support/cache/strategy/local_cache.rb:179:in `block in bypass_local_cache'
activesupport (5.2.0) lib/active_support/cache/strategy/local_cache.rb:186:in `use_temporary_local_cache'
activesupport (5.2.0) lib/active_support/cache/strategy/local_cache.rb:179:in `bypass_local_cache'
activesupport (5.2.0) lib/active_support/cache/strategy/local_cache.rb:109:in `increment'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0476778a8a6b/lib/rack/attack/cache.rb:54:in `do_count'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0476778a8a6b/lib/rack/attack/cache.rb:18:in `count'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0476778a8a6b/lib/rack/attack/throttle.rb:28:in `[]'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0476778a8a6b/lib/rack/attack.rb:105:in `block in throttled?'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0476778a8a6b/lib/rack/attack.rb:104:in `any?'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0476778a8a6b/lib/rack/attack.rb:104:in `throttled?'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0476778a8a6b/lib/rack/attack.rb:170:in `call'
rack (2.0.5) lib/rack/tempfile_reaper.rb:15:in `call'
rack (2.0.5) lib/rack/etag.rb:25:in `call'
rack (2.0.5) lib/rack/conditional_get.rb:25:in `call'
rack (2.0.5) lib/rack/head.rb:12:in `call'
actionpack (5.2.0) lib/action_dispatch/http/content_security_policy.rb:18:in `call'
rack (2.0.5) lib/rack/session/abstract/id.rb:232:in `context'
rack (2.0.5) lib/rack/session/abstract/id.rb:226:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/cookies.rb:670:in `call'
activerecord (5.2.0) lib/active_record/migration.rb:559:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
activesupport (5.2.0) lib/active_support/callbacks.rb:98:in `run_callbacks'
actionpack (5.2.0) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/executor.rb:14:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
web-console (3.6.2) lib/web_console/middleware.rb:135:in `call_app'
web-console (3.6.2) lib/web_console/middleware.rb:30:in `block in call'
web-console (3.6.2) lib/web_console/middleware.rb:20:in `catch'
web-console (3.6.2) lib/web_console/middleware.rb:20:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
railties (5.2.0) lib/rails/rack/logger.rb:38:in `call_app'
railties (5.2.0) lib/rails/rack/logger.rb:26:in `block in call'
activesupport (5.2.0) lib/active_support/tagged_logging.rb:71:in `block in tagged'
activesupport (5.2.0) lib/active_support/tagged_logging.rb:28:in `tagged'
activesupport (5.2.0) lib/active_support/tagged_logging.rb:71:in `tagged'
railties (5.2.0) lib/rails/rack/logger.rb:26:in `call'
sprockets-rails (3.2.1) lib/sprockets/rails/quiet_assets.rb:13:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/request_id.rb:27:in `call'
rack (2.0.5) lib/rack/method_override.rb:22:in `call'
rack (2.0.5) lib/rack/runtime.rb:22:in `call'
activesupport (5.2.0) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/executor.rb:14:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/static.rb:127:in `call'
rack (2.0.5) lib/rack/sendfile.rb:111:in `call'
railties (5.2.0) lib/rails/engine.rb:524:in `call'
puma (3.11.4) lib/puma/configuration.rb:225:in `call'
puma (3.11.4) lib/puma/server.rb:632:in `handle_request'
puma (3.11.4) lib/puma/server.rb:446:in `process_client'
puma (3.11.4) lib/puma/server.rb:306:in `block in run'
puma (3.11.4) lib/puma/thread_pool.rb:120:in `block in spawn_thread'

@brian-kephart
Copy link
Contributor Author

Strangely, I can't reproduce the error on command. It's an occasional thing. The stack trace above was part of a series of consecutive errors. Before and after the series of errors, the app worked fine with the same request.

This is with a brand new Rails app, just showing the "Yay! You're on Rails!" page.

@brian-kephart
Copy link
Contributor Author

brian-kephart commented May 18, 2018

Test app is a new Rails 5.2 app using Ruby 2.5.1. Other details:

  • gem 'rack-attack', github: 'kickstarter/rack-attack' and gem 'redis' added to Gemfile
  • config.middleware.use Rack::Attack added to config/application.rb
  • This code in config/initializers/rack-attack.rb:
class Rack::Attack
  throttle('req/ip', :limit => 60, :period => 2.minutes) do |req|
    req.ip # unless req.path.start_with?('/assets')
  end

  throttle('logins/ip', :limit => 5, :period => 20.seconds) do |req|
    if req.path == '/login' && req.post?
      req.ip
    end
  end

  throttle("logins/email", :limit => 5, :period => 20.seconds) do |req|
    if req.path == '/login' && req.post?
      # return the email if present, nil otherwise
      req.params['email'].presence
    end
  end
end
  • This code in config/environments/development.rb:
NOISY_ERROR_HANDLER = ->(method:, returning:, exception:) { raise exception }
config.action_controller.perform_caching = true

config.cache_store = :redis_cache_store, { error_handler: NOISY_ERROR_HANDLER }

Please note that the original error report was from my production environment, so this has been observed in both environments.

@brian-kephart
Copy link
Contributor Author

Ok, so I think I fixed the wrong thing in my pull request. My errors didn't go away because of the new cache store proxy, they went away because after I disabled rack-attack, I had some different Redis errors that I solved by setting reconnect_attempts: 1 in my cache config.

I tried using my PR branch in the test app. The errors were different, but I still got errors in the same situation as when I used the current version. With either version of the gem, the errors went away when I set the cache config as described above.

This explains the intermittent behavior of the errors in production, because they were the result of Redis disconnecting momentarily. They happened to resemble the errors caused by other means, so my search led me to bad conclusions.

It might be worth documenting this setting for users of RedisCacheStore, but it doesn't seem like there's anything to fix in rack-attack itself. Sorry for the wild goose chase. I'll close the PR.

Like I mentioned, the errors were different when using the store proxy from my PR. Here's the stack trace, if you're still interested in it for any reason:

Redis::ConnectionError (Connection lost (ECONNRESET)):

redis (4.0.1) lib/redis/client.rb:255:in `rescue in io'
redis (4.0.1) lib/redis/client.rb:247:in `io'
redis (4.0.1) lib/redis/client.rb:259:in `read'
redis (4.0.1) lib/redis/client.rb:186:in `block in call_pipelined'
redis (4.0.1) lib/redis/client.rb:229:in `block (2 levels) in process'
redis (4.0.1) lib/redis/client.rb:366:in `ensure_connected'
redis (4.0.1) lib/redis/client.rb:219:in `block in process'
redis (4.0.1) lib/redis/client.rb:304:in `logging'
redis (4.0.1) lib/redis/client.rb:218:in `process'
redis (4.0.1) lib/redis/client.rb:185:in `call_pipelined'
redis (4.0.1) lib/redis/client.rb:155:in `block in call_pipeline'
redis (4.0.1) lib/redis/client.rb:291:in `with_reconnect'
redis (4.0.1) lib/redis/client.rb:153:in `call_pipeline'
redis (4.0.1) lib/redis.rb:2307:in `block in pipelined'
redis (4.0.1) lib/redis.rb:45:in `block in synchronize'
/Users/briankephart/.rvm/rubies/ruby-2.5.1/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
redis (4.0.1) lib/redis.rb:45:in `synchronize'
redis (4.0.1) lib/redis.rb:2303:in `pipelined'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0351b8be368a/lib/rack/attack/store_proxy/redis_cache_store_proxy.rb:13:in `increment'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0351b8be368a/lib/rack/attack/cache.rb:54:in `do_count'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0351b8be368a/lib/rack/attack/cache.rb:18:in `count'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0351b8be368a/lib/rack/attack/throttle.rb:28:in `[]'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0351b8be368a/lib/rack/attack.rb:106:in `block in throttled?'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0351b8be368a/lib/rack/attack.rb:105:in `any?'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0351b8be368a/lib/rack/attack.rb:105:in `throttled?'
/Users/briankephart/.rvm/gems/ruby-2.5.1/bundler/gems/rack-attack-0351b8be368a/lib/rack/attack.rb:171:in `call'
rack (2.0.5) lib/rack/tempfile_reaper.rb:15:in `call'
rack (2.0.5) lib/rack/etag.rb:25:in `call'
rack (2.0.5) lib/rack/conditional_get.rb:25:in `call'
rack (2.0.5) lib/rack/head.rb:12:in `call'
actionpack (5.2.0) lib/action_dispatch/http/content_security_policy.rb:18:in `call'
rack (2.0.5) lib/rack/session/abstract/id.rb:232:in `context'
rack (2.0.5) lib/rack/session/abstract/id.rb:226:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/cookies.rb:670:in `call'
activerecord (5.2.0) lib/active_record/migration.rb:559:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
activesupport (5.2.0) lib/active_support/callbacks.rb:98:in `run_callbacks'
actionpack (5.2.0) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/executor.rb:14:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
web-console (3.6.2) lib/web_console/middleware.rb:135:in `call_app'
web-console (3.6.2) lib/web_console/middleware.rb:30:in `block in call'
web-console (3.6.2) lib/web_console/middleware.rb:20:in `catch'
web-console (3.6.2) lib/web_console/middleware.rb:20:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
railties (5.2.0) lib/rails/rack/logger.rb:38:in `call_app'
railties (5.2.0) lib/rails/rack/logger.rb:26:in `block in call'
activesupport (5.2.0) lib/active_support/tagged_logging.rb:71:in `block in tagged'
activesupport (5.2.0) lib/active_support/tagged_logging.rb:28:in `tagged'
activesupport (5.2.0) lib/active_support/tagged_logging.rb:71:in `tagged'
railties (5.2.0) lib/rails/rack/logger.rb:26:in `call'
sprockets-rails (3.2.1) lib/sprockets/rails/quiet_assets.rb:13:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/request_id.rb:27:in `call'
rack (2.0.5) lib/rack/method_override.rb:22:in `call'
rack (2.0.5) lib/rack/runtime.rb:22:in `call'
activesupport (5.2.0) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/executor.rb:14:in `call'
actionpack (5.2.0) lib/action_dispatch/middleware/static.rb:127:in `call'
rack (2.0.5) lib/rack/sendfile.rb:111:in `call'
railties (5.2.0) lib/rails/engine.rb:524:in `call'
puma (3.11.4) lib/puma/configuration.rb:225:in `call'
puma (3.11.4) lib/puma/server.rb:632:in `handle_request'
puma (3.11.4) lib/puma/server.rb:446:in `process_client'
puma (3.11.4) lib/puma/server.rb:306:in `block in run'
puma (3.11.4) lib/puma/thread_pool.rb:120:in `block in spawn_thread'

I'll leave this issue open until I hear whether you think reconnect_attempts should be mentioned in the documentation or not. Thanks for your attention on this @grzuy, and sorry if it sucked up your time.

@grzuy
Copy link
Collaborator

grzuy commented May 18, 2018

[...] it doesn't seem like there's anything to fix in rack-attack itself.

Cool

I'll leave this issue open until I hear whether you think reconnect_attempts should be mentioned in the documentation or not.

I am not sure about that. Feels like something out of the scope of rack-attack to me. It's up to users to set their preferred redis configuration.

Thanks for your attention on this @grzuy, and sorry if it sucked up your time.

No worries. I think this discussion ended up being helpful. We now know rack-attack supports rails 5.2 RedisCacheStore. Thanks for taking the time to investigate the issue and being so responsive.

@grzuy grzuy closed this as completed May 18, 2018
@grzuy grzuy removed this from the 5.3.0 milestone May 18, 2018
@orenbnv
Copy link

orenbnv commented Jun 12, 2018

Having the same issue here.

Redis::CommandError/team
error ERR value is not an integer or out of range

Same stack.
Rails 5.2. Redis being used as cache store. Also using hiredis.
Any suggestions?

Full stack trace:

redis/client.rb in call at line 119
redis.rb in block in incrby at line 735
redis.rb in block in synchronize at line 45
monitor.rb in mon_synchronize at line 226
redis.rb in synchronize at line 45
redis.rb in incrby at line 734
active_support/cache/redis_cache_store.rb in block (3 levels) in increment at line 255
active_support/cache/redis_cache_store.rb in with at line 26
active_support/cache/redis_cache_store.rb in block (2 levels) in increment at line 255
active_support/cache/redis_cache_store.rb in failsafe at line 439
active_support/cache/redis_cache_store.rb in block in increment at line 254
active_support/cache.rb in block in instrument at line 663
active_support/notifications.rb in instrument at line 170
active_support/cache.rb in instrument at line 663
active_support/cache/redis_cache_store.rb in increment at line 253
active_support/cache/strategy/local_cache.rb in block in increment at line 109
active_support/cache/strategy/local_cache.rb in block in bypass_local_cache at line 179
active_support/cache/strategy/local_cache.rb in use_temporary_local_cache at line 186
active_support/cache/strategy/local_cache.rb in bypass_local_cache at line 179
active_support/cache/strategy/local_cache.rb in increment at line 109
rack/attack/cache.rb in do_count at line 55
rack/attack/cache.rb in count at line 19
rack/attack/throttle.rb in [] at line 28
rack/attack.rb in block in throttled? at line 103
rack/attack.rb in any? at line 102
rack/attack.rb in throttled? at line 102
rack/attack.rb in call at line 168
rack/tempfile_reaper.rb in call at line 15
rack/etag.rb in call at line 251
rack/head.rb in call at line 12
action_dispatch/http/content_security_policy.rb in call at line 18
rack/session/abstract/id.rb in context at line 232
rack/session/abstract/id.rb in call at line 226
action_dispatch/middleware/cookies.rb in call at line 670
action_dispatch/middleware/callbacks.rb in block in call at line 28
active_support/callbacks.rb in run_callbacks at line 98
action_dispatch/middleware/callbacks.rb in call at line 26
action_dispatch/middleware/debug_exceptions.rb in call at line 61
action_dispatch/middleware/show_exceptions.rb in call at line 33
rails/rack/logger.rb in call_app at line 38
rails/rack/logger.rb in block in call at line 26
active_support/tagged_logging.rb in block in tagged at line 71
active_support/tagged_logging.rb in tagged at line 28
active_support/tagged_logging.rb in tagged at line 71
rails/rack/logger.rb in call at line 26
action_dispatch/middleware/remote_ip.rb in call at line 81
action_dispatch/middleware/request_id.rb in call at line 27
rack/method_override.rb in call at line 221
active_support/cache/strategy/local_cache_middleware.rb in call at line 29
action_dispatch/middleware/executor.rb in call at line 14
action_dispatch/middleware/static.rb in call at line 127
rack/sendfile.rb in call at line 111
action_dispatch/middleware/ssl.rb in call at line 74
raven/integrations/rack.rb in call at line 51
rails/engine.rb in call at line 524
puma/configuration.rb in call at line 225
puma/server.rb in handle_request at line 632
puma/server.rb in process_client at line 446
puma/server.rb in block in run at line 306
puma/thread_pool.rb in block in spawn_thread at line 120

@orenbnv
Copy link

orenbnv commented Jun 12, 2018

When you look at redis, seems like the value being stored is indeed not an integer.
It is:

"\u0004\bo: ActiveSupport::Cache::Entry\n:\v@valuei\u0006:\u0015@marshaled_value\"\t\u0004\bi\u0006:\r@version0:\u0010@created_atf\u00161528819338.985056:\u0010@expires_inf\b163"

So something is indeed dropping the wrong value.

@brian-kephart
Copy link
Contributor Author

Did you read this comment above? In my case, I discovered the problem went away when I added reconnect_attempts: 0 to my cache config as detailed here. I was actually experiencing a connection error.

I never did figure out why that seems to work, though. All my reasoning says there's a problem in this gem, but the acceptance tests and my experience using it says it works fine as is. 🤷‍♂️

Do you have a reliable repro?

@orenbnv
Copy link

orenbnv commented Jun 14, 2018

Thanks @brian-kephart .
I read that. Unfortunately, that did not solve the issue for me.
So still experiencing the same problem.
It does not appear to be happening consistently.
Will usually happen after an hour or so, even if it is set up to a 5 minute throttling period.

@grzuy grzuy added this to the 5.3.0 milestone Jun 19, 2018
@stevegeek
Copy link

Hi all, I have just been experiencing this too. I checked that the redis cache config does not specify the reconnect attempts and as per the docs http://edgeguides.rubyonrails.org/caching_with_rails.html#activesupport-cache-rediscachestore the default should just be 0. It is intermittent and as per other posts clears after some time. (Rails 5.2, Ruby 2.5.1, on Heroku using Heroku Redis)

@grzuy
Copy link
Collaborator

grzuy commented Jul 4, 2018

Hi @stevegeek,

Can you please provide the following info to help debug your issue?

  • rack-attack version
  • Error stacktrace
  • Are you setting Rack::Attack.cache.store? If so, what are you assigning?

Thank you! :-)

@stevegeek
Copy link

stevegeek commented Jul 4, 2018

@grzuy Sure thing!

rack-attack (5.2.0)

Redis::CommandError: ERR value is not an integer or out of range

[PROJECT_ROOT]/vendor/ruby-2.5.1/lib/ruby/2.5.0/monitor.rb:226 :in `mon_synchronize`
224     mon_enter
225     begin
> 226       yield
227     ensure
228       mon_exit

[GEM_ROOT]/gems/redis-4.0.1/lib/redis/client.rb:119 :in `call`
 [GEM_ROOT]/gems/redis-4.0.1/lib/redis.rb:735 :in `block in incrby`
 [GEM_ROOT]/gems/redis-4.0.1/lib/redis.rb:45 :in `block in synchronize`
[PROJECT_ROOT]/vendor/ruby-2.5.1/lib/ruby/2.5.0/monitor.rb:226 :in `mon_synchronize`
 [GEM_ROOT]/gems/redis-4.0.1/lib/redis.rb:45 :in `synchronize`
 [GEM_ROOT]/gems/redis-4.0.1/lib/redis.rb:734 :in `incrby`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/redis_cache_store.rb:255 :in `block (3 levels) in increment`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/redis_cache_store.rb:26 :in `with`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/redis_cache_store.rb:255 :in `block (2 levels) in increment`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/redis_cache_store.rb:439 :in `failsafe`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/redis_cache_store.rb:254 :in `block in increment`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache.rb:663 :in `block in instrument`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/notifications.rb:168 :in `block in instrument`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:23 :in `instrument`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/notifications.rb:168 :in `instrument`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache.rb:663 :in `instrument`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/redis_cache_store.rb:253 :in `increment`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/strategy/local_cache.rb:109 :in `block in increment`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/strategy/local_cache.rb:179 :in `block in bypass_local_cache`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/strategy/local_cache.rb:186 :in `use_temporary_local_cache`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/strategy/local_cache.rb:179 :in `bypass_local_cache`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/strategy/local_cache.rb:109 :in `increment`
 [GEM_ROOT]/gems/rack-attack-5.2.0/lib/rack/attack/cache.rb:55 :in `do_count`
 [GEM_ROOT]/gems/rack-attack-5.2.0/lib/rack/attack/cache.rb:19 :in `count`
 [GEM_ROOT]/gems/rack-attack-5.2.0/lib/rack/attack/throttle.rb:28 :in `[]`
 [GEM_ROOT]/gems/rack-attack-5.2.0/lib/rack/attack.rb:103 :in `block in throttled?`
 [GEM_ROOT]/gems/rack-attack-5.2.0/lib/rack/attack.rb:102 :in `any?`
 [GEM_ROOT]/gems/rack-attack-5.2.0/lib/rack/attack.rb:102 :in `throttled?`
 [GEM_ROOT]/gems/rack-attack-5.2.0/lib/rack/attack.rb:168 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/warden-1.2.7/lib/warden/manager.rb:36 :in `block in call`
 [GEM_ROOT]/gems/warden-1.2.7/lib/warden/manager.rb:35 :in `catch`
 [GEM_ROOT]/gems/warden-1.2.7/lib/warden/manager.rb:35 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/rack-2.0.5/lib/rack/tempfile_reaper.rb:15 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/rack-2.0.5/lib/rack/etag.rb:25 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/rack-2.0.5/lib/rack/conditional_get.rb:25 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/rack-2.0.5/lib/rack/head.rb:12 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/http/content_security_policy.rb:18 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:232 :in `context`
 [GEM_ROOT]/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:226 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/middleware/cookies.rb:670 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/middleware/callbacks.rb:28 :in `block in call`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/callbacks.rb:98 :in `run_callbacks`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/middleware/callbacks.rb:26 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/middleware/debug_exceptions.rb:61 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/middleware/show_exceptions.rb:33 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/railties-5.2.0/lib/rails/rack/logger.rb:38 :in `call_app`
 [GEM_ROOT]/gems/railties-5.2.0/lib/rails/rack/logger.rb:26 :in `block in call`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/tagged_logging.rb:71 :in `block in tagged`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/tagged_logging.rb:28 :in `tagged`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/tagged_logging.rb:71 :in `tagged`
 [GEM_ROOT]/gems/railties-5.2.0/lib/rails/rack/logger.rb:26 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/middleware/remote_ip.rb:81 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/middleware/request_id.rb:27 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/action_dispatch/request_id.rb:12 :in `call`
 [GEM_ROOT]/gems/rack-2.0.5/lib/rack/method_override.rb:22 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/rack-2.0.5/lib/rack/runtime.rb:22 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/activesupport-5.2.0/lib/active_support/cache/strategy/local_cache_middleware.rb:29 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/middleware/executor.rb:14 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/middleware/static.rb:127 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/rack-2.0.5/lib/rack/sendfile.rb:111 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
 [GEM_ROOT]/gems/actionpack-5.2.0/lib/action_dispatch/middleware/ssl.rb:74 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/probes/middleware.rb:37 :in `call`
[GEM_ROOT]/gems/skylight-core-2.0.1/lib/skylight/core/middleware.rb:83 :in `call`
 [GEM_ROOT]/gems/railties-5.2.0/lib/rails/engine.rb:524 :in `call`
 [GEM_ROOT]/gems/puma-3.11.4/lib/puma/configuration.rb:225 :in `call`
 [GEM_ROOT]/gems/puma-3.11.4/lib/puma/server.rb:632 :in `handle_request`
 [GEM_ROOT]/gems/puma-3.11.4/lib/puma/server.rb:446 :in `process_client`
 [GEM_ROOT]/gems/puma-3.11.4/lib/puma/server.rb:306 :in `block in run`
 [GEM_ROOT]/gems/puma-3.11.4/lib/puma/thread_pool.rb:120 :in `block in spawn_thread`

Rack attack initializer

module Rack
  class Attack
    if Rails.env.production?
      throttle("csp/ip", limit: 3000, period: 5.minutes) do |req|
        req.ip if req.path.start_with?("/csp-violation-report-endpoint")
      end

      throttle("req/ip", limit: 6000, period: 5.minutes) do |req|
        req.ip unless req.path.start_with?("/csp-violation-report-endpoint")
      end

      throttle("logins/ip", limit: 5, period: 20.seconds) do |req|
        req.ip if req.path == "/accounts/sign_in" && req.post?
      end
    end
  end
end

Rails config:
config.cache_store = :redis_cache_store, {url: ENV["REDIS_URL"]}

@grzuy
Copy link
Collaborator

grzuy commented Jul 4, 2018

rack-attack (5.2.0)

rack-attack 5.3.2, or greater, should fix that problem.

Let me know if it doesn't.

@stevegeek
Copy link

@grzuy Ah ok thanks, sorry! missed that it was fixed

tigefa4u pushed a commit to tigefa4u/gitlabhq that referenced this issue Aug 22, 2019
`ActiveSupport::Cache::RedisCacheStore` is not compatible with the
version of Rack Attack we are using (v4.4.1) per
rack/rack-attack#281. Users that had
rate limits enabled might see `Redis::CommandError: ERR value is not an
integer or out of range` because the `raw` parameter wasn't passed along
properly.

Let's partially revert the change to the original cache store until we
can update to Rack Attack v5.2.3 that has support for
`ActiveSupport::Cache::RedisCacheStore` via
rack/rack-attack#340.

Closes https://gitlab.com/gitlab-org/gitlab-ce/issues/66449
tigefa4u pushed a commit to tigefa4u/gitlabhq that referenced this issue Aug 22, 2019
`ActiveSupport::Cache::RedisCacheStore` is not compatible with the
version of Rack Attack we are using (v4.4.1) per
rack/rack-attack#281. Users that had
rate limits enabled might see `Redis::CommandError: ERR value is not an
integer or out of range` because the `raw` parameter wasn't passed along
properly. As a result, the Rack Attack entry would be stored as an
`ActiveSupport::Cache::Entry` instead of a raw string holding an integer
value.

Let's partially revert the change in
https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/30966 to use the
original cache store until we can update to Rack Attack v5.2.3 that has
support for `ActiveSupport::Cache::RedisCacheStore` via
rack/rack-attack#350.

Closes https://gitlab.com/gitlab-org/gitlab-ce/issues/66449
tigefa4u pushed a commit to tigefa4u/gitlabhq that referenced this issue Aug 26, 2019
`ActiveSupport::Cache::RedisCacheStore` is not compatible with the
version of Rack Attack we are using (v4.4.1) per
rack/rack-attack#281. Users that had
rate limits enabled might see `Redis::CommandError: ERR value is not an
integer or out of range` because the `raw` parameter wasn't passed along
properly. As a result, the Rack Attack entry would be stored as an
`ActiveSupport::Cache::Entry` instead of a raw string holding an integer
value.

Let's partially revert the change in
https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/30966 to use the
original cache store until we can update to Rack Attack v5.2.3 that has
support for `ActiveSupport::Cache::RedisCacheStore` via
rack/rack-attack#350.

Closes https://gitlab.com/gitlab-org/gitlab-ce/issues/66449
@leondmello
Copy link

Seeing this error on the latest version of the gem. 6.2.2
Dunno why it stored an error value in the first place.
we have a custom wrapper around the Redis cache store. Trying to see if that cause any of this 😕

@leondmello
Copy link

leondmello commented Apr 15, 2020

Figured out our issue. Posting for anyone who has a similar setup.
We extended the base redis cache store with out custom implementation with something like,

class CustomRedisCacheStore < ActiveSupport::Cache::RedisCacheStore

Since we do that, it bypasses the custom proxy instantiation done via https://github.com/kickstarter/rack-attack/blob/da418806638d0556fe15f20cea20194d4bbb85b3/lib/rack/attack/store_proxy.rb#L5-L18

Because of that, we missed the raw write that this offers
https://github.com/kickstarter/rack-attack/blob/da418806638d0556fe15f20cea20194d4bbb85b3/lib/rack/attack/store_proxy/redis_cache_store_proxy.rb#L33-L37

Fixed it with a monkey patch

class StoreProxy::RedisCacheStoreProxy
    def self.handle?(store)
      store.class.name == CustomRedisCacheStore.name
    end
  end

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants