Thread safe middleware

[ayanko]

Existing implementation is NOT thead-safe.

That produces unexpected errors. See https://github.com/ruby-grape/grape/issues/1054 for details.

That's because ActiveSupport::Notifications.subscribe/unsubscribe is called in request cycle. And it's not thread-safe because of ActiveSupport::Notifications::Fanout:

https://github.com/rails/rails/issues/5531#issuecomment-4664316

Yes, the Fanout class is definitely not thread safe. But the subscribe / unsubscribe methods should be called on boot before any request threads are spun up.

New implementation should be thread-safe so that we can use grape with Puma, etc ...

[abner]

:+1: Using grape with puma and Jruby. I'm just facing this problem

[dmitry]

@ayanko please rebase to one commit. @aserafin please merge afterwards, it really should be fixed.

[ayanko]

Rebase? What for?

[dmitry]

At the moment here are 2 commits. Can you please merge them together and rebase your branch?

[ayanko]

I still don't see any reason to do this. Merge is pretty good enough.

[Strnadj]

@ayanko Iam trying your implementation and I found a problem https://github.com/ayanko/grape_logging/blob/master/lib/grape_logging/middleware/request_logger.rb#L51 why there is response[0] ? My code fails with ERROR -- undefined method `downcase' for 0:Fixnum, original implementation is only response without trying to get a first element..

[dmitry]

@Strnadj what version of grape do you use?

[Strnadj]

The last one..

 bundle install | grep grape
 Using grape 0.13.0

[Strnadj]

I've endup with sending status (https://github.com/netbrick/grape_logging/blob/master/lib/grape_logging/middleware/request_logger.rb#L51), maybe there is a place for refactoring? Provide for formatter full response, instead of just status... After you merge @ayanko PR, I can quickly modify it ...

[ayanko]

@Strnadj It depends how middleware is mounted into rack stack

Response can be either

• Rack::Response
• Array

According to Rack Spec it should be array

A Rack application is a Ruby object (not a class) that responds to call. It takes exactly one argument, the environment and returns an Array of exactly three values: The status, the headers, and the body.

But some people don't follow spec ...

[Strnadj]

Yes that's true, Iam getting an Instance of Rack::Response, but could you tell me where is written in Rack::Response class, that [0] accessor method returns to you a status?

Iam seeing only aliasing to get headers here (https://github.com/rack/rack/blob/master/lib/rack/response.rb#L107)

so it can be an explanation of my error - he try to downcase the key to find a proper value of header.

[Strnadj]

One last thing for your information, Iam not using something special as middleware - grape, rack, puma and my fork of grape_logging.

As you can see here: https://gist.github.com/Strnadj/a1e306f44dc6a6b502da

[ayanko]

@Strnadj I added "improvement".

[ayanko]

But anyway looks like original author is sleeping ...

[aserafin]

Not sleeping but with a lot on my head right now ;) I will have two less busy days end of next week to take a look and merge 20.11.2015 4:53 PM "Andriy Yanko" notifications@github.com napisał(a):

But anyway looks like original author is sleeping ...

— Reply to this email directly or view it on GitHub https://github.com/aserafin/grape_logging/pull/17#issuecomment-158439749 .

[Strnadj]

@ayanko Thanks :+1:

[ayanko]

Any progress?

[aserafin]

Yes :) I've noticed that you removed ActiveSupport::Notifications.unsubscribe(@subscription) if @subscription from the code. It was reported before that without unsubscribing active support notifications cause memory leaks. Did you do this on purpose or simply overlooked?

[ayanko]

That's main solution. You don't need re-subscribe each time!

[johnthethird]

I dont think this is right. The middleware initialize gets called on every request, so you will continually be subscribing.

Please see this PR https://github.com/aserafin/grape_logging/pull/18 for an alternative approach that I believe is more correct.

[ayanko]

@johnthethird That's is only your meaning. it depends on which level you will use this middleware.

This one is designed to be used as "global" one so initialize will be invoke only once:

When you use it in config.ru:

...
use GrapeLogging::Middleware::RequestLogger, {logger: MyLohger, another_options...}
...

So this implementation is still correct.

[johnthethird]

@ayanko Ahh yes you are correct. Thank you for clarifying.

[johnthethird]

As an FYI, I was getting tripped up by this Grape bug https://github.com/ruby-grape/grape/pull/1201 which calls each middleware initialize on every request.

[grozen]

Having faced an issue similar to the one this aims to address (specifically, https://github.com/rails/rails/issues/20447) I took a peek to see if this can help and am actually wondering about a few things:

• What's the motivation for no longer inheriting from Grape::Middleware::Base?
• Isn't the new DB time calculation slightly (or not so slightly) inaccurate? The measurement is not guaranteed to only take the DB operation into account, seeing how the init_db_runtime is invoked before calling the app itself, which may do some other things before actually calling the DB.

Also, there is a chance that all this will do is add a circumvention of a deeper lying issue that has nothing to do with grape_logging itself, at the cost of making the code less simple. There's no real reason for the ActiveSupport::Notifications::Event's duration to be nil, which is the real guilty party here. See how the issue you originally referenced was possibly treated in the course of https://github.com/rails/rails/issues/12069 (specifically, https://github.com/rails/rails/commit/45318e4010e4f6303ef740bf159d2803c28acc7a, which seems to contain changes similar in spirit to what you did).

It was possibly not fixed enough, however, as this sort of problem has been resurfacing as of late.

[Ben-M]

@aserafin what's the plan with this and https://github.com/aserafin/grape_logging/pull/18? Now that ruby-grape/grape#1201 is in place ActiveSupport::Notifications.unsubscribe(@subscription) is unnecessary.

[aserafin]

@ayanko thanks for contributing :) Very similar approach have been merged with #16 so I will close this PR now

[Ben-M]

@aserafin the approach merged in #16 prevents us from being able to override the behaviour in a child class. Would you be open to a pull request in which the subscription happens in the initialiser, much like this PR?

[aserafin]

@Ben-M sure, I have nothing against moving this to initializer