Silence logs optional
jwoodrow opened this issue · 10 comments
jwoodrow commented
Is your feature request related to a problem? Please describe.
When running rspec-tracer with parallel_tests (via turbo_tests to sync outputs) the rspec-tracer logs' output inserts itself in the middle of the output to notify it's done and that's it's generating coverage.
Describe the solution you'd like
Log once at the end of all parallel_specs.
Maybe this could be a good place to look or what turbo_tests implemented to sync the outputs
Describe alternatives you've considered
A config variable that would allow the silencing of all logs from rspec-tracer
avmnu-sng commented
Logging once at the end doesn't make sense because the whole point of the logs is to provide feedback on what's happening.
- rspec_tracer runs the report generation logic at the end of all the processes because it is the right behavior but not for logging the progress per process
- turbo_tests also prints the total number of processes and tests before starting the tests.
@jwoodrow It would be great if you can tell me what problem it is causing, maybe we can find some other solution.
jwoodrow commented
Here is the parallel_tests (run using turbo_tests to sync output because otherwise it's unreadable) when combined with rspec_tracer.
bundle exec turbo_tests -n 4 output
bundle exec turbo_tests -n 4
Using recorded test runtime
4 processes for 495 specs, ~ 124 specs per process
Started RSpec tracer (pid: 70338)
Started RSpec tracer (pid: 70335)
Started RSpec tracer (pid: 70337)
Started RSpec tracer (pid: 70336)
RSpec tracer loaded cache from PROJECT_PATH/rspec_tracer_cache/8cfc5428c3cdc219656bd9ed9982a4df (took 0.45007 seconds)
RSpec tracer loaded cache from PROJECT_PATH/rspec_tracer_cache/8cfc5428c3cdc219656bd9ed9982a4df (took 0.45097 seconds)
RSpec tracer loaded cache from PROJECT_PATH/rspec_tracer_cache/8cfc5428c3cdc219656bd9ed9982a4df (took 0.45239 seconds)
RSpec tracer loaded cache from PROJECT_PATH/rspec_tracer_cache/8cfc5428c3cdc219656bd9ed9982a4df (took 0.45306 seconds)
RSpec tracer is running 1716 examples (actual: 1987, skipped: 271) (took 0.26584 seconds)
RSpec tracer is running 1944 examples (actual: 2145, skipped: 201) (took 0.3441 seconds)
RSpec tracer is running 2090 examples (actual: 2550, skipped: 460) (took 0.30335 seconds)
..........................................................................................................................................................................................................
RSpec tracer is running 2023 examples (actual: 2114, skipped: 91) (took 0.23018 seconds)
................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................*............................................................................................................*...............................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................*.............................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................**...................................................*...........................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................*.......................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................F........................................................................................................................................................................................................*........................................................................................................................................*.......*......................*.*.............................F................................F..................F.................................F................F..........................................................................................................F................................................................................................................................................................................................................................................................................................................................................RSpec tracer is generating reports (pid: 70335)
............................................................................................RSpec tracer reports written to PROJECT_PATH/rspec_tracer_cache/97f30b470bcac0265f4245a4d1f2a5ac (took 3.26 seconds)
....RSpecTracer generated HTML report to PROJECT_PATH/rspec_tracer_report/index.html (took 1.43 seconds)
SimpleCov will now generate coverage report (<3 RSpec tracer)
.......Coverage report generated for RSpec to PROJECT_PATH/coverage. 15836 / 22526 LOC (70.3%) covered.
.....................................................................................................................RSpec tracer is generating reports (pid: 70336)
...............................RSpec tracer reports written to PROJECT_PATH/rspec_tracer_cache/e6b52681b8ded121d8cecf384c702b9e (took 2.31 seconds)
.....RSpecTracer generated HTML report to PROJECT_PATH/rspec_tracer_report/index.html (took 1.12 seconds)
SimpleCov will now generate coverage report (<3 RSpec tracer)
......Coverage report generated for RSpec to PROJECT_PATH/coverage. 16980 / 24000 LOC (70.75%) covered.
.........................................................................................................................................................*...............................................RSpec tracer is generating reports (pid: 70337)
...RSpec tracer reports written to PROJECT_PATH/rspec_tracer_cache/7ad77aedb6e1062962aa23936ee179a3 (took 1.68 seconds)
.RSpecTracer generated HTML report to PROJECT_PATH/rspec_tracer_report/index.html (took 1.68 seconds)
SimpleCov will now generate coverage report (<3 RSpec tracer)
Coverage report generated for RSpec to PROJECT_PATH/coverage. 17242 / 24677 LOC (69.87%) covered.
..............*.........................................................................................................................................................................................................RSpec tracer is generating reports (pid: 70338)
RSpec tracer reports written to PROJECT_PATH/rspec_tracer_cache/3c7109b4611c7494eb9bba938a8a4e59 (took 1.1 seconds)
RSpecTracer generated HTML report to PROJECT_PATH/rspec_tracer_report/index.html (took 2.29 seconds)
SimpleCov will now generate coverage report (<3 RSpec tracer)
Coverage report generated for RSpec to PROJECT_PATH/coverage. 16525 / 23731 LOC (69.63%) covered.
Pending: (Failures listed here are expected and do not affect your suite's status)
# Some pending specs
Failures:
# Some failing specs due to parallel_tests causing issues
Finished in 20 minutes 56 seconds (files took 1 minute 10.36 seconds to load)
7773 examples, 7 failures, 14 pending, 2 errors occurred outside of examples
Failed examples:
# Some failing specs due to parallel_tests causing issuesAs you can see the intermediate output from rspec_tracer pollutes the output from parallel_tests/turbo_tests making it not great to track how many tests have been run and are left (I usually do this by copy-pasting the .*F characters in an IDE and auto-count them that way but with the output from rspec_tracer I can't do this anymore. And in my opinion this sort of output is undesirable and should be optional since it's only really useful when debugging (with a verbosity level).
That's why I'm saying output from rspec_tracer should be optional 🤔
jwoodrow commented
As a side note when running the tests a second time, this is the output (error in the rspec_tracer gem it seems ?)
bundle exec turbo_tests -n 4
bundle exec turbo_tests -n 4
Using recorded test runtime
4 processes for 495 specs, ~ 124 specs per process
Started RSpec tracer (pid: 82120)
Started RSpec tracer (pid: 82117)
Started RSpec tracer (pid: 82119)
Started RSpec tracer (pid: 82118)
RSpec tracer loaded cache from PROJECT_PATH/rspec_tracer_cache/3c7109b4611c7494eb9bba938a8a4e59 (took 0.5986 seconds)
RSpec tracer loaded cache from PROJECT_PATH/rspec_tracer_cache/3c7109b4611c7494eb9bba938a8a4e59 (took 0.59978 seconds)
RSpec tracer loaded cache from PROJECT_PATH/rspec_tracer_cache/3c7109b4611c7494eb9bba938a8a4e59 (took 0.60211 seconds)
RSpec tracer loaded cache from PROJECT_PATH/rspec_tracer_cache/3c7109b4611c7494eb9bba938a8a4e59 (took 0.60305 seconds)
RSpec tracer is running 307 examples (actual: 1927, skipped: 1620) (took 0.19261 seconds)
RSpec tracer is running 197 examples (actual: 1899, skipped: 1702) (took 0.18735 seconds)
RSpec tracer is running 212 examples (actual: 2338, skipped: 2126) (took 0.22359 seconds)
RSpec tracer is running 322 examples (actual: 2632, skipped: 2310) (took 0.32491 seconds)
......................................................................................................................................................................................................*.......................................................................................................................................................................................................................................................................................................................................................................................................*..................................................................................................RSpec tracer is generating reports (pid: 82118)
..........................RSpec tracer reports written to PROJECT_PATH/rspec_tracer_cache/166d8add509c40e9cf50349e4b94d4c1 (took 1.2 seconds)
..............RSpecTracer generated HTML report to PROJECT_PATH/rspec_tracer_report/index.html (took 2.74 seconds)
SimpleCov will now generate coverage report (<3 RSpec tracer)
............Coverage report generated for RSpec to PROJECT_PATH/coverage. 15467 / 22316 LOC (69.31%) covered.
..............................*........RSpec tracer is generating reports (pid: 82117)
............*.RSpec tracer reports written to PROJECT_PATH/rspec_tracer_cache/64b0e664ff492df345e4f40321eeed2b (took 0.93888 seconds)
.........................RSpecTracer generated HTML report to PROJECT_PATH/rspec_tracer_report/index.html (took 2.58 seconds)
SimpleCov will now generate coverage report (<3 RSpec tracer)
.................Coverage report generated for RSpec to PROJECT_PATH/coverage. 16221 / 24215 LOC (66.99%) covered.
................................*.*......................................................................................*..................................*.*RSpec tracer is generating reports (pid: 82119)
..........HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/coverage_reporter.rb:75:in `block (2 levels) in merge_coverage': undefined method `+' for nil:NilClass (NoMethodError)
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/coverage_reporter.rb:74:in `each_pair'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/coverage_reporter.rb:74:in `block in merge_coverage'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/coverage_reporter.rb:67:in `each_pair'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/coverage_reporter.rb:67:in `merge_coverage'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer.rb:291:in `process_coverage'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer.rb:262:in `generate_reports'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer.rb:250:in `run_exit_tasks'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer.rb:86:in `at_exit_behavior'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/defaults.rb:15:in `block in <top (required)>'
...Coverage report generated for RSpec to PROJECT_PATH/coverage. 10559 / 20215 LOC (52.23%) covered.
....****...............*......RSpec tracer is generating reports (pid: 82120)
HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/coverage_reporter.rb:75:in `block (2 levels) in merge_coverage': undefined method `+' for nil:NilClass (NoMethodError)
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/coverage_reporter.rb:74:in `each_pair'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/coverage_reporter.rb:74:in `block in merge_coverage'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/coverage_reporter.rb:67:in `each_pair'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/coverage_reporter.rb:67:in `merge_coverage'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer.rb:291:in `process_coverage'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer.rb:262:in `generate_reports'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer.rb:250:in `run_exit_tasks'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer.rb:86:in `at_exit_behavior'
from HOME_DIR/.rvm/gems/ruby-3.0.1/gems/rspec-tracer-1.0.0/lib/rspec_tracer/defaults.rb:15:in `block in <top (required)>'
Coverage report generated for RSpec to PROJECT_PATH/coverage. 9427 / 18917 LOC (49.83%) covered.
Pending: (Failures listed here are expected and do not affect your suite's status)
# Some Pending specs
Finished in 4 minutes 4.7 seconds (files took 33.66 seconds to load)
1038 examples, 0 failures, 14 pending, 1 error occurred outside of examplesavmnu-sng commented
@jwoodrow Can you provide me a sample project to reproduce the error? It certainly is some missed case in the Gem.
jwoodrow commented
Unfortunately this is a private work project so I cannot provide a sample project for this issue but it feels to me that the coverage file is not being merged/created correctly on the first run, which results the key being present but it's value being nil ?
avmnu-sng commented
I didn't ask for this project itself but some other project which would reproduce the issue.
jwoodrow commented
Ok, so quick update.
- I thought
turbo_testsusedparallel_teststo run the tests but they in fact did not so that's probably the reason why I was getting an error because even though RSpecTracer wanted to run withturbo_testsit was having issues doing so correctly. Maybe something that could be looked into one day. - I'm still getting logs that I didn't get when I disabled
RSpecTracer. What I mean is that I set the logger forSimpleCovtoSimpleCov::Formatter::SimpleFormatterwhich makes it silent and removes the "Generating coverage" message fromSimpleCovbut when I re-add SimpleCov I end up with the following 4 extra unwanted logs
RSpec tracer is generating reports (pid: xxxxx)
RSpec tracer reports written
RSpecTracer generated HTML report
SimpleCov will now generate coverage report (<3 RSpec tracer)
I feel like there should really be an option to both:
- Silence report generation
- Respect the SimpleCov configuration or at least set it on the RSpecTracer side of things too.
avmnu-sng commented
All of the following messages are coming from RSpec Tracer only. It always respects the SimpleCov configuration.
RSpec tracer is generating reports (pid: xxxxx)
RSpec tracer reports written
RSpecTracer generated HTML report
SimpleCov will now generate coverage report (<3 RSpec tracer)
I am working on improving the logging experience.
jwoodrow commented
Hi @avmnu-sng Thanks for the continued hard work on your gem :)
In the meantime I've also had to disable rspec-tracer because when running with parallel_tests it seems the dependency part does seem to work as well.
For example:
I've run all 8k+ tests locally with parallel_tests + rspec-tracer and when re-running everything without any modifications it works fine => No specs are rerun except pending tests.
I then change 1 test. When running rspec without parallel_tests this results in that test's file being rerun (~40 tests) and nothing else. But when running with parallel_tests it runs 800 tests (~20 files). I feel like something is wrong in this situation and if you want me to do some debugging to checkout what going on I'll look into it.
this issue is making it so when tests are rerun on travis ~80% of the specs are rerun instead of 10-20%, so we've decided to simply run all tests each time and bite the bullet until a fix arrives for this 👋