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

mtest: fix test output issues (in console) #9232

Merged
merged 1 commit into from
Sep 25, 2021
Merged

Conversation

trhd
Copy link
Contributor

@trhd trhd commented Sep 7, 2021

I was annoyed by e.g. the meson's test subcommand's output's usage of the scissors emoji that never displayed properly in my development environments and set out to improve the look and feel of the test subcommand's output.

In the commit message I write:

This change set aims to fix various "issues" seen with the current
implementation. The changes can be summarized with the following list:

  • Replace emojis and spinners with multiline status displaying the name
    and running time of each currently running test.
  • The test output (especially in verbose mode or when multiple failing
    tests' output gets printed out) can get confusing. Try to make the
    output easier to read and grasp. Most notable change here is the
    addition of the test number to the beginning of each printed line.
  • Print exit details (i.e. exit code) of the test in verbose mode.
  • Try to make the verbose "live" output from tests to match the look and
    feel of otherwise produced (verbose) test output.

which quite well describes the changes I believe (hope). A "picture" is however worth a thousand words:

https://asciinema.org/a/dGOULiN7z9t0OJXrAno570W7T

In my opinion the end result is better that the original. This is however quite a subjective matter and you might disagree...

In the case that people agree with me on the above I still feel that it would be good if other people tried this out as well before merging. AFAIK the "test output" is not really tested via meson's own tests and as I can check only so many corner cases on my own there are bound to be issues that got overlooked. Especially if someone has strong opinions on how the subtests should be reported I'd love to hear back from you.

@trhd trhd requested a review from jpakkane as a code owner September 7, 2021 19:14
@codecov
Copy link

codecov bot commented Sep 7, 2021

Codecov Report

Merging #9232 (e9b470e) into master (e049494) will increase coverage by 3.09%.
The diff coverage is 52.17%.

❗ Current head e9b470e differs from pull request most recent head 65344c2. Consider uploading reports for the commit 65344c2 to get more accurate results
Impacted file tree graph

@@            Coverage Diff             @@
##           master    #9232      +/-   ##
==========================================
+ Coverage   66.85%   69.94%   +3.09%     
==========================================
  Files         386      193     -193     
  Lines       85058    42565   -42493     
  Branches    17551     8784    -8767     
==========================================
- Hits        56862    29774   -27088     
+ Misses      23402    10352   -13050     
+ Partials     4794     2439    -2355     
Impacted Files Coverage Δ
mesonbuild/mlog.py 89.57% <50.00%> (-0.31%) ⬇️
mesonbuild/mtest.py 76.60% <52.20%> (-0.60%) ⬇️
mesonbuild/scripts/vcstagger.py 87.50% <0.00%> (-4.17%) ⬇️
mesonbuild/wrap/wrap.py 61.75% <0.00%> (-0.86%) ⬇️
mesonbuild/interpreter/dependencyfallbacks.py 94.75% <0.00%> (-0.78%) ⬇️
modules/fs.py
scripts/yelphelper.py
templates/fortrantemplates.py
mesonmain.py
... and 193 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update e049494...65344c2. Read the comment docs.

@lgtm-com
Copy link

lgtm-com bot commented Sep 7, 2021

This pull request introduces 1 alert when merging 8726858 into 0fcd696 - view on LGTM.com

new alerts:

  • 1 for Unnecessary pass

@jpakkane
Copy link
Member

jpakkane commented Sep 7, 2021

Looks nice. Has this been tested on Windows? Its terminal is wonky.

@trhd
Copy link
Contributor Author

trhd commented Sep 7, 2021

Has this been tested on Windows? Its terminal is wonky.

Not at all. Unfortunately I dont have access to a Windows machine (well I suppose I could set up a virtual machine of some sort) so that is definitely something I could use some help on testing.

@anarazel
Copy link
Contributor

I see two issues trying this out:

  1. summary() referencing to dependencies are broken:
  External Libraries
    zlib           : [<mesonbuild.mlog.AnsiDecorator object at 0x7f68a8ed7730>, ' ', <mesonbuild.mlog.AnsiDecorator object at 0x7f68a8a2ad00>]

on master that is

  External Libraries
    zlib           : YES 1.2.11
  1. The new output doesn't work for larger concurrency. On a 40 core workstation, in a project with 98 tests, it printed out 1577 lines. With status updates repeating a lot of information:
13/98 postgresql:tap+pg_test_timing / pg_test_timing/t/001_basic.pl                           OK                0.11s
      postgresql:tap+pg_verifybackup / pg_verifybackup/t/001_basic.pl                                           0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/008_min_recovery_point.pl                                          0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/007_standby_source.pl                                              0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/005_same_timeline.pl                                               1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/004_pg_xlog_symlink.pl                                             1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/003_extrafiles.pl                                                  1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/002_databases.pl                                                   1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/001_basic.pl                                                       1/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/010_dump_connstr.pl                                        1/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/003_pg_dump_with_server.pl                                 1/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/002_pg_dump.pl                                             2/ 300s
      postgresql:tap+pg_verifybackup / pg_verifybackup/t/002_algorithm.pl                                       0/ 300s
      postgresql:tap+pg_verifybackup / pg_verifybackup/t/001_basic.pl                                           0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/008_min_recovery_point.pl                                          0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/007_standby_source.pl                                              0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/005_same_timeline.pl                                               1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/004_pg_xlog_symlink.pl                                             1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/003_extrafiles.pl                                                  1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/002_databases.pl                                                   1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/001_basic.pl                                                       1/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/010_dump_connstr.pl                                        1/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/003_pg_dump_with_server.pl                                 2/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/002_pg_dump.pl                                             2/ 300s
14/98 postgresql:tap+pg_verifybackup / pg_verifybackup/t/001_basic.pl                         OK                0.14s
      postgresql:tap+pg_verifybackup / pg_verifybackup/t/002_algorithm.pl                                       0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/008_min_recovery_point.pl                                          0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/007_standby_source.pl                                              0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/005_same_timeline.pl                                               1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/004_pg_xlog_symlink.pl                                             1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/003_extrafiles.pl                                                  1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/002_databases.pl                                                   1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/001_basic.pl                                                       2/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/010_dump_connstr.pl                                        2/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/003_pg_dump_with_server.pl                                 2/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/002_pg_dump.pl                                             2/ 300s
      postgresql:tap+pg_verifybackup / pg_verifybackup/t/003_corruption.pl                                      0/ 300s
      postgresql:tap+pg_verifybackup / pg_verifybackup/t/002_algorithm.pl                                       0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/008_min_recovery_point.pl                                          0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/007_standby_source.pl                                              0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/005_same_timeline.pl                                               1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/004_pg_xlog_symlink.pl                                             1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/003_extrafiles.pl                                                  1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/002_databases.pl                                                   1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/001_basic.pl                                                       2/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/010_dump_connstr.pl                                        2/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/003_pg_dump_with_server.pl                                 2/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/002_pg_dump.pl                                             2/ 300s
      postgresql:tap+pg_verifybackup / pg_verifybackup/t/003_corruption.pl                                      0/ 300s
      postgresql:tap+pg_verifybackup / pg_verifybackup/t/002_algorithm.pl                                       0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/008_min_recovery_point.pl                                          0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/007_standby_source.pl                                              0/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/005_same_timeline.pl                                               1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/004_pg_xlog_symlink.pl                                             1/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/003_extrafiles.pl                                                  2/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/002_databases.pl                                                   2/ 300s
      postgresql:tap+pg_rewind / pg_rewind/t/001_basic.pl                                                       2/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/010_dump_connstr.pl                                        2/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/003_pg_dump_with_server.pl                                 2/ 300s
      postgresql:tap+pg_basebackup / pg_basebackup/t/002_pg_dump.pl                                             2/ 300s

whereas on master it ends up with roughly one line per finished test, and the summary.

  1. This branch lost the information about subtest information, as e.g. present for tap:
    master:
 2/98 postgresql:tap+pg_checksums / pg_checksums/t/001_basic.pl                               OK                0.16s   8 subtests passed

PR:

 2/98 postgresql:tap+pg_checksums / pg_checksums/t/001_basic.pl                               OK                0.17s

@trhd trhd force-pushed the tyrkky branch 2 times, most recently from 1fcaad0 to e9b470e Compare September 16, 2021 21:25
@trhd
Copy link
Contributor Author

trhd commented Sep 16, 2021

Thanks @anarazel for pointing these out. I hopefully managed to fix these:

  1. This one got fixed by rebasing the PR to the lasted head.
  2. I suspect things went bad here when the terminal needed to start scrolling the text but not quite sure. I did however realize that when there are 10+ tests running at the same time reporting all of them individually quickly loses its usefulness and appeal. I hence limited the numer of tests that get individually reported like this to 10 and included a notification about the rest of the tests running in the background. After this change I could no longer reproduce this issue even with very large number of tests running simultaneously.
  3. Restored this (when not running in verbose mode as it would be redundant then).

I have yet to try this out on Windows but...soon...hopefully.

@trhd
Copy link
Contributor Author

trhd commented Sep 18, 2021

I managed to try this out in a virtual machine following mesonbuild.com's instructions for absolute beginners (needed help with Windows and Visual Studio). The performance of my virtual machine was terrible so I can't really say anything about timings, flickerings or such but everything looked OK to me. Didn't notice any issues with Windows' terminal.

This change set aims to fix various "issues" seen with the current
implementation. The changes can be summarized with the following list:

* Replace emojis and spinners with multiline status displaying the name
  and running time of each currently running test.
* The test output (especially in verbose mode or when multiple failing
  tests' output gets printed out) can get confusing. Try to make the
  output easier to read and grasp. Most notable change here is the
  addition of the test number to the beginning of each printed line.
* Print exit details (i.e. exit code) of the test in verbose mode.
* Try to make the verbose "live" output from tests to match the look and
  feel of otherwise produced (verbose) test output.
@jpakkane
Copy link
Member

jpakkane commented Sep 24, 2021

@anarazel did the change fix things for you?

@jpakkane jpakkane merged commit 5fcb0e6 into mesonbuild:master Sep 25, 2021
@anarazel
Copy link
Contributor

@jpakkane

@anarazel did the change fix things for you?

Yes, looks better now.

I kinda liked that spinner thingy though ;)

@bonzini
Copy link
Contributor

bonzini commented Sep 28, 2021

Has anybody looked at how Gitlab/GitHub/Travis deal with the multiline output and ESC[A sequences? This was the main reason why I went for the spinner.

Also it would have been much better to split this in multiple commits. The changes to the logging of completed tests are completely independent from the ones to the progress.

I will test it tomorrow on QEMU and report how it feels for TAP tests and in verbose mode.

@trhd
Copy link
Contributor Author

trhd commented Sep 28, 2021

I quickly tried this out in Sourcehut and sadly it was as @bonzini suspected and the up/down cursor movement was not handled properly. If I had to guess this is due to the fact that we have TERM=xterm and insufficient ANSI escape character support. It seems that at least in Sourcehut the size of the TTY was reported as being 0x0 so we could perhaps do something like this which seemed to at least work in Sourcehut:

--- a/mesonbuild/mtest.py
+++ b/mesonbuild/mtest.py
@@ -488,6 +488,8 @@ class ConsoleLogger(TestLogger):
         self.started_tests = 0
         try:
             self.cols, _ = os.get_terminal_size(1)
+            if self.cols == 0:
+                raise OSError
             self.is_tty = True
         except OSError:
             self.cols = 80

But now I really have to go to bed...

@bonzini
Copy link
Contributor

bonzini commented Sep 29, 2021

I tried it now and I see some problems, in that these changes completely undo some of the design points for the improved meson test in #7830:

Furthermore, these changes are not documented in the release notes.

Also, the exit code was printed already before, see TestRun.detail.

I would rather see this pull request reverted and submitted again as a separate set of changes that can be tested and evaluated individually. See #7830 for how to do it.

@anarazel
Copy link
Contributor

I just got the windows portion for my postgres-built-via-meson project actually pass tests, and that showed that the new output seems problematic for windows. In a normal terminal the ansi control sequences seem to get broken for both the old and the new output at some point (after initially working), but the consequences with the new output are way worse. The not-deleted multi-line output ends up being very noisy:

 1/98 postgresql:setup / temp_install                                                         OK                1.11s                
postgresql:pg_regress+btree_gist / btree_gist/pg_regress                                                  0/ 300s              
postgresql:pg_regress+btree_gin / btree_gin/pg_regress                                                    0/ 300s              
postgresql:pg_regress+bloom / bloom/pg_regress                                                            0/ 300s              
postgresql:pg_regress+amcheck / amcheck/pg_regress                                                        0/ 300s              
postgresql:pg_regress+adminpack / adminpack/pg_regress                                                    0/ 300s              
postgresql:isolation+test_decoding / test_decoding/isolation                                              0/ 300s              
postgresql:isolation+main / main/isolation                                                                0/1000s              postgresql:pg_regress+main /
 main/pg_regress                                                              0/1000s        �[8A�[K�[1B�[K�[1B�[K�[1B�[K�[1B�[K�[1B�[K�[1B�[K�[1B�[K�[7A      postgresql:pg_regress+btree_gist / btree_gist/pg_regress                                                  0/ 300s                                                                                 
postgresql:pg_regress+btree_gin / btree_gin/pg_regress                                                    0/ 300s              
postgresql:pg_regress+bloom / bloom/pg_regress                                                            0/ 300s              
postgresql:pg_regress+amcheck / amcheck/pg_regress                                                        0/ 300s              
postgresql:pg_regress+adminpack / adminpack/pg_regress                                                    0/ 300s              
postgresql:isolation+test_decoding / test_decoding/isolation                                              0/ 300s              
postgresql:isolation+main / main/isolation                                                                0/1000s              postgresql:pg_regress+main / 
main/pg_regress                                                              0/1000s        �[8A�[K�[1B�[K�[1B�[K�[1B�[K�[1B�[K�[1B�[K�
[1B�[K�[1B�[K�[7A      postgresql:pg_regress+btree_gist / btree_gist/pg_regress                                                  1/ 300s                                                                                 
postgresql:pg_regress+btree_gin / btree_gin/pg_regress                                                    1/ 300s              
postgresql:pg_regress+bloom / bloom/pg_regress                                                            1/ 300s              
postgresql:pg_regress+amcheck / amcheck/pg_regress                                                        1/ 300s              
postgresql:pg_regress+adminpack / adminpack/pg_regress                                                    1/ 300s              
postgresql:isolation+test_decoding / test_decoding/isolation                                              1/ 300s              
postgresql:isolation+main / main/isolation                                                                1/1000s              postgresql:pg_regress+main / main/pg_regress                                                              1/1000s

And it goes on like that for the rest of the test.

@trhd
Copy link
Contributor Author

trhd commented Sep 29, 2021

@anarazel What is your "normal terminal"? Something different from what you end up with following this guide for windows? And this does't work with these changes now reverted either?

@bonzini Thanks for the input. I now have fixes for the problems you mentioned but can currently test the Travis/GitLab/GitHub aspect only in Sourcehut. Maybe I'll squash those fixen in for a new PR?

@bonzini
Copy link
Contributor

bonzini commented Sep 29, 2021

I can help with testing, just make small patches and fix one thing at a time. In particular for now I'd keep the spinner as is, because it also has the scrolling problem with very large parallelism.

@bonzini
Copy link
Contributor

bonzini commented Sep 29, 2021

@anarazel the "normal" terminal (command prompt) is more or less broken, though the effect on the old (0.59) code should be limited to no emoji. The Windows "Terminal Preview" should work fine. I can help testing that using WSL.

@trhd
Copy link
Contributor Author

trhd commented Sep 29, 2021

I believe all other known issues got fixed already (the last fixes didn't get merged) except:

  • try out in GitHub/GitLab/Travis
  • the windows terminal issues @anarazel pointed out above (I'm assuming this is about windows terminal and not large parallellism since we didn't see this on non-windows terminals)

The changes depend on each other quite heavily and that's why the commit became so large in the first place but I guess the spinner change is the one thing that could be splitted to a separate commit. I'll see what I can do.

@bonzini
Copy link
Contributor

bonzini commented Sep 29, 2021

There are a lot of changes that can be split, such as:

  • handling of subtests in non-verbose failure output
  • handling of how the command line is printed
  • changing colored output to italic
  • changing the indent of subtests from triangle to spaces
  • removing the horizontal lines around test output.

and so on. Each of the above for example should be a separate commit; it's more work but it's really needed to do a meaningful review (and it would have allowed a more fine-grained revert). You don't need to create many PRs, just split changes into logical parts.

@anarazel
Copy link
Contributor

@anarazel the "normal" terminal (command prompt) is more or less broken, though the effect on the old (0.59) code should be limited to no emoji. The Windows "Terminal Preview" should work fine. I can help testing that using WSL.

Right, I noted that I saw a bit borked output on the "old" code as well. But that the damage is much more limited. FWIW, it didn't even work on the preview, until I change the system local to UTF-8, which seems to not work in other places :/.

@anarazel
Copy link
Contributor

I think there's quite a bit of benefit in logging in a way where the "worst case" output on a broken terminal isn't too bad.

@trhd trhd mentioned this pull request Feb 1, 2022
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

Successfully merging this pull request may close these issues.

4 participants