Skip to content
This repository

Fix Issue #2639: "Served asset log messages are pretty annoying!" by adding config variable #3795

Closed
wants to merge 1 commit into from
Cisco Riordan

Addresses issue #2639 (#2639) -- there are many assets related log messages and no config variable to hide them. Example log lines:

Started GET "/assets/logo.png" for 127.0.0.1 at 2011-11-24 01:22:02 -0800
Served asset /logo.png - 200 OK (1ms)

With these commits, both asset related logger messages (Sprockets and Rack) can be hidden with a config variable. By default the messages still appear.

To hide the messages, add this line to e.g. application.rb:

config.assets.logger = false

Note: This is a replacement for #3741 (closed), squashed into one commit and no longer hiding the messages by default.

Cisco Riordan

I did some benchmarking. There seems to be a small performance boost from the commit, since it causes Rack to use the Rails logger less frequently.

This gist (https://gist.github.com/1404199) includes a file for the benchmarking code and files for sample output both with and without the config variable config.assets.logger = false.

In each benchmark report, the first and third lines use before_dispatch(env) as it was before my commit, and the second and fourth lines use before_dispatch(env) (renamed before_dispatch_modified(env) here) from my commit. I repeat each, in alternating order, to help account for normal benchmarking fluctuations.

If you include config.assets.logger = false there are fewer calls to the Rails logger and that results in slightly improved performance. For users who do not include the config variable, there is no performance cost (as measured by the benchmark module).

Without the config line specified, the conditional that I added immediately evaluates to true in every case. In the benchmarking reports, sometimes the before_dispatch(env) is faster, sometimes before_dispatch_modified(env) is.

Started GET "/assets/application.css?body=1" for 127.0.0.1 at 2011-11-29 03:04:24 -0800


Started GET "/assets/application.css?body=1" for 127.0.0.1 at 2011-11-29 03:04:24 -0800


Started GET "/assets/application.css?body=1" for 127.0.0.1 at 2011-11-29 03:04:24 -0800


Started GET "/assets/application.css?body=1" for 127.0.0.1 at 2011-11-29 03:04:24 -0800
Served asset /application.css - 200 OK (1ms)
      user     system      total        real
  0.000000   0.000000   0.000000 (  0.000178)
  0.000000   0.000000   0.000000 (  0.000125)
  0.000000   0.000000   0.000000 (  0.000088)
  0.000000   0.000000   0.000000 (  0.000091)

With the config line config.assets.logger = false included, sometimes the conditional evaluates to true and logs (if the path doesn't start with "/assets/"), sometimes to false (if it does start with "/assets/"). Performance is consistently faster than without the config line for false evaluations, and true evaluations have results that are similar to the no-config results.

Started GET "/assets/application.css?body=1" for 127.0.0.1 at 2011-11-29 03:03:18 -0800


Started GET "/assets/application.css?body=1" for 127.0.0.1 at 2011-11-29 03:03:18 -0800
      user     system      total        real
  0.000000   0.000000   0.000000 (  0.000191)
  0.000000   0.000000   0.000000 (  0.000075)
  0.000000   0.000000   0.000000 (  0.000114)
  0.000000   0.000000   0.000000 (  0.000063)

So there seems to be a side benefit of a performance gain of a few ten-thousandths of a second for each request.

Piotr Sarnacki drogus commented on the diff December 10, 2011
railties/lib/rails/rack/logger.rb
@@ -21,8 +21,12 @@ def before_dispatch(env)
21 21
         request = ActionDispatch::Request.new(env)
22 22
         path = request.filtered_path
23 23
 
24  
-        info "\n\nStarted #{request.request_method} \"#{path}\" " \
25  
-             "for #{request.ip} at #{Time.now.to_default_s}"
  24
+        # If config.assets.logger is set to false, only log non-assets related requests
  25
+        if ((Rails.application.config.assets.logger != false) || 
1
Piotr Sarnacki Collaborator
drogus added a note December 10, 2011

You should not use Rails.application here, please see how it's done in case of other similar options: https://github.com/ciscoriordan/rails/blob/4928434455c9a89197fda106534f57f6b319184c/railties/lib/rails/application.rb#L121

/cc @josevalim

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

can you send a PR for master branch instead of 3-1-stable?

aaronchi

Can we PLEASE get something like this in before 3.2 final?

José Valim
Owner

I don't think we should mute both loggers, just one. That said, +1 for config.assets.logger but besides setting it to false, we could also configure sprockets logger through it and therefore use the same logger as Rails, but with increased severity. In other words, I am fine with changes in sprockets/railties (and they could be improved) but I don't think we should change rails/rack/logger. Thanks.

David Phillips

How do we suppress the request log messages without changing rails/rack/logger? The purpose here is to get rid of ALL log messages related to assets. Having these in the log makes it much less useful for development.

José Valim
Owner

We are not special casing the rails logger middleware to get rid of it. As I said, I will gladly accept a patch that allows you to turn off sprockets logger, but we won t special case the middleware.

José Valim
Owner

Someone please submit a new pull request, because I think the original author won't.

José Valim josevalim closed this December 28, 2011
Dmitriy Kiriyenko

+1 to @electrum: How do we suppress the request log messages without changing rails/rack/logger? I agree with @josevalim that special casing the logger middleware, but in the meantime, it would be great if we could get rid of logging the requests that are served by assets.

Manu J

@josevalim If the change is not made in rails/rack/logger then the only other place it can be made is https://github.com/rails/rails/blob/master/activesupport/lib/active_support/tagged_logging.rb#L29 ?

In that case if the user sets a custom logger, the log file will again contain the requests. So IMO the logical place to change it is rack logger since it will work for all loggers.

Correct me If I'm wrong :)

José Valim
Owner

Let me rephrase: Rails won't special case any of the loggers or logger related middlewares to not log specific routes. If you want, you can inherit from the Rails::Rack::Logger in your app and special case it. Meanwhile, to be a bit less verbose, Rails added an option to change Sprockets logger, so you can set it to a higher level like warn/fatal.

ara.t.howard

this is really unfortunate. we should not be required to use monkey patches like this: https://gist.github.com/2036895

it's not uncommon, in real apps, to want to shut the logger up for a bit.

ara.t.howard

er. should not be...

Marco A. Peraza

The current state of this is terrible. You should not have to jump through hoops to make the logger actually useful. 99% of the time you don't want your development logs filled up with noise from the assets being requested. The rails server log is functionally broken as it stands.

If you want to maintain the purity of the logger, then maybe it can be monkey patched within the development environment configuration.

Adam Spiers

@MarcoPeraza is absolutely right. Whatever happened to "convention over configuration"?! The cleanest solution I can find out there is the quiet_assets gem which monkey-patches Rails::Rack::Logger. If so, that's a sad state of affairs indeed, considering the large number of developers who have fallen foul of this.

@josevalim, your comment above has been linked to at least twice, by @guilleiguaran here and here as "details about why we won't silent the request logs", but that's very misleading, because your comment doesn't cover why this functionality won't be implemented at all; it simply says that it won't be.

By "you can inherit from the Rails::Rack::Logger in your app and special case it", you seem to be suggesting that every single Rails developer who doesn't want spam in their development log should become a Rack specialist and reinvent the same wheel?! Maybe that wasn't the message you intended, but that's how it comes across.

I see that sprockets will log more silently in Rails 4.0. That's great, but what about ActionPack?

To be clear, I am not necessarily disagreeing with your decision not to make Rails special-case middleware. But given the number of developers who have been bitten by this, I am strongly disagreeing with how this is being handled in terms of (a) finding an alternative user-friendly solution, and (b) communication and documentation of that solution. When a solution based on monkey-patching receives over 240 up-votes on StackOverflow then that is a sure sign that something has gone badly wrong.

Christian Seiler
csmuc commented March 19, 2013

@aspiers thank you for the words, this is as far as you can get from the initial Rails spirit IMO

williscool

so did this happen on master (re #4512) or not happen?

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

Showing 1 unique commit by 1 author.

Nov 29, 2011
Cisco Riordan Allow users to hide assets logger messages with 'config.assets.logger…
… = false' in an environment config file
4928434
This page is out of date. Refresh to see the latest.
3  actionpack/lib/sprockets/railtie.rb
@@ -21,8 +21,9 @@ class Railtie < ::Rails::Railtie
21 21
 
22 22
       require 'sprockets'
23 23
 
  24
+      # Don't display Sprockets log messages if config.assets.logger is false in envrionment
24 25
       app.assets = Sprockets::Environment.new(app.root.to_s) do |env|
25  
-        env.logger  = ::Rails.logger
  26
+        env.logger  = ::Rails.logger unless config.assets.logger == false
26 27
         env.version = ::Rails.env + "-#{config.assets.version}"
27 28
 
28 29
         if config.assets.cache_store != false
8  railties/lib/rails/rack/logger.rb
@@ -21,8 +21,12 @@ def before_dispatch(env)
21 21
         request = ActionDispatch::Request.new(env)
22 22
         path = request.filtered_path
23 23
 
24  
-        info "\n\nStarted #{request.request_method} \"#{path}\" " \
25  
-             "for #{request.ip} at #{Time.now.to_default_s}"
  24
+        # If config.assets.logger is set to false, only log non-assets related requests
  25
+        if ((Rails.application.config.assets.logger != false) || 
  26
+          (env['PATH_INFO'].index("/assets/") != 0))
  27
+          info "\n\nStarted #{request.request_method} \"#{path}\"" \
  28
+              " for #{request.ip} at #{Time.now.to_default_s}"
  29
+        end
26 30
       end
27 31
 
28 32
       def after_dispatch(env)
Commit_comment_tip

Tip: You can add notes to lines in a file. Hover to the left of a line to make a note

Something went wrong with that request. Please try again.