search

zombocom / rack-timeout

Abort requests that are taking too long
MIT License
873 stars 155 forks source link

undefined method `state=' for nil:NilClass since 0.3.1 #92

Closed nvloff closed 6 years ago

nvloff commented 9 years ago

Yesterday we've upgraded rack-timeout to 0.3.1 from 0.2.4 and we started seeing this error on production (we're using heroku) :


    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/core.rb:168 :in `_set_state!`

    166     def self._set_state!(env, state)
    167       raise "Invalid state: #{state.inspect}" unless VALID_STATES.include? state
    168       env[ENV_INFO_KEY].state = state
    169       notify_state_change_observers(env)
    170     end

    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/core.rb:115 :in `block in call`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/core.rb:117 :in `call`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/core.rb:117 :in `block in call`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/support/scheduler.rb:39 :in `call`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/support/scheduler.rb:39 :in `run!`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/support/scheduler.rb:52 :in `run!`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/support/scheduler.rb:99 :in `block (2 levels) in run_loop!`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/support/scheduler.rb:99 :in `each`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/support/scheduler.rb:99 :in `block in run_loop!`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/support/scheduler.rb:80 :in `loop`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/support/scheduler.rb:80 :in `run_loop!`
    [GEM_ROOT]/gems/rack-timeout-0.3.1/lib/rack/timeout/support/scheduler.rb:72 :in `block (2 levels) in runner`

Rack middlewares on production:

use Honeybadger::Rack::UserInformer
use Honeybadger::Rack::UserFeedback
use Honeybadger::Rack::ErrorNotifier
use HireFire::Middleware
use Rack::Cors
use Rack::UTF8Sanitizer
use Rack::Sendfile
use ActionDispatch::Static
use #<ActiveSupport::Cache::Strategy::LocalCache::Middleware:0x007f7d7d3117b0>
use Rack::Timeout
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use ActionDispatch::DebugExceptions
use ActionDispatch::RemoteIp
use ActionDispatch::Callbacks
use ActionDispatch::Cookies
use ActionDispatch::Session::CookieStore
use ActionDispatch::Flash
use ActionDispatch::ParamsParser
use Rack::Head
use Rack::ConditionalGet
use Rack::ETag
use Warden::Manager
use JQuery::FileUpload::Rails::Middleware

Tried reproducing locally but I can't seem to find the right conditions to do so.

kch commented 9 years ago

How frequently/consistently are you seeing this in production? Is it for all requests? A particular set of? A seemingly random set?

Do you have the full logs for a failing request? I wanna see what rack-timeout logs before the failure.

Looking at the code in rack/timeout/core.rb you can see the value is init'd in L81, and _set_state! seems to get successfully called in L109… So I suspect something else during the request to be affecting env and for some reason clearing out rack-timeout's info struct. (and maybe more?)

register_state_change is called repeatedly in a separate thread, but I suspect the main thread would already be doing L125.

nvloff commented 9 years ago

How frequently/consistently are you seeing this in production?

About 300 times for a 15h period.

Is it for all requests?

Some. For other we do get standard RequestTimeout exceptions.

A particular set of?

Seemingly random. But for endponts that don't usually (or at all) timeout

Do you have the full logs for a failing request?

No, unfortunately.

So the Rack::Timeout middleware order change grabbed my attention from the change log. And we deployed a rendom fix that moved Rack::Timeout before Rack::Cors in the middleware list. And for the past 10h we haven't had a single error.

I'm closing this. I don't currently have logs or any more debug information, and we no longer see the issue.

kch commented 9 years ago

Yeah I was wondering if the middleware order was to blame. Can you paste here the new middleware list? Probably one of them is doing something funny.

nvloff commented 9 years ago

Ok, I spoke too soon :)

We encountered the same issue eventually. I insta-reverted to 0.2.4 once I saw it.

It occurred exactly 2 times ~10min apart.

So, I really want to be able to provide some more debug info, but I'm still unable to reproduce locally. And we can't run 0.3.x on production for now. Anything I can do to provide more info?

I don't know what's the policy for issues like this, I reopened it, but I'll understand if you close it due to the lack of debug data.

kch commented 9 years ago

Well I'd like to get it fixed.

If I make a debug branch will you run it?

The idea, if the info struct is not present, is to give up on the timeout code but let the request finish normally, whilst along with it logging some debug info.

nvloff commented 9 years ago

Yep, sure we can run that.

kch commented 9 years ago

Ok, try with:

gem "rack-timeout", github:"heroku", branch:"vanishing-env-info-debug"

This will log some extra stuff that'll be helpful in understanding what's going on. Additionally it'll not raise if info is not present.

It's a lot of logging per request so just run it long enough to run into the issue a few times. Maybe half a day or so?

You'll need a log retention add-on with heroku.

Can you open a ticket with heroku support and ask that it be sent my way? Also make sure you grant application access so I can inspect your log retention add-on.

nvloff commented 9 years ago

Hey, Thanks!

Just deployed to production and created the ticket with heroku. We've added papertrail for the logs hope the data size would be enough there.

nvloff commented 9 years ago

Ok, this started appearing now:

TypeError: nil is not a symbol

GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/logging-observer.rb:42 :in `log_state_change`
40     info = env[::Rack::Timeout::ENV_INFO_KEY]
41     level = STATE_LOG_LEVEL[info.state]
42     logger(env).send(level) do
43       s  = "source=rack-timeout"
44       s << " id="      << info.id           if info.id
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/core.rb:199 :in `call`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/core.rb:199 :in `block in notify_state_change_observers`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/core.rb:199 :in `each`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/core.rb:199 :in `notify_state_change_observers`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/core.rb:176 :in `_set_state!`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/core.rb:117 :in `block in call`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/core.rb:119 :in `call`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/core.rb:119 :in `block in call`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/support/scheduler.rb:39 :in `call`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/support/scheduler.rb:39 :in `run!`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/support/scheduler.rb:52 :in `run!`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/support/scheduler.rb:99 :in `block (2 levels) in run_loop!`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/support/scheduler.rb:99 :in `each`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/support/scheduler.rb:99 :in `block in run_loop!`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/support/scheduler.rb:80 :in `loop`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/support/scheduler.rb:80 :in `run_loop!`
[GEM_ROOT]/bundler/gems/rack-timeout-60e99cb3108a/lib/rack/timeout/support/scheduler.rb:72 :in `block (2 levels) in runner`
kch commented 8 years ago

I made some updates to the branch and asked you on the heroku ticket to re-deploy but haven't heard from you since. Any news?

nvloff commented 8 years ago

Yeah, quite simple: we hit our papertrail plan limit and I was gonna deploy the branch tomorrow on next month's quota. I'll reopen the ticket when it's done.

metade commented 8 years ago

We're seeing the same thing. Rolling back to an older version of rack-timeout.

We'll try running the vanishing-env-info-debug on our staging environment to see if we can replicate the error.

kch commented 8 years ago

What I gather from the logs so far is, when this happens, env has been basically cleared. There's a single key in it. Next commit I'll print the key so we know which.

Also, all the failing calls happen coming from the heartbeat_event proc, which runs in another thread. Also, the heartbeat is basically irrelevant to the main operation of rack timeout. It's only really used for logging purposes atm. So it's fine to just bail if info is not present.

But I wanna get to the bottom of this first.

kch commented 8 years ago

Ok, about to push some updates. When you deploy with the new updates, can you set Rack::Timeout::Logger.level = Logger::DEBUG or at least Logger::INFO?

kch commented 8 years ago

New things are in. Please run in prod a couple days, accumulate some logs, and let me know so I can download them. You might get attention faster if you notify me in the support ticket.

@metade if you wanna do the same, you're welcome. This branch is safe to run in prod, it should not explode as it just skips stuff if env has been cleared.

nvloff commented 8 years ago

I get the following error when I run this new debug code, start the development server, and try to do a request.

=> Booting Thin
=> Rails 4.2.4 application starting in development on http://localhost:3000
=> Run `rails server -h` for more startup options
=> Ctrl-C to shutdown server
Thin web server (v1.6.4 codename Gob Bluth)
Maximum connections set to 1024
Listening on localhost:3000, CTRL+C to stop
/Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:23: [BUG] object allocation during garbage collection phase
ruby 2.0.0p481 (2014-05-08) [x86_64-darwin14.1.0]

-- Crash Report log information --------------------------------------------
   See Crash Report log file under the one of following:
     * ~/Library/Logs/CrashReporter
     * /Library/Logs/CrashReporter
     * ~/Library/Logs/DiagnosticReports
     * /Library/Logs/DiagnosticReports
   the more detail of.

-- Control frame information -----------------------------------------------
c:1613 p:---- s:12029 e:002028 CFUNC  :caller
c:1612 p:0018 s:12025 e:002020 METHOD /Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:23
c:1611 p:0013 s:12015 e:002014 LAMBDA /Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:16 [FINISH]
c:1610 p:0021 s:12011 e:002005 METHOD /Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:23
c:1609 p:0013 s:12000 e:001999 LAMBDA /Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:16 [FINISH]
c:1608 p:0021 s:11996 e:001990 METHOD /Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:23
c:1607 p:0013 s:11985 e:001984 LAMBDA /Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:16 [FINISH]

... snip ..

/Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:23:in `__log_method_call'
/Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:16:in `block (2 levels) in extended'
/Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:23:in `__log_method_call'
/Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:16:in `block (2 levels) in extended'
/Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:23:in `__log_method_call'
/Users/nvloff/work/Textmaster.com/vendor/ruby/2.0.0/bundler/gems/rack-timeout-5e579ee5fe7b/lib/rack/timeout/core.rb:23:in `caller'

-- C level backtrace information -------------------------------------------

Full error: https://gist.github.com/nvloff/ccb7ebfecfe5f2d8dd80

kch commented 8 years ago

Ugh. Could you try with ruby 2.2.3?

kch commented 8 years ago

@metade which ruby version are you on btw?

nvloff commented 8 years ago

@kch not anytime soon. we'll be on 2.0 for a while. We have 2.2.3 under testing but we may decide against running it on prod. I'll know more next week.

kch commented 8 years ago

OK, I'll see if I can figure out wth is going on with 2.0.0

kch commented 8 years ago

Even for 2.0, there's a newer patchlevel ( 2.0.0-p647), you might want to at least look into that. Not sure if it would fix anything for this issue tho.

kch commented 8 years ago

@nvloff so I tried here with same ruby, rails, and thin versions, and the error did not happen for my test app.

kch commented 8 years ago

@nvloff you only tried that locally yes? I'd say try in new staging app on heroku?

I also pushed a new commit to the branch. There's a slight chance it may make things better.

(Also if you recently updated OS X, any chance something's off with your ruby after that?)

nvloff commented 8 years ago

Hey, now I don't get that error, but just the dev server keeps on loading and never finishes a request. I now get this same behaviour even with the previous commit.

It's probably something local, I'll check my setup and get back to you. May take me a couple of days as I'm a bit swamped with other things right now.

ravi-ture commented 8 years ago

Hi, we are getting the same error on our heroku deployed application. 

NoMethodError: undefined method `state=' for nil:NilClass
…2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:  168:in `_​set_​state!'​
…2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:  115:in `block in call'​
…2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:  117:in `call'​
…2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:  117:in `block in call'​
…ck-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:   39:in `call'
​…ck-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:   39:in `run!'
​…ck-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:   52:in `run!'
​…ck-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:   99:in `block ​(2 levels)​ in run_​loop!'​…ck-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:   99:in `each'
​…ck-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:   99:in `block in run_​loop!'​
…ck-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:   80:in `loop'​
…ck-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:   80:in `run_​loop!'​
…ck-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:   72:in `block ​(2 levels)​ in runner'
nadavshatz commented 8 years ago

I used to get this as well https://github.com/heroku/rack-timeout/issues/57 and never was able to resolve. I subscribed to this issue and am really interested in its conclusion :)

DSAMPAT commented 8 years ago

@kch

I am using Heroku as well and have changed the logger to logger::ERROR and have set the rack_timeout.rb to the following:-

Rack::Timeout::timeout = 120
Rack::Timeout::Logger.logger = Logger.new($stderr)
Rack::Timeout::Logger.level  = Logger::ERROR

The message still appears as below with either a 6, 8, 9, 11 or 12:-

Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.661861 #9] ERROR -- : listen loop error: undefined method `state=' for nil:NilClass (NoMethodError) 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.661942 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:168:in `_set_state!' 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.661989 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:115:in `block in call' 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662031 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:117:in `call' 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662071 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:117:in `block in call' 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662111 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:39:in `call' 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662150 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:39:in `run!' 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662190 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:52:in `run!' 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662229 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99:in `block (2 levels) in run_loop!' 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662269 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99:in `each' 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662308 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99:in `block in run_loop!' 
Dec 16 11:31:15 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662347 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:80:in `loop' 
Dec 16 11:31:16 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662386 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:80:in `run_loop!' 
Dec 16 11:31:16 xxxappname app/web.1:  E, [2015-12-16T03:31:15.662426 #9] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:72:in `block (2 levels) in runner' 

Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.004838 #6] ERROR -- : listen loop error: undefined method `state=' for nil:NilClass (NoMethodError) 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.004906 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:168:in `_set_state!' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.004946 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:115:in `block in call' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.004981 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:117:in `call' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.005013 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:117:in `block in call' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.005044 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:39:in `call' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.005074 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:39:in `run!' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.005104 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:52:in `run!' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.005131 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99:in `block (2 levels) in run_loop!' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.005161 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99:in `each' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.005222 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99:in `block in run_loop!' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.005252 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:80:in `loop' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.005282 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:80:in `run_loop!' 
Dec 16 12:46:36 xxxappname app/web.1:  E, [2015-12-16T04:46:36.005310 #6] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:72:in `block (2 levels) in runner' 

Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.116998 #12] ERROR -- : listen loop error: undefined method `state=' for nil:NilClass (NoMethodError) 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117060 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:168:in `_set_state!' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117085 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:115:in `block in call' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117108 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:117:in `call' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117131 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:117:in `block in call' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117154 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:39:in `call' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117176 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:39:in `run!' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117199 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:52:in `run!' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117221 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99:in `block (2 levels) in run_loop!' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117243 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99:in `each' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117265 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99:in `block in run_loop!' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117287 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:80:in `loop' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117309 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:80:in `run_loop!' 
Dec 16 12:58:01 xxxappname app/web.1:  E, [2015-12-16T04:58:01.117332 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:72:in `block (2 levels) in runner'

Please advise if there is anything else we can do to assist with more information to help resolve the issue.

samandmoore commented 8 years ago

migrating my comment over from the closed issue #57:

Seeing a similar issue on jruby 1.7.19 using puma 2.15.3 and rack-timeout 0.3.2.

NoMethodError: undefined method `state' for nil:NilClass
               log_state_change at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/logging-observer.rb:41
                           call at org/jruby/RubyProc.java:271
  notify_state_change_observers at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:192
                           each at org/jruby/RubyArray.java:1613
  notify_state_change_observers at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:192
                    _set_state! at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:169
                           call at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:115
                           call at org/jruby/RubyProc.java:271
                           call at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:117
                           call at org/jruby/RubyProc.java:271
                           run! at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:39
                           run! at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:52
                      run_loop! at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99
                           each at org/jruby/RubyArray.java:1613
                      run_loop! at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:99
                           loop at org/jruby/RubyKernel.java:1507
                      run_loop! at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:80
                         runner at /code/jruby/1.9/gems/rack-timeout-0.3.2/lib/rack/timeout/support/scheduler.rb:72

It also appears to have resulted / coincided with a crash in the puma process. could be an out of memory issue?

NielsKSchjoedt commented 8 years ago

+1 We are seeing this too pretty frequently on our app deployed to dedicated servers (not on heroku). We are running 2.2.3

DSAMPAT commented 8 years ago

@kch Any update here?

samandmoore commented 8 years ago

I would like to add that I'm actually seeing these undefined method errors on 0.2.4 (which was believed not to have the issue) not just on the latest release. Interestingly, they're not crashing the process in 0.2.4, but they appear to be crashing the thread.

kch commented 8 years ago

Ok, I'm ready to get back to this.

So everyone willing to help, I still need data.

If you're willing, please run this branch, and if you're on heroku, add a log retention add-on. (otherwise, you know, keep your logs somehow.)

It'll log A LOT OF DATA. I'm trying to track down what is resetting the env, so if it's nil I'll log stack traces for all methods sent to env during that request.

When you have some of those, please paste them here. All lines interesting to me start with source=rack-timeout-debug.

kch commented 8 years ago

Also keep in mind that this branch pretends everything is ok when our env info is nil and let's the request proceed as normal, just without enforcing timeout. Which is a nice benefit while we don't have a fix.

DSAMPAT commented 8 years ago

@kch Any chance you can make the branch into a rc release so we can test it and then revert if needed using the gemfile?

kch commented 8 years ago

@DSAMPAT why can't you just gem "rack-timeout", github:"heroku", branch:"vanishing-env-info-debug"?

kch commented 8 years ago

Well, giving the wrong code wasn't very helpful. What I meant is, add this to your Gemfile:

gem "rack-timeout", github:"heroku/rack-timeout", branch:"vanishing-env-info-debug"

I'm hoping to get this fixed for the next release, but I can only do that if I see some debug data as I have so far not been able to reproduce this nor observed it in any of our systems.

DSAMPAT commented 8 years ago

@kch used the above code and got the error immediately after updating the app. View updated error log below. Hope it is of use and related to the same issue.

Mar 08 20:36:12 appname heroku/web.1:  Starting process with command `bundle exec unicorn -p 8082 -c ./config/unicorn.rb` 
Mar 08 20:36:16 appname app/web.1:  I, [2016-03-09T04:36:16.251672 #3]  INFO -- : Refreshing Gem list 
Mar 08 20:36:19 appname app/web.1:  I, [2016-03-09T04:36:18.854026 #3]  INFO -- : listening on addr=0.0.0.0:8082 fd=9 
Mar 08 20:36:19 appname app/web.1:  I, [2016-03-09T04:36:18.893064 #6]  INFO -- : worker=0 ready 
Mar 08 20:36:19 appname app/web.1:  I, [2016-03-09T04:36:18.893274 #3]  INFO -- : master process ready 
Mar 08 20:36:19 appname app/web.1:  I, [2016-03-09T04:36:18.896350 #9]  INFO -- : worker=1 ready 
Mar 08 20:36:19 appname app/web.1:  I, [2016-03-09T04:36:18.898024 #12]  INFO -- : worker=2 ready 
Mar 08 20:36:19 appname heroku/web.1:  State changed from starting to up 
Mar 08 20:36:21 appname heroku/router:  at=info method=GET path="/" host=appname.herokuapp.com request_id=1e5218fc-12e5-4ea6-bb4f-c81678d169eb fwd="xxx.xxx.xxx.xxx" dyno=web.1 connect=2ms service=5ms status=500 bytes=38 
Mar 08 20:36:21 appname app/web.1:  source=rack-timeout id=1e5218fc-12e5-4ea6-bb4f-c81678d169eb wait=33172ms timeout=30000ms state=expired at=error 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559318 #12] ERROR -- : app error: Request older than 30000ms. (Rack::Timeout::RequestExpiryError) 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559404 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-timeout-0.3.2/lib/rack/timeout/core.rb:98:in `call' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559454 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/activesupport-4.2.3/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559501 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/actionpack-4.2.3/lib/action_dispatch/middleware/static.rb:116:in `call' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559542 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/sendfile.rb:113:in `call' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559606 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.3/lib/rails/engine.rb:518:in `call' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559640 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.3/lib/rails/application.rb:165:in `call' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559681 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/unicorn-4.9.0/lib/unicorn/http_server.rb:580:in `process_client' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559718 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/unicorn-4.9.0/lib/unicorn/http_server.rb:674:in `worker_loop' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559765 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/unicorn-4.9.0/lib/unicorn/http_server.rb:529:in `spawn_missing_workers' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559812 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/unicorn-4.9.0/lib/unicorn/http_server.rb:140:in `start' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559850 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/gems/unicorn-4.9.0/bin/unicorn:126:in `<top (required)>' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559904 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/bin/unicorn:23:in `load' 
Mar 08 20:36:21 appname app/web.1:  E, [2016-03-09T04:36:21.559971 #12] ERROR -- : /app/vendor/bundle/ruby/2.2.0/bin/unicorn:23:in `<main>'
mbasset commented 8 years ago

:+1: We are also have this issue and have no idea whats causing it. It seems almost random even though we are sure its not.

kch commented 8 years ago

@DSAMPAT that seems just an artefact of having restarted the dyno. Some requests that had been waiting too long for the dyno to come back online will be deemed too old. Did the app run fine after that?

kch commented 8 years ago

@mbasset you're welcome to try this debug branch too then :)

DSAMPAT commented 8 years ago

@kch I have implemented the code change on the Production code but pushed it to a Staging site. Yes, the app is running fine with the code. Now whenever it resumes from an idle state, the same few lines come up, other than that, the old errors have not appeared.

Maybe @mbasset can confirm that his errors have disappeared as well.

mbasset commented 8 years ago

We tried the debug branch and got massive memory consumption. The application seemed to grow in memory size without bounds when using the debug branch. We have had to use a custom version of the gem where we essentially bypass the problem to avoid it translating into an end user 5xx error for now. Unfortunately not meaningful debug information could be retrieved when using the gem the first time as the server would go critical shortly after the code was used and become extremely unresponsive.

mbasset commented 8 years ago

Should mention we are using ruby 2.2.4 with rails 4.2.5.1 and a whole lot of other gems.

kch commented 8 years ago

@mbasset hum I do store a lot of stuff during the request in the debug branch, but it should all expire after that. I have an idea about how to do this without logging every damn access to env. I'll update the branch when I can. Hopefully soon.

kch commented 8 years ago

@DSAMPAT yeah the branch bypasses the error, but it logs a bunch of stuff when it happens. I'm looking for log lines containing source=rack-timeout-debug. Can you search your logs for some?

kch commented 8 years ago

@mbasset @DSAMPAT alright, I've updated the branch with new code. It should be a lot easier on your memory and logs. It'll only log the trace at the moment the rack-timeout key disappears from env.

We'll still be looking for log lines with source=rack-timeout-debug.

DSAMPAT commented 8 years ago

@kch Have you made the change on the actual release? The errors were occurring every 2 to 4 mins and stopped last night at around your last comment.

EDIT: The error just started again :-(

kch commented 8 years ago

I made the changes in the branch. If you bundle updated it'd update the branch.

kch commented 8 years ago

@DSAMPAT if you're seeing the errors then do you have the log lines that I need?

DSAMPAT commented 8 years ago

@kch The gem doesn't work after bundle update was done. It runs on my local machine, but does not work on Heroku. Can you do rc version? Then I can lock it in the gemfile to confirm that it is not any other gem causing the app to not compile. I think the Heroku bundler has an issue with using a branch.

No logs with source=rack-timeout-debug. Just the same old " #12] ERROR -- : listen loop error: undefined method `state=' for nil:NilClass (NoMethodError) "