Browse files

Log newlines separately to ensure the 'Started GET ...' line has a ta…

…g on the same line
  • Loading branch information...
1 parent 59f8315 commit d1cbcd781bdb974c4232c3d63e3d1b4d1f9c4bd5 @jeremy jeremy committed Sep 25, 2012
Showing with 2 additions and 1 deletion.
  1. +2 −1 railties/lib/rails/rack/logger.rb
View
3 railties/lib/rails/rack/logger.rb
@@ -22,7 +22,8 @@ def call(env)
def call_app(env)
request = ActionDispatch::Request.new(env)
path = request.filtered_path
- Rails.logger.info "\n\nStarted #{request.request_method} \"#{path}\" for #{request.ip} at #{Time.now.to_default_s}"
+ Rails.logger.info "\n\n"
+ Rails.logger.info "Started #{request.request_method} \"#{path}\" for #{request.ip} at #{Time.now.to_default_s}"
@app.call(env)
ensure
ActiveSupport::LogSubscriber.flush_all!

11 comments on commit d1cbcd7

@wlipa

A more general fix would be to tag each line inside the logger (ie, split the logged string by /n before applying the tags). That's what anyone grepping for a tag will want.

@jeremy
Ruby on Rails member

That'd mean splitting log messages, though, perhaps inappropriately for syslog/logstash/etc.

The double-newline here is just to put a space in the development logs. I'd prefer to remove that entirely, or perhaps do it in dev mode only.

@tenderlove
Ruby on Rails member

@jeremy 👍 :+9000:

@jeremy
Ruby on Rails member
@tenderlove
Ruby on Rails member

💄👮❤️👨

I KISS YOU 👬

@jeremy
Ruby on Rails member

😁

@ifightcrime

This change caused logs to go from having two empty lines, to three empty lines before requests because of the extra newline added by the additional info call. To impart no change to formatting, line 25 should have been Rails.logger.info "\n" instead. It looks like this has basically been brought forward into the newest code as well (https://github.com/rails/rails/blob/master/railties/lib/rails/rack/logger.rb#L32-L33), where there only needs to be one debug statement instead of two.

I'm probably nit-picking, but we use the double newline to parse our logs into Splunk so this has caused a bit of a ruckus. In part due to c131211 as well (only enabling the extra lines in development). For now I've just been monkey patching this sucker. Maybe it doesn't matter anymore since it's only in development, and that's fine, but thought I would bring it up anyway in case it has caused trouble for anyone else.

Also, it looks like this happened a while back in afde6fd too, but it was reverted in c83d9a1.

Before:

130417 13:22:50 [INFO]::

Started GET "/blah" for 127.0.0.1 at 2013-04-17 13:22:50 -0500

After:

130417 13:59:58 [INFO]::


130417 13:59:58 [INFO]:: Started GET "/blah" for 127.0.0.1 at 2013-04-17 13:59:58 -0500

(ignore the custom timestamp prefixes)

@steveklabnik
Ruby on Rails member

Can you submit that as a PR, please?

@wlipa

It would be nice if the request-separating behavior was more pluggable, as different people want different things in their log output.

@ifightcrime

What about even adding a config option or something to set the separator? That would be cool.

Then you could also set it per environment and avoid the conditional for only development that's there now. config.logger_request_separator = "\n\n" or something. Obviously it'd be nice to keep the config options to a minimum, but this may just be a good case. Any other ideas? I'm ready to implement!

@wlipa

It'd also be nice if the lines:

# Put some space between requests in development logs.
Rails.logger.info "\n\n" if Rails.env.development? 

were split off into a separate method so they could be more easily overridden.

Please sign in to comment.