Rspec-rails: Rspec 3.7.0 is showing Puma logs during spec suite

[RemyMaucourt]

I'm building a Rails 5.1 app, and I just upgraded Rspec from 3.6.0 to 3.7.0, and rspec-rails from 3.6.1 to 3.7.1.

Since this upgrade, that puma starting log is displayed during my spec suite.

Puma starting in single mode...
* Version 3.10.0 (ruby 2.4.1-p111), codename: Russell's Teapot
* Min threads: 0, max threads: 1
* Environment: test
* Listening on tcp://0.0.0.0:36775
Use Ctrl-C to stop

Has anything changed in the rspec configuration?

(Screen capture in stackoverflow post)

[deivid-rodriguez]

Same here, I fixed it with ActionDispatch::SystemTesting::Server.silence_puma = true.

[penelopezone]

this configuration option should default to true. Do you have capybara and puma installed?

[roberts1000]

I just ran into this as well. It looks like the first spec example, that runs with js: true, triggers the log output.

[JonRowe]

Can you try master? We've delayed loading system test integration which should eliminate this issue for you.

[roberts1000]

Hi. I just gave 3.7.2 a shot and it's working great now. Thanks!

[sarojkh]

@roberts1000 I upgraded to 3.7.2 as well, but still see the Puma log. Are you sure it wasn't something else?

[roberts1000]

@sarojkh When I was testing this, the only change I made to the Gemfile.lock was to update rspec and it's dependencies. 3.7.2 solved the problem in my environment.

[swrobel]

I'm also on 3.7.2 and still seeing Puma in my test output. Rails 5.2.0.beta2 if that's important. Also, I have the following in my rails_helper although removing it doesn't seem to change anything:

  config.before(:each, type: :system) do
    driven_by :selenium, using: :headless_chrome
  end

[JonRowe]

Have you tried ActionDispatch::SystemTesting::Server.silence_puma = true

[swrobel]

@JonRowe thought rspec-rails was supposed to set that, but where would be the preferred place to set that manually?

[JonRowe]

We do set it if it exists at the time of load, but its possible a load order issue means it's not set when we try to. In your rails_helper.rb I would try.

[swrobel]

Also had to add require 'action_dispatch/system_test_case' otherwise I get uninitialized constant ActionDispatch::SystemTesting but regardless that didn't work. I'm running w/ bundle exec so spring shouldn't be an issue...

[JonRowe]

Try before(:all, type: :system) { ActionDispatch::SystemTesting::Server.silence_puma = true }

[swrobel]

Unfortunately that didn't do it either

[swrobel]

The following in rails_helper is the only thing I've found that works so far:

  config.before(:all, type: :system) do
    Capybara.server = :puma, { Silent: true }
  end

So weird...

[rsl]

i'm getting this and none of these solutions seem to work.
gem 'rails', '~> 5.1.1' gem 'rspec-rails', '~> 3.5.0', require: false gem 'rspec-given', '~> 3.8.0', require: false gem 'rspec_junit_formatter', require: false

[rspec_junit_formatter is keeping us from upgrading rspec-rails]

[JonRowe]

@rsl if you can't upgrade rspec-rails nothing will work

[rsl]

@JonRowe dang, well thanks for the answer

[eric-hemasystems]

Dug into this a bit to determine the root cause although I need advice regarding the resolution path. I see it mostly as a design problem in Rails.

1. When rspec sees that a system test is being run it loads action_dispatch/system_test_case.
2. Rails loads all the parts of ActionDispatch::SystemTestCase and then before returning actually boots the server. Simply doing a require 'action_dispatch/system_test_case' boots the server.
3. This means that even though rspec attempts to configure puma to be silent, by that time it has already booted (noisily).

I see this as a design problem in Rails because it provides a configuration option, but simply loading the library makes it too late to actually use that configuration.

If we wanted to solve this in rspec the solution would be to first load the "server" slice of the system test library to make the config, then load the rest of the system test library. So instead of:

require 'action_dispatch/system_test_case'
ActionDispatch::SystemTesting::Server.silence_puma = true

We would do:

require 'action_dispatch/system_testing/server'
ActionDispatch::SystemTesting::Server.silence_puma = true
require 'action_dispatch/system_test_case'

This seems a bit convoluted. Better would be for Rails to be changed so that simply requiring action_dispatch/system_testing doesn't boot the server. The calling code would need to then actually boot the server when it saw fit. This gives an opportunity to make any necessary config of that server.

If you want to work around this issue in the meantime you can place the following in your rails_helper.rb file (no need to put it in a before callback, just before rspec is confiugred is fine):

require 'action_dispatch/system_testing/server'
ActionDispatch::SystemTesting::Server.silence_puma = true

If this project is fine with working around Rails I can create a patch against this. OTOH if this project would rather get things fixed in Rails so it can be actually configured I can open a ticket on the Rails project.

[penelopezone]

Hi Folks,

RSpec rails will now do this for you if you're on a high enough version fo rails: https://github.com/rspec/rspec-rails/blob/master/lib/rspec/rails/example/system_example_group.rb#L74.

Please upgrade your RSpec Rails and Rails versions and that should fix it for you :)

[eric-hemasystems]

I don't believe it does. The code you pointed to runs too late. See my previous message for the full explanation.

[penelopezone]

@eric-hemasystems can you provide a rails app to clone that reproduces this following these exact steps:

Thanks for the issue. We need a little more detail to be able to reproduce this.

Could you please provide us with a rails app that we can clone that demonstrates the issue. Specifically it'd be great if

1) you could rails new an application and commit
2) make all the changes necessary to reproduce the issue and commit

then, provide us with a description of how to clone your application and reproduce the issue.

Thanks :)

[roberts1000]

It's slightly different, but maybe it's related. When I run RSpec (with capybara), I can trigger

Capybara starting Puma...
* Version 3.11.4 , codename: Love Song
* Min threads: 0, max threads: 4
* Listening on tcp://127.0.0.1:37067

Here's a simple Rails app that reproduces the issue: https://github.com/roberts1000/puma_in_rspec_output. Instructions are in the app's README.

[eric-hemasystems]

@samphippen - Here is a sample repo that demonstrates the problem, shows my work-around fixing it and provides exactly how this repo was reproduced in the README. Let me know if you need anything further to confirm this is a problem.

https://github.com/eric-hemasystems/rspec_system_puma_output

[artur79]

@swrobel Unfortunately that snippet:

config.before(:all, type: :system) do
  Capybara.server = :puma, { Silent: true }
end 

causes that Capybara is not able to connect to Chrome in js spec. But my configuration is specific because I use remote chrome in Docker container.

[ndbroadbent]

This was happening for me with rspec-rails 3.7.2 and rails 5.2.0. I was able to fix it by putting Capybara.server = :puma, { Silent: true } in spec/rails_helper.rb. (Didn't need the before block.)

[georgemillo]

Had this issue with rspec-rails 3.6.1, rails 5.1.6, puma 3.11.4. Fixed it by changing Capybara.server = :puma in rails_helper to Capybara.server = :puma, { Silent: true }

[jrochkind]

I am having this with rspec-rails 3.8.1 and Rails 5.2.2. I don't believe it's true that upgraded rspec-rails or rails dependencies fix it.

For me, explicit require 'action_dispatch/system_testing/server'; ActionDispatch::SystemTesting::Server.silence_puma = true in rails_helper makes no difference, does not fix it.

Putting Capybara.server = :puma, { Silent: true } in my rails_helper.rb does fix it for me (not in a before(:all) callback, just directly).

Not sure if this has any undesirable side effects.

[jrochkind]

Followup note:

Putting Capybara.server = :puma, { Silent: true } in my rails_helper.rb seems to have resulted in sometimes when running my system tests, a hard crash of MRI. You know, the kind that ends in "Don't forget to include the Crash Report log file under DiagnosticReports directory in bug reports."

If I scroll up through the 8000 lines of "Loaded features" to notice there IS a ruby backtrace there, the final line is:

/Users/jrochkind/.gem/ruby/2.5.3/gems/puma-3.12.0/lib/puma/thread_pool.rb:133:in `block in spawn_thread'

Which somehow made me realize maybe it was related to my trying to silence puma as above.

The error is not entirely reliably reproducible, but somehow _right now_ it is, and I have commented in-and-out the Capybara.server = :puma, { Silent: true } line several times, and verified that, right now anyway, that line there, I get the "Crash Report", that line commented out, I don't (but get puma log lines in my stdoub).

So that was apparently not the right solution.

I really don't understand what's going on. Does anyone know the _right_ way to keep puma log lines out of stdout in my test logs?

Is _everyone_ having this problem, with puma log lines in stdout? If everyone was having it, I'd think it would be a higher priority to fix... so maybe it's something special to my setup... but as far as I know I set up everything pretty darn standard for Rails 5.2, system tests, and capybara.

Very confused and frustrated.

[jrochkind]

It's possible it has nothing to do with this, heisenbugs are hard, and I don't really know how to read a C-level MRI crash report.

In case this means anything to anyone:

ruby 2.5.3p105 (2018-10-18 revision 65156) [x86_64-darwin16]
capybara 3.13.2, puma 3.12.0

console output
.crash report from ~/Library/Logs/DiagnosticReports

[JonRowe]

Not everyone has this, its an ordering issue dependant on when puma is booted, the config option needs to happen before puma boots to take affect. I would paste that puma log to puma, it looks like a legit crash from a threading issue.

[jrochkind]

OK, will report to puma, thanks. (I'm still wondering if it's got to do with the combo of rails system tests and puma setup though)

its an ordering issue dependant on when puma is booted, the config option needs to happen before puma boots to take affect.

Is there anything I can do in my app to make sure the ordering is correct? Is it as simple as making sure rspec-rails is in the Gemfile before puma?

[JonRowe]

It is not, it is down to how you boot your application, if you need a file run before anything else you must use the --require option on the RSpec cli, either via a config file (such as .rspec) or directly.

This is why the generated install drops a --require spec_helper in your .rspec, as it means the top of your spec_helper.rb is evaluated first. With the split of spec_helper.rb and rails_helper.rb it becomes a bit more complicated, as at some point Rails will be loaded, and the rails_helper.rb loaded, ideally the rails_helper.rb is loaded first but various auto load scenarios will prevent this.

If all your specs are rspec-rails specs you could put require 'rails_helper' at the top of your spec_helper.rb, but that loses some benefits. Alternatively you could load just capybara and puma at the top of your spec helper and configure it.

[aledelsur]

This configuration on the rails_helper.rb worked for me on Puma "3.11.4":

Capybara.configure do |config|
  config.server = :puma, { Silent: true }
end

Thanks @swrobel.

[benoittgt]

Closed by https://github.com/rspec/rspec-rails/pull/2289