Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Stop logging "Nothing to do" #2392

Closed
reggieb opened this issue Dec 11, 2019 · 15 comments
Closed

Stop logging "Nothing to do" #2392

reggieb opened this issue Dec 11, 2019 · 15 comments

Comments

@reggieb
Copy link
Contributor

reggieb commented Dec 11, 2019

At the moment, a "Nothing to do" log entry is being generated every time Webpacker::Compiler#compile is called on non stale compiled packs.

def compile
    if stale?
      run_webpack.tap do |success|
        # We used to only record the digest on success
        # However, the output file is still written on error, (at least with ts-loader), meaning that the
        # digest should still be updated. If it's not, you can end up in a situation where a recompile doesn't
        # take place when it should.
        # See https://github.com/rails/webpacker/issues/2113
        record_compilation_digest
      end
    else
      logger.info "Everything's up-to-date. Nothing to do"
      true
    end
  end

This log entry is unnecessary and I think it should be removed or at the very least set at the :debug level.

@burmashave
Copy link

This log entry is unnecessary and I think it should be removed or at the very least set at the :debug level.

Agreed.

@jakeNiemiec
Copy link
Member

jakeNiemiec commented Dec 19, 2019

If you are seeing this in your log files, it would indicate that webpack is being run when it is not needed. In what context does this cause issues?

@burmashave
Copy link

It's not an 'issue' so much as it's unnecessary. We're being informed of something it didn't do with every request.

This was added in July to "keep the user informed, vs. have them wonder if anything happened". It's just as informative to not see a message when it does nothing as it is to send a message telling us it did nothing.

@jakeNiemiec
Copy link
Member

Understand that this is hard to balance with people who say things aren't verbose enough #955 (comment), #1824, #2312

We're being informed of something it didn't do with every request.

Can you think of any middle ground? I agree that it seems unnecessary for every single request.

@reggieb
Copy link
Contributor Author

reggieb commented Dec 20, 2019

I'd suggest the middle ground is to log it :debug level.

@burmashave
Copy link

Understand that this is hard to balance with people who say things aren't verbose enough #955 (comment), #1824, #2312

Those complaints are about it failing silently. This complaint is about it succeeding noisily.

Can you think of any middle ground? I agree that it seems unnecessary for every single request.

I think @reggieb has a good solution: use :debug level.

@dwightwatson
Copy link
Contributor

Don't mean to hijack if it's unrelated, but are other people seeing this log error multiple times per request?

Started GET "/" for ::1 at 2019-12-23 09:53:34 +1100
Processing by PagesController#index as HTML
  Rendering layouts/application.html.slim
  Rendering pages/index.html.slim within layouts/application
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do  
  Rendered pages/index.html.slim within layouts/application (Duration: 716.1ms | Allocations: 131629)
  Rendered layouts/application.html.slim (Duration: 1632.2ms | Allocations: 251011)
Completed 200 OK in 1635ms (Views: 1632.1ms | ActiveRecord: 1.2ms | Allocations: 252079)

Or is this occurring every time an asset is referred to?

@reggieb
Copy link
Contributor Author

reggieb commented Dec 23, 2019

@dwightwatson That's not hijacking at all. Seems to prove my point.

@rpbaptist
Copy link

rpbaptist commented Dec 30, 2019

@jakeNiemiec

If you are seeing this in your log files, it would indicate that webpack is being run when it is not needed.

This make me wonder. Should I configure something so it doesn't run? I am migrating to containers and after precompiling, I see this message and it's noticably slowing down development and tests. How can I stop webpacker from runnin unnecessarily?

@reggieb
Copy link
Contributor Author

reggieb commented Dec 30, 2019

Surely the very nature of the method structure suggests that it is normal for it to be called often. The comment is only logged when the #compile method call has nothing to do, because the state is not "stale".

@jakeNiemiec
Copy link
Member

How can I stop webpacker from running unnecessarily?

This was my mistake, I was under the impression that dev_server_runner did not need to be explicitly called to run the dev_server (which won't give you that message). https://github.com/rails/webpacker/blob/f848074b916bd8e1d800d86634926adfb3da53e2/lib/webpacker/dev_server_runner.rb

@aka47
Copy link

aka47 commented Mar 9, 2020

We see this in our production.log and this really irritates me. We set compile: true for production in webpacker.yml and I would expect webpacker is not active at all in production with this compile set true.

Am I missing something?

@Freika
Copy link

Freika commented Apr 29, 2020

This is getting kinda ridiculous on localhost:

[ActionCable] Broadcasting to StimulusReflex::Channel:0294526bd8d906f95809e5e6494d2c0c: {"cableReady"=>true, "operations"=>{"morph"=>[{"selector"=>"#nick", "html"=>"Gezar Glitzspanner", "childrenOnly"=>true, "permanentAttributeName"=>"data-reflex-permanent", "stimulusReflex"=>{"target"=>"NickReflex#generate", "args"=>[], "url"=>"http://localhost:3000/en/gw2/asura", "attrs"=>{"class"=>"btn btn-success btn-small text-white", "data-reflex"=>"click->NickReflex#generate", "data-action"=>"nick#generate click->stimulus-reflex#__perform", "data-sex"=>"female", "data-race"=>"asura", "href"=>"#", "data-controller"=>"stimulus-reflex", "checked"=>false, "selected"=>false, "tagName"=>"A"}, "selectors"=>["#nick"], "permanentAttributeName"=>"data-reflex-permanent", "reflexId"=>"425fa8e9-893e-4d38-ade5-e27d2b9e0b08", "last"=>true}}]}}
StimulusReflex::Channel transmitting {"cableReady"=>true, "operations"=>{"morph"=>[{"selector"=>"#nick", "html"=>"Gezar Glitzspanner", "childrenOnly"=>true, "permanentAttributeName"=>"data-reflex-permanent", "stimulusReflex"=>{"target"=>"NickReflex#generate", "args"=>[], "url"=>"http://localhost:3000/en/gw2/asura", "attrs"=>{"class"... (via streamed from StimulusReflex::Channel:0294526bd8d906f95809e5e6494d2c0c)
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
  Rendered shared/_favicon.html.slim (Duration: 421.4ms | Allocations: 58219)
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
[Webpacker] Everything's up-to-date. Nothing to do
  Rendered shared/_navbar.html.slim (Duration: 1458.4ms | Allocations: 176292)
  Rendered shared/_sidebar.html.slim (Duration: 0.1ms | Allocations: 29)
  Rendered shared/_footer.html.slim (Duration: 0.1ms | Allocations: 26)
  Rendered shared/_scripts.html.erb (Duration: 0.0ms | Allocations: 5)
Completed 200 OK in 2131ms (Views: 2123.6ms | ActiveRecord: 1.4ms | Allocations: 266384)

@reggieb
Copy link
Contributor Author

reggieb commented Sep 1, 2020

I've updated the PR to change the logger call to the debug level - so hopefully that will be a satisfactory compromise.

@nick123pig
Copy link

Let's get this one merged!

ericfranz added a commit to OSC/ondemand that referenced this issue May 10, 2021
the 12factor gem pulled in two gem dependencies that changed two
configuration values:

1. rails_serve_static_assets set serve static assets to true
2. rails_stdout_logging created a default logger that connected to
   STDOUT

in Rails 5, these can be controlled using env vars, so we set
RAILS_LOG_TO_STDOUT in NGINX stage

furthermore, we don't want to enable "serve static assets" from Rails,
since NGINX already serves static assets

when enabled, Rails tries to serve a missing static asset for 404 request,
which includes executing Webpacker::Compiler#compile though that just
pollutes the log file with lines like "[Webpacker] Everything's
up-to-date. Nothing to do"
(rails/webpacker#2392).

So ensuring we disable "serve static assets" from Rails solves this
problem as well.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

9 participants