middleware ordering not controlled when in threadsafe! mode

[jjb]

if an app is in threadsafe! mode, then the middleware ordering won't be controlled (or maybe the middleware won't be inserted at all? not sure)

https://github.com/Octo-Labs/heroku-request-id/blob/master/lib/heroku-request-id/railtie.rb

given that threadsafe! will be on by default in rails 4, and in general is now recommended even for single-threaded apps, this should probably be accounted for.

[jjb]

here's an idea -- it would be nice to copy the value of the HTTP_HEROKU_REQUEST_ID into HTTP_X_REQUEST_ID so that ActionDispatch:: RequestId can pick it up and use it

If doing this, then perhaps it suggests a better place to inject the middleware:

app.config.middleware.insert_before 'ActionDispatch:: RequestId', "HerokuRequestId::Middleware"

[jagthedrummer]

Hey, @jjb, thanks for the ideas. You're right that the current implementation would not get reliable loading order in threadsafe mode. I like the idea about copying the header value. I think inserting before ActionDispatch::RequestId could work, but I'm wondering if there's a way to make sure that it loads first.

I also just came across this, which I think we could do to make sure to wrap all middleware :

https://github.com/lukeludwig/rack_timer/blob/master/lib/rack_timer/stack.rb#L59

[jjb]

@jagthedrummer glad you liked the header feature.

back to the middleware discussion: what was the rationale for putting it after Rack::Lock? What criteria should we use to decide where to put it?

[jagthedrummer]

Hey, @jjb. Honestly, I don't remember why it went after Rack::Lock. It maybe that I found some article about adding middleware to the stack inside of a gem, and that's what the article did. I think the criteria is that we want it loaded as early in the stack as possible. Ideally it would be first. Otherwise we have parts of the app response cycle that are running outside of the elapsed time calculation.

[jjb]

gotcha

so, one option is to set it at position 0. it's possible that another
middleware will set itself at position 0 after that, but unlikely, and also
unlikely that it will matter much.

one thing to consider is that if a user IS using rack lock, then it's
probably preferable to keep it inside there like you're doing. so, we could
do "if rack lock is present, inject it before there, otherwise, position 0"

(i don't know how to check if a middleware is present)

[jagthedrummer]

What would be the downside to having it outside of Rack::Lock for apps that are using it? (Or conversely, what's the benefit to having it inside Rack::Lock?)

[jjb]

i was thinking along the lines of what you wanted to measure -- "everything
inside rack lock" is probably a semantically relevant place to start --
although i can't think of any reason that "everything" (position 0) isn't
better, but i think i was sort of subconsciously assuming that you had a
reason :D

[jjb]

(so, if you think measuring everything from position 0 is better, i agree)

On Fri, May 31, 2013 at 1:32 PM, John Joseph Bachir [email protected] wrote:

i was thinking along the lines of what you wanted to measure --
"everything inside rack lock" is probably a semantically relevant place to
start -- although i can't think of any reason that "everything" (position
0) isn't better, but i think i was sort of subconsciously assuming that you
had a reason :D

[jagthedrummer]

I think this should do the trick : 628b99e

[jagthedrummer]

Running a quick test in a dummy app to be sure.

[jagthedrummer]

Looks like that does it.

heroku-request-id-test$ rake middleware
use HerokuRequestId::Middleware
use ActionDispatch::Static
use Rack::Lock
use #<ActiveSupport::Cache::Strategy::LocalCache::Middleware:0x007ffbc919e200>
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use ActionDispatch::DebugExceptions
use ActionDispatch::RemoteIp
use ActionDispatch::Reloader
use ActionDispatch::Callbacks
use ActiveRecord::ConnectionAdapters::ConnectionManagement
use ActiveRecord::QueryCache
use ActionDispatch::Cookies
use ActionDispatch::Session::CookieStore
use ActionDispatch::Flash
use ActionDispatch::ParamsParser
use ActionDispatch::Head
use Rack::ConditionalGet
use Rack::ETag
use ActionDispatch::BestStandardsSupport
run HerokuRequestIdTest::Application.routes

[jjb]

some more meandering thoughts: hardcoding it to 0 rubs me the wrong way and seems like it should only be appropriate for very specific reasons. Which also makes me think maybe timing the request, tracking the id, and writing a log are three different concerns.

here's what the relevant part of one of my app's middleware stack looks like:

use Rack::Lock
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId

hmmm, what's rack::Runtime do?: https://github.com/rack/rack/blob/master/lib/rack/runtime.rb

looks like it times everything below it -- so perhaps:

• you can reuse this work, remove your redundant timing, and use the value of this header in your log output (if you want to support non-rails projects, you can just reuse the rack-timetime middleware)
• this is a semantically tidy place to put your middleware -- instead of after rack-lock, you put it before rack-runtime. it's in the "same" place as before, and keeps it before ActionDispatch::RequestId

drawback: requests for static resources won't be handled.

Thoughts?

getting back to my "maybe timing the request, tracking the id, and writing a log are three different concerns" -- maybe your functionality could be split into two middlewares. one which is concerned with all things regarding heroku request ids, and another which is concerned with all things regarding heroku logs (logs the request id, the request time, and maybe more things in the future).

[jjb]

I should have mentioned: a reason to not use a hardcoded number is that you will be battling for 0th place with other gems, such as the very popular rack-timeout: https://github.com/kch/rack-timeout/blob/master/lib/rack-timeout.rb

[jagthedrummer]

Hmm... those are some good thoughts. Lemme stew on it for a little while.

FYI, I just built and pushed v0.0.7 with the hardcoded 0 spot. v0.0.8 may not be far behind....

[jjb]

more exciting developments: i just tried 0.0.7 locally, with rack::lock enabled (threadsafe! not on), using puma, and when hitting the app with concurrent requests i got a lot of errors like this:

Rack app error: #<ThreadError: deadlock; recursive locking>

I commented out everything in the middleware to see if any of its features in particular are the culprit. i got it down to this and the problem did not go away:

def call(env)
  @status, @headers, @response = @app.call(env)
  [@status, @headers, self]
end

def each(&block)
  @response.each(&block)
end

Puma is multithreaded, so when using puma AND rack::lock, then everything before rack::lock is multithreaded. however, i don't see any non-threadsafe code. I'm suspicious of the use of @@ class variables, this seems atypical. i haven't thought it fully through but, it seems the config should be kept in the instance of the middleware and not in its class. here's an example: https://github.com/rack/rack-contrib/blob/master/lib/rack/contrib/static_cache.rb

another thought: when appending to the body, this has to be done BEFORE the deflate middleware, otherwise it will be appended to a zipped blob instead of to text. So, this is a reason why it absolutely cannot be set at position 0.

[jagthedrummer]

Wow. OK, clearly the loading scheme in 0.0.7 is not good.

I think your idea of inserting before Rack::Runtime makes a lot of sense. That would mean that this gem wouldn't need any timing code at all and could just grab the header.

I'm very surprised that the stripped down version was causing threading issues. I can see how the @@ vars might be an issue, but there weren't even in play in your examples. Strange.

Good point about the deflate middleware.

[jagthedrummer]

OK, first step. Loading in a (hopefully) better place. 705bf74

[jagthedrummer]

I just pushed a change that removes all of the timing code from this gem and relies on the header set by Rack::Runtime. If the header is not there it will just indicate that runtime information is not available. v0.0.9 is the latest gem release. Would you mind giving that a try with your puma test and see how it fares?