methodoverride does not appear anywhere in logs #426

Closed
dlee opened this Issue May 6, 2011 · 12 comments

Comments

Projects
None yet
3 participants
Contributor

dlee commented May 6, 2011

Right now, when you issue a PUT request using the _method param method override, it's not indicated anywhere in the logs. The _method parameter is stripped from the Parameters line, and the log says it was a POST request:

Started POST "/post/1" for 127.0.0.1 at 2011-05-06 16:15:58 -0700
  Processing by PostsController#update as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"pirld4RhMa0a3LRTVKGPg+KRa8Cr3To/aeyxsr4pXRI=", "name"=>"a", "commit"=>"Save changes", "id"=>"1"}
Contributor

josevalim commented May 7, 2011

When "Started POST" is logged, we still haven't passed through the method override middleware. I think the sanest fix is to include _method in the Parameters. That is handled here:

https://github.com/rails/rails/blob/master/actionpack/lib/action_controller/log_subscriber.rb#L5

What do you think?

Contributor

dlee commented May 7, 2011

Sounds good to me. I'll cook up a patch.

dlee added a commit to dlee/rails that referenced this issue May 7, 2011

Don't hide _method param in logs; Issue #426
Hiding the _method param leaves no indication in the Rails log that a request
would be interpreted by the Rails app according to the method override.
Owner

dhh commented May 7, 2011

We need to fix the "Started POST" part. Whatever is outputting that needs to look at _method. This used to work, so let's not go backwards.

Contributor

dlee commented May 7, 2011

Alright, so this is a regression.
I think we should indicate somewhere in the logs both the original method and the overridden method.

josevalim's suggestion does this the easy way by showing the original method in the "Started ..." part and the overridden method in the params.

If you think that that's backwards, we can do something like "Started PUT (overrides POST)". What do you think?

Owner

dhh commented May 7, 2011

When will the "(overrides POST)" be a valuable piece of information? By the time Rails sees the request, Rails won't be able to tell whether it's a real PUT or an artificial PUT.

Contributor

dlee commented May 7, 2011

I'd argue that showing the overrides would be useful in various debugging and analytic situations. Also, it could be useful in distinguishing whether or not the request was made by a browser. Rails certainly has the internal ability to differentiate between real and artificial put requests, and applications built on Rails should have the ability as well if they can access the rack env.

Owner

dhh commented May 7, 2011

I don't think it's a valuable enough piece of information to log with every request in the log. If you need it, you can always get at it directly via code. Or if you need it temporarily for debugging, you can do logger.info and output it yourself.

But let's definitely fix the core issue as described at the top of this ticket.

Contributor

dlee commented May 7, 2011

Sounds like a plan.

@ghost ghost assigned dhh May 7, 2011

Contributor

dlee commented May 7, 2011

I actually went with a different approach since I assumed there was a reason the "Started ..." log was separated into railties/lib/rails/rack/logger.rb in the first place. Expect a pull request soon...

Contributor

josevalim commented May 7, 2011

Ok, but if the another approach is including a new middleware, I would say it is a no-go. :) Our middleware stack is already too long, which leads to a long call stack that Ruby 1.8.x doesn't like at all. Maybe we could log at the router level? Thanks for your time in this.

Contributor

josevalim commented May 7, 2011

Closing this one in favor of #430.

@josevalim josevalim closed this May 7, 2011

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