22

I believe the default behavior of rails logging on production is to not output the rendering of all partials. This should log in development but not on production.

However, I'm seeing this in production and I'm not sure how to remove it. My logs are too noisy. My production environment is Heroku running Unicorn and using Papertrail to view my logs. I know Unicorn does some wonky stuff with logs and to get them working properly in the first place I had to add this to my production.rb:

  config.logger = Logger.new(STDOUT)
  config.logger.level = Logger.const_get('INFO')

( Explained here: http://help.papertrailapp.com/kb/configuration/unicorn )

But even with log_level INFO I'm seeing huge blocks of these in all my logs:

Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_caption.html.erb (0.7ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_rights.html.erb (2.1ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_category.html.erb (4.8ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_caption.html.erb (0.3ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_rights.html.erb (0.4ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_category.html.erb (4.4ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_caption.html.erb (0.3ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_rights.html.erb (0.3ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_category.html.erb (1.8ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_caption.html.erb (0.4ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_rights.html.erb (4.6ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_category.html.erb (2.1ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_caption.html.erb (0.3ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_rights.html.erb (0.4ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_category.html.erb (4.1ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_caption.html.erb (0.2ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_rights.html.erb (1.8ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_category.html.erb (6.0ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_caption.html.erb (0.5ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_rights.html.erb (0.8ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_category.html.erb (1.9ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_caption.html.erb (0.3ms) 
Jun 25 22:15:15 tacktile app/web.1:    Rendered photos/pieces/_rights.html.erb (0.7ms)
Jared Beck
  • 16,796
  • 9
  • 72
  • 97
Keith Schacht
  • 1,998
  • 15
  • 23
  • Have you done `heroku config:add LOG_LEVEL="info"`? – Deej Jun 26 '13 at 12:22
  • David, yes. And I've tried setting it at "debug" vs "info" to confirm that the verbosity changes. Indeed it does. But even at "info" level I still get all these rendered statements. I'm sure I can turn it down even further and hide them. But the verbosity is great *except* for these "rendered" statements for all the partials. I'd like to figure out how to hide just those. – Keith Schacht Jun 26 '13 at 18:25
  • See also this answer: http://stackoverflow.com/a/12003652/514483 – robd May 22 '14 at 09:26

5 Answers5

24

For Rails 4 (at least):

Try this in your config/environments/development.rb

config.action_view.logger = nil
Patrice Gagnon
  • 1,276
  • 14
  • 14
  • 1
    NOTE: This is an "all or nothing" option -- it is not just for hiding partial view logs. It hides *all* view logging. (Which can be useful for debugging and trying to see specific output without being buried in view log verbosity.) – Jon Kern Jun 12 '19 at 01:01
8

Use Lograge, it removes rendering times for partials

Yarin
  • 173,523
  • 149
  • 402
  • 512
  • 1
    To expand a bit on this imo incomplete/inaccurate answer: Lograge is a gem that changes the default logging format for Rails (plug 'n play). Instead of logging tons of different lines for each request it tries to fit all the relevant information into one line (request data/controller/timing etc.), using a key-value format. Partials rendering logging is disabled/skipped in the process since it is considered non-essential (at least on production systems). So yeah, I do agree that it's the best way to reformat Rails logging, but it doesn't just "remove rendering times for partials"... – fgblomqvist Feb 04 '19 at 16:09
  • 1
    Worth noting that lograge changes the order of logs, which might not be ideal for some. – steel Feb 11 '19 at 20:40
3

Instead of completely disabling actionview logging (as described in another answer), I opted to change the logging level for rendering to DEBUG. This way, it can be easily omitted from production logs by setting the log level to INFO or higher.

Note, this is for rails 5.2. I'm unsure if it would work on other versions.

module ViewLoggingOverride
  def info(progname = nil, &block)
    logger.debug(progname, &block) if logger
  end
end

ActionView::LogSubscriber.include(ViewLoggingOverride)

Relevant rails code:

https://github.com/rails/rails/blob/5-2-stable/actionview/lib/action_view/log_subscriber.rb

https://github.com/rails/rails/blob/5-2-stable/activesupport/lib/active_support/log_subscriber.rb#L93-L99

RyanB
  • 707
  • 1
  • 5
  • 18
2

I got the following answer from a papertrail:

I think the quickest way to deal with this is to use our log filtering functionality. That'll let you drop anything that matches a regex and will save you from having to make any app configuration changes.

In the longer term, you'll probably want to silence these messages at source. Lograge is probably your best bet for that. You may find it also removes a few other bits but give it a go and let me know what you think.

I know this is probably irrelevant to you at the moment, but for future use you might also find some other useful tips here. It covers lograge, removing static asset requests and unnecessary actions,

Let me know if you need help with anything mentioned above.

Keith Schacht
  • 1,998
  • 15
  • 23
1

This is so common that, in Papertrail emails notifying you of a logging spike, there is a link with this exact example.

This is the link.

I tweaked the regex a bit:

/\A\s{3}Rendered \w+\/_.+\.erb \(\d+\.\d+ms\)\z/

PS: I always found it odd they are printed at info level in the first place.

ecoologic
  • 10,202
  • 3
  • 62
  • 66