Rails 5.1.3 display regression

[bobmaerten]

Hello.

Checking Rails 5.1.3.rc3 against our main application, and I find display quite broken while executing tests. I formatted output from my terminal (adding LF and removing extra spaces to fit here in the issue), it seems that default reporter still run even with Rails trick from README (Minitest::Reporters.use! Minitest::Reporters::ProgressReporter.new, ENV, Minitest.backtrace_filter`

❯ rails test
Started with run options --seed 34013

Run options: --seed 34013-=---=---=---=---=---=---=-] 0% Time: 00:00:00,  ETA: ??:??:??

# Running:


.  2756/2: [                                         ] 0% Time: 00:00:02,  ETA: 00:56:0
.  2756/3: [                                         ] 0% Time: 00:00:02,  ETA: 00:37:3
...  2756/6: [                                         ] 0% Time: 00:00:02,  ETA: 00:18
.  2756/7: [                                         ] 0% Time: 00:00:02,  ETA: 00:15:5
.  2756/8: [                                         ] 0% Time: 00:00:02,  ETA: 00:14:0
..  2756/10: [                                        ] 0% Time: 00:00:02,  ETA: 00:12
:..  2756/12: [                                        ] 0% Time: 00:00:02,  ETA: 00:10
:.  2756/13: [                                        ] 0% Time: 00:00:02,  ETA: 00:10:1
.  2756/14: [                                        ] 0% Time: 00:00:03,  ETA: 00:09:5
.  2756/15: [                                        ] 0% Time: 00:00:03,  ETA: 00:09:5
.  2756/16: [                                        ] 0% Time: 00:00:03,  ETA: 00:09:4
.  2756/17: [                                        ] 0% Time: 00:00:03,  ETA: 00:09:3
.  2756/18: [                                        ] 0% Time: 00:00:03,  ETA: 00:09:0
...  2756/21: [                                        ] 0% Time: 00:00:03,  ETA: 00:07
......^CInterrupted. Exiting...
  2756/2756: [=====================================] 100% Time: 00:00:03, Time: 00:00:03

Finished in 3.71382s
26 tests, 81 assertions, 0 failures, 0 errors, 0 skips


Finished in 3.713659s, 7.0012 runs/s, 21.8114 assertions/s.
26 runs, 81 assertions, 0 failures, 0 errors, 0 skips

I have no idea how things work so I only report to keep track of it.
It will eventually be resolved after Rails 5.1.3 final release, or may be it simply a minitest bug?

[tekniklr]

seeing this in Rails 5.0.5, too. Looks to be related to changes in railties? https://github.com/rails/rails/blob/v5.0.5/railties/CHANGELOG.md

[skunkworker]

Same issue with 5.1.3 final released today. Both the . and progress bar are showing up.

[bobmaerten]

🤔 Hum...

When disabling minutest-reporters from test_helper, the test suite appears to double output "Running". So it's probably just minutest related

[bencrouse]

there were some significant changes to Rails' minitest integration: rails/rails@0d72489

[mttdffy]

So heres the trouble.

Minitest plugins are loaded based on being in the path of minitest/*_plugin.rb.

Now that Rails uses a minitest plugin as of 5.1.3, rails_plugin.rb, it gets loaded through minitest's normal plugin loading (which I assume is alphabetical) along with minitest_reporters_plugin.rb.

this gem's plugin resets minitests reporters to be just its own DelegateReporter, passing in the reporters that already exist into itself so it can manage reporters for you.

Rails then comes along and deletes the default reporters (though they aren't there anymore, they're in delegate reporter now) and then adds its own. So now delegate reporter loops through the originals for output, and then rails reporters do their thing -- double output.

I'm not sure what the best fix is in terms of fixing it from MiniTest::Reporters.

[os97673]

@mttdffy could you please point the rails code which does this

[mttdffy]

https://github.com/rails/rails/blob/v5.1.3/railties/lib/minitest/rails_plugin.rb#L42

[padi]

Experiencing the same thing in the final release of 5.1.3.

Was able to confirm that adding this gem alone reproduces the same behavior as @bobmaerten's screenshot. I don't even need to add Minitest::Reporters.use! Minitest::Reporters::SpecReporter.new

Commenting out gem 'minitest-reporter in the Gemfile + bundle install; rails test removes the doubled output.

[padi]

Thanks @mttdffy for the detailed explanation.

[os97673]

I might be wrong but it looks like we could just add similar line you our init to remove the reporters rails want to remove and this will fix the problem. Am I right?
After we will have this quick and dirty solution we can start discussion with rails to find a better way to fix the problem.
@mttdffy WDYT?

[mttdffy]

Deleting the default reporters in minitest-reporters doesn't accomplish anything. Without Rails, you end up with a DelegateReporter that does nothing because its now the only reporter, and it doesn't do anything on its own. With Rails, you end up with this:

DelegateReporter
SuppressedSummaryReporter
Rails::TestUnitReporter

This ends up defeating the purpose of this gem, as its no longer managing all the reporters being used.

I think the biggest hurdle is the unpredictability of minitest plugin load order. It uses Gem.find_files, which doesn't seems to have a clear order to how it finds which gems are there. So theres no guarantee rails loads before or after minitest-reporters.

I'm not sure there is a solution to get this to play nicely without having Rails use minitest-reporters, which isn't going to happen.

In a perfect world, minitest provides a way for you to define when your plugin gets loaded, i.e. a prepend_plugin, append_plugin functionality. Then Rails would prepend to ensure its one of the first, and mini-test reporters could append, ensuring it was one of the last and could safely absorbed all the other reporters into it's DelegateReporter

I guess to answer your question @os97673, it does "fix" the display issue, but DelegateReporter is now managing nothing, and the rails reporters are outside it's control and you can no longer use Minitest::Reporters.use! to override all the reporters. Anything added with that would get used in addition to rails' reporters

[fedegos]

I don't understand, is there a solution for this problem?

[mttdffy]

No, there is currently no clear way to fix it.

[tmandke]

here is a workaround you can add to the test_helper its a total hack but it works.

module Minitest
  # copied from minitest
  def self.init_plugins(options)
    extensions.each do |name|
      msg = "plugin_#{name}_init"
      send msg, options if respond_to?(msg)
    end
    fix_reporters
  end

  def self.fix_reporters
    dr = reporter.reporters.find { |r| r.is_a? Minitest::Reporters::DelegateReporter }

    # getting rid of default reporters
    drr = dr.instance_variable_get(:@reporters)
    drr.delete_if { |r| r.is_a?(Minitest::SummaryReporter) || r.is_a?(Minitest::ProgressReporter) }

    # getting rid of rails reporters
    reporter.reporters.delete_if { |r| r.is_a?(Minitest::SuppressedSummaryReporter) || r.is_a?(::Rails::TestUnitReporter) }
  end
end

[samcday]

I found a cleaner workaround than the one above. AFAICT the underlying problem is Rails had this commit to make sure the Rails minitest plugin would initialize first. I think at some point that commit was lost (the file that was changed in that commit no longer exists in Rails 5.1 series, they probably missed it when cherry-picking changes around or whatever). I've raised rails/rails#30491 to track the upstream issue.

You can replicate the same behaviour by adding the following to your test_helper.rb, directly after requiring everything:

# This is a workaround for https://github.com/kern/minitest-reporters/issues/230
Minitest.load_plugins
Minitest.extensions.delete('rails')
Minitest.extensions.unshift('rails')

[os97673]

Forced to revert #236 since it creates too many problems for other gems (#239, #241, #244)

[gshaw]

FWIW, I started seeing this problem only after upgrading to 1.1.19 (1.1.18) was reporting fine and as expected but after updating to .19 I started seeing the duplicate reporting, reverting back to .18 resolved the issue.

[os97673]

This is expected since I have reverted changes which fixed the problem in .18 because of regressions they added :(

[ybakos]

Is the current status that we "can't" use minitest-reporters with Rails 5.1.3+ ?
(Same behavior on Rails 5.1.4.)

[bobmaerten]

@samcday solution works fine.

[gr8distance]

loading local minitest-reporters does not cause problems.

[Kevinrob]

I made a PR that should fix the double reporters output rails/rails#31901

[markedmondson]

Nice work @Kevinrob. Thanks!

[wuron]

I've just tested this in Rails 5.1.6 and it seems working just fine. No double output.

[likeuwill]

On rails 5.1.5 bug exists.

[Kevinrob]

@likeuwill Yes. It's fixed on 5.1.6
https://github.com/rails/rails/blob/5-1-stable/railties/CHANGELOG.md#rails-516-march-29-2018

[kreintjes]

Any way to fix this in combination with Rails 5.0.7.2 (currently newest Rails 5.0)? Problem occurs with both minitest-reporters 1.1.14 as well as minitest-reporters 1.3.8. @tekniklr did you manage to fix this in Rails 5.0?

[andreynering]

I could fix this issue on Rails 5.0 by going back to v1.1.18.