Formatting of Rails logs when using ActiveRecord

Question

So I have an application that earlier did not need ActiveRecord - thus we removed ActiveRecord from the application and formatted our logging as such:

In application.rb:

class DreamLogFormatter < Logger::Formatter
  SEVERITY_TO_COLOR_MAP   = {'DEBUG'=>'32', 'INFO'=>'0;37', 'WARN'=>'35', 'ERROR'=>'31', 'FATAL'=>'31', 'UNKNOWN'=>'37'}

  def call(severity, time, progname, msg)
    color = SEVERITY_TO_COLOR_MAP[severity]
    "\033[0;37m[%s] \033[#{color}m%5s - %s\033[0m\n" % [time.to_s(:short), severity, msg2str(msg)]
  end
end

class ActiveSupport::BufferedLogger
  def formatter=(formatter)
    @log.formatter = formatter
  end
end

In development.rb

config.logger = Logger.new("log/#{Rails.env}.log")
config.logger.formatter = DreamLogFormatter.new
ActiveResource::Base.logger =  Logger.new("log/#{Rails.env}.log")
ActiveResource::Base.logger.formatter = DreamLogFormatter.new

Note: The ActiveResource logger configuration was added because we want the URL output of our ActiveResource calls like so:

GET http://localhost:2524/users/
 --> 200 OK 239 (13.0ms)

Logging with this configuration gave us a nice output combination of ActiveResource calls and our own logging using Rails.logger.

However, we have needed to add ActiveRecord back into our application as we needed to change our session storage from cookie store to ActiveRecord store. And since adding ActiveRecord back in, the logging is no longer working nicely.

Previous Log Output:

Started GET "/audit/?key1=value1&key2=value2" for 0:0:0:0:0:0:0:1%0 at 2012-08-15 15:39:58 -0400
[15 Aug 15:39]  INFO -   Processing by AuditController#index as HTML
[15 Aug 15:39]  INFO -   Parameters: {"utf8"=>"✓", "key1"=>"value1", "key2"=>"value2"}
[15 Aug 15:39]  INFO - GET http://localhost:2524/api/users/jeff/prefs/?label=language
[15 Aug 15:39]  INFO - --> 200 OK 151 (55.0ms)
[15 Aug 15:39]  WARN - There is no user currently logged in - retrieving default theme.
[15 Aug 15:39]  INFO - GET http://localhost:2524/api/users/jeff/prefs/?label=theme
[15 Aug 15:39]  INFO - --> 200 OK 151 (35.0ms)

Note: What I really enjoy about this format is each request is logged beginning with a Started GET <URL> or POST or PUT, etc - followed by which controller and function is doing the processing and what the parameters sent are. This is extremely helpful for debugging. As well, this format allowed us to print out our own Rails.logger logging information.

Current Log Output (With ActiveRecord):

[20 Aug 11:40]  INFO - GET http://localhost:2524/api/users/jeff
[20 Aug 11:40]  INFO - --> 200 OK 199 (144.0ms)
[20 Aug 11:40]  INFO - GET http://localhost:2524/api/users/jeff/prefs/?label=language
[20 Aug 11:40]  INFO - --> 200 OK 148 (12.0ms)
[20 Aug 11:40]  INFO - GET http://localhost:2524/api/users/jeff/prefs/?label=theme
[20 Aug 11:40]  INFO - --> 200 OK 155 (15.0ms)

Essentially all we get now is a constant stream of URL calls - it doesn't log anything coming from Rails.logger and also there is no separation between different requests - it is literally just one constant stream of URL's and responses.

---

I have tried setting ActiveResource::Base.logger = ActiveRecord::Base.logger as a lot of the blogs recommend but that just made things worse - it logged a couple URLs, and then just stopped logging completely unless it was at ERROR level (and nowhere do I set the logging level, so it should still be at default)

Any help or suggestions would be greatly appreciated!! Thanks

Answer 1

Maybe the implementation of lograge will help:

https://github.com/roidrage/lograge/blob/master/lib/lograge.rb#L57