Detect if the middleware is already loaded and prevent it from being loaded twice

[dbackeus]

We're running a Rails 6 app on Heroku with rack-timeout initialized with: config.middleware.use Rack::Timeout, service_timeout: 25, wait_timeout: 25

The errors we see in our exception tracking look legit, eg:
Rack::Timeout::RequestTimeoutError (Request waited 6ms, then ran for longer than 24994ms )

However what actually happens is that the requests timeout after pretty much exactly 15 seconds every time.

From the browsers point of view:

From the logs:
08 Dec 2020 09:26:40.810256 <190>1 2020-12-08T08:26:40.4593+00:00 app web.1 - - E, [2020-12-08T08:26:40.459200 #153] ERROR -- : source=rack-timeout id=e14e9348-e767-4b66-82aa-8c32821a0b3b wait=6ms timeout=24994ms service=15000ms state=timed_out

(note that we have timeout=24994ms but service=15000ms)

What's going on here?

[wuputah]

This is quite weird. My best guess is you may have the middleware loaded twice (though the behavior you're seeing still doesn't make sense to me, even if that is true), or there's something about the use of .use rather than .insert_before that is causing weird behavior. Please see https://github.com/sharpstone/rack-timeout#rails-apps-manually and make sure it's being loaded appropriately.

From what I remember, you can check which middleware are loaded with rake middleware, but you might need to run rake -T to check what the actual name is.

[dbackeus]

Thanks for the reply.

You are correct that we had the middleware included twice. This is an old code-base so perhaps our implementation pre-dates when you started auto-adding the middleware to Rails applications? Will try to sort this out and confirm if it fixes the issue.

Meanwhile I'm still concerned about the error / log messages. Seems odd that a time close to 25s would be stated when in fact only 15s have passed. Perhaps they could be improved?

[wuputah]

I am also confused by the logging. Can you confirm the version number you are/were running?

[wuputah]

Ah, I suspect the reason why is because the info that is ultimately displayed in the logs is "shared" between all instances of Rack::Timeout (obviously, only 1 instance is intended), since it all goes into the same key in the Rack request environment hash.
https://github.com/sharpstone/rack-timeout/blob/master/lib/rack/timeout/logging-observer.rb#L43

[dbackeus]

Sorry for the slow feedback here.

Can you confirm the version number you are/were running?

We were and are running the latest version of rack-timeout.

Can also confirm that removing the duplicate initialization fixed the issue.

Merry Christmas :)

[wuputah]

I think the only way to solve this problem directly is to check the middleware stack in the Railtie to see if it's already loaded:
https://github.com/sharpstone/rack-timeout/blob/master/lib/rack/timeout/rails.rb#L7

However, it could still happen where the middleware is loaded again after the Railtie fires, which I don't think is preventable or detectable from inside the middleware itself.

Rack Timeout could set and/or check something in the request env to see if it's already touched the request, which would indicate the middleware was loaded multiple times, and provide an opportunity to either present a warning and/or not process the request through the middleware a second time.

[kkohrt]

@dbackeus - I had the same issue, and solved it by "swapping" the middlewhere inserted by the gem via the Railtie code that @wuputah referenced with a version that would use different initial values.
In short, instead of doing

config.middleware.use Rack::Timeout, service_timeout: 25, wait_timeout: 25

you should be able to use

config.middleware.swap Rack::Timeout, Rack::Timeout, service_timeout: 25, wait_timeout: 25

[schneems]

Some ideas/thoughts

• Use an API to either inspect or delete the current middleware: I see from Rails docs that config.middleware.delete is an API for removing an existing middleware. If this is idempotent and does not raise an error when you call it with a class that is not on the middleware stack then we could use it in the railtie.
• Add a warning from Rails: In the config.middleware.* methods we could add a check to see if that class (or an instance of that class) has already been added. This would at least alert people to the problem earlier. The downside is that some people might be intentionally including the same class as different instances to achieve some goal via some pattern. The warning behavior would need to be disabled via a flag or env var. We could also allow people to error/raise when this happens instead of a warning.
• Something else?

I'm not planning on working on this. If someone else wants to take a stab, open a PR here, or open one against Rails and then add a link back on this thread so people can chime in. If you send a PR for this to rack-timeout, I would want an codetriage.com/example_app that demonstrates the problem and can be solved by using your branch so that I can verify independently that it does what it says it does. For regressions, having the behavior tested would be better. But such a test is non-trivial (I think) and might slow the suite down (though I'm happy to be proven wrong).

[germanotm]

I fix the load twice problem by putting a require: false in gemfile and them requiring it on initializer with correct service_timeout.

# Gemfile
gem "rack-timeout", '~> 0.6.3', require: false

# config/initializers/rack_timeout.rb
require 'rack/timeout/base'
Rails.application.config.middleware.use Rack::Timeout, service_timeout: 30