-
Notifications
You must be signed in to change notification settings - Fork 3k
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
ct: Allow running tests more silently / improve ct_run's terminal output #7375
Conversation
CT Test Results 4 files 187 suites 53m 0s ⏱️ For more details on these failures, see this check. Results for commit 0bd7c5c. ♻️ This comment has been updated with latest results. To speed up review, make sure that you have read Contributing to Erlang/OTP and that all checks pass. See the TESTING and DEVELOPMENT HowTo guides for details about how to run test locally. Artifacts// Erlang/OTP Github Action Bot |
Hello! Have you tried using https://github.com/ferd/cth_readable to limit the output? I think it should work without rebar3. Anyway, I don’t think this type of functionality should live in the makefiles but instead be in ct so that all ct users can benefit from it. |
Good morning! Thank you for the quick review.
Thanks for the suggestion - this definitely helps in limiting the output. As it's external though it grows the command line quite a bit to configure it. I ended up with the following: make test \
ERL_ARGS="-pz /Users/Johannes/workspace/cth_readable/_build/default/lib/cth_readable/ebin/ -pz /Users/Johannes/workspace/cth_readable/_build/default/lib/cf/ebin/" \
ARGS="-ct_hooks cth_readable_failonly and cth_readable_shell"
This sounds good. Digging into Common Test a bit more, I found
That way we can keep information from logs in the CT HTML output for detailed tests whilst slimming down shell output. |
I think that sounds like a good idea! What do you think @u3s ? |
I would like to have such knob available in ct_run
Can't you open https://erlang.github.io/prs/7375/ct_logs/index.html ? Is this too heavy?
Yes. This would be great.
Yes, I would prefer HTML logs to stay verbose but it would be great to have an option for trimming shell. |
42beeb4
to
acb9434
Compare
I have updated my commit such that
I think
This definitely looks like a big improvement to me :-) Having this format - maybe with colours and a progress indicator on the right - as the default - or even just a small knob - would be nice!
No, that works. But I don't want to open PRs in upstream if I don't know that tests passed: maybe some idea I had turns out to be completely breaking and I didn't catch it locally because I didn't run the entire test suite. Instead, I wait for actions to run on my fork. For example, for #7380 here is my actions run of an earlier version (with a dumb typo - I had a gen server call
I will see what I can do to help adding something like this 🙂 |
b5ea032
to
e11a4b8
Compare
%% Prevent recursively logging messages we have seen | ||
log(#{meta:=Meta}=_Log, _Config) when is_map_key(?MODULE, Meta) -> | ||
ok; | ||
log(#{meta:=#{domain:=[otp]}}=Log,Config) -> | ||
do_log(add_log_category(Log,error_logger),Config); | ||
log(#{meta:=#{domain:=_}},_) -> | ||
ok; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
can you give more details?
%% Prevent recursively logging messages we have seen | ||
log(#{meta:=Meta}=_Log, _Config) when is_map_key(?MODULE, Meta) -> | ||
ok; | ||
log(#{meta:=#{domain:=[otp]}}=Log,Config) -> | ||
do_log(add_log_category(Log,error_logger),Config); | ||
log(#{meta:=#{domain:=_}},_) -> | ||
ok; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
can you give more details? what was the unwanted flow?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
From what I gathered when writing this, the previous behaviour would ignore redirect for some messages. I figured that the log redirect should probably capture all log messages, so removed it. For example the HTML logs for httpd_SUITE:bad_hex/1
with this change include:
*** System report during httpd_SUITE:bad_hex/1 in http_1_0 2023-06-12 23:45:06.509 ***
=ERROR REPORT==== 12-Jun-2023::23:45:06.509079 ===
Server: httpd_test
Protocol: HTTP
Transport: TLS
Host: 127.0.1.1:40797
Peer: 127.0.0.1:50042
Reason: [{statuscode,400},
{description,"Bad Request"},
{details,{malformed_syntax,"http://www.erlang.org/%skalle"}}]
Without this change, this report is not included.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Also, since we're already on the review comments in here: I am not sure if the "prevent recursively logging" does what I intend it to. If we added the key I don't think we're passed the log message again because it's immutable. I did see some test cases that looked suspiciously like they were recursively logging themselves again but I'm not sure it was caused by this one...
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'll check that later please wait with resolving that one.
%% Prevent recursively logging messages we have seen | ||
log(#{meta:=Meta}=_Log, _Config) when is_map_key(?MODULE, Meta) -> | ||
ok; | ||
log(#{meta:=#{domain:=[otp]}}=Log,Config) -> | ||
do_log(add_log_category(Log,error_logger),Config); | ||
log(#{meta:=#{domain:=_}},_) -> | ||
ok; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'll check that later please wait with resolving that one.
I think it would be good to have something built-in. I would greatly appreciate if it allows for optional redirecting output to text file which you can "tail -f". I tend to collect those text files with results. My sketchy attempt can be found in #7427. Feel free to extend it or write your own solution from scratch. I don't know what is better (hooks or events) at this stage. If you prefer we can re-use Python conventions regarding results representation or have color output as option. Depending on where we get we can document it or leave it a bit sketchy until it matures enough. What do you think? |
Just to clarify, do you mean the output of CT as a whole or the logging output that's captured by the log redirect handler?
I will check this out!
My idea would be to do this in separate stages so you can decide on what you think makes sense to have in OTP and what does not. The rough outline of what I would like to do, each in a separate PR, would be:
We can also put all into this PR, it is really up to you, but I think having it in smaller chunks makes it easier to review. Just let me know 🙂 In either case I'm still a bit unsure about the changes to make the log redirect work, at the moment it breaks some tests, see e.g. https://erlang.github.io/prs/7375/ct_logs/[email protected]_12.53.32/make_test_dir.kernel_test.logs/run.2023-06-14_12.54.14/logger_std_h_suite.default_formatter.html. Waiting for your comment there on the code review to see how to deal with it. |
I meant test execution progress being redirect to text file, but maybe this would not be needed if
Yes. I think we should try to leave default as is.
|
I meant test execution progress being redirect to text file, but maybe this would not be needed if `ct_run -brief` option works well ... see below.
We'll see how well it works - I think adding a way to duplicate the
output to a second file shouldn't be hard - with your handler as I
understand it you can add the hook twice with /dev/stdout and some file
as paths.
Yes. I think we should try to leave default as is.
👍
- Plan looks good, maybe each bullet should be a separate commit to make reviewing easier but in a single PR so the change remains atomic and not scattered?
- I like `ct_run -brief` suggestion and think this is also inline with what @garazdawi proposed; but this might make `make -s` not needed anymore, right? ... so if we're still kind of experimenting and prototyping, maybe we should stay within single PR ...
Hmmm, I agree that having multiple commits in single big PR is probably
the best of both worlds.
With `-s` I am 50/50 - I would personally be in favour of keeping it (as
a shortcut to adding `-brief`). So instead of:
make test ARGS="-brief"
you would have the (IMO much easier to remember and less tedious to run):
make test -s
Up to you.
- if `ct_run -brief` would really silence the output (seems quite a lot of work) then maybe my requirement for writing test progress to separate file could be skipped ...
The main work as I see it boils down to: making the log redirect work,
and removing explicit print / io:fwrite calls from test suites.
Some parts will be harder to change: I recall the Mnesia test suite
testing coredump generation and that circumvented the test_server GL.
But as you mention a lot of work, I think this will require some changes
to the test_server as well to work cleanly.
- I need some to rethink and consult wanted approach. I will let you know about the outcome.
Sure, thank you.
|
I have no strong opinion here. Just thought that having it on make level, would suggest it will apply silencing also to compilation process ... which might further increase the scope of work ;-) (maybe better to leave aside in the beginning - compilation process i mean). |
Hi @u3s, I know it's summer vacation time, I just wanted to check in to make sure we're on the same page - the further changes I mentioned above should wait until we figured out how to fix the log capture, or should I start work on those already? |
hi @jchristgit , you're right, vacation time affects us a little. nevertheless, in general I think you can slowly start proceeding with this PR. we had some discussion with @garazdawi about it and are both positive about this potential new CT feature (combining wanted characteristics under single umbrella). we even considered if this should become new default behavior at some later OTP release. I hope @garazdawi can write his thoughts when he has time. |
I agree with @u3s that your plan looks good. There will have to be changes in CT to make this all work properly, it cannot all be done using hooks/event handlers. It might even be better to just incorporate it into CT directly instead of building it as a layer on top. In my opinion the end goal for this should be that rebar3 no longer needs cth_readable, but instead CT output is compact enough for their and our use-cases. There will always be arguments about how verbose the output should be, so we will have to figure out some good defaults and introduce some tuning nobs to make most users happy (for instance this issue was just opened on the rebar3 project about changing how skipped testcases are shown). I think that the new compact output should be the default and we will introduce a "-verbose" flag for CT to restore the backwards compatible behaviour. To allow users to tune the output a bit we could also add "-verbose error" and "-verbose skipped". The output of We also need to think a bit about what will happen when ct:break is called? Do we print all captured output for the testcase then? |
Thank you for the feedback! I've pushed another commit to reduce the log output on startup by default. I am a fan of having a Another question: to allow to span the terminal nicely I would like to make use of
What about something inbetween: we could hold the captured output and when the break is entered and log messages have been captured, log something such as % Holding 12 captured log message(s) for current test case, use `ct:flush` to display ... or alternatively add a |
I was imagining it minimizing as much as possible. If we start out being aggressive we can later re-introduce things that we find are missing from the output.
You should be able to do
Having thought about it a bit more, maybe we can just leave it as is and if anyone wants to use ct:break they just have to run in verbose mode for the time being. |
Happy user of verbose output here. For me any console output indicates an error, and sometimes that's the only way to catch some bugs. For example a process may crash and an error log gets printed, but the test still passes. Occasionally output is expected and can't always easily be silenced (for example Happy to add a
It's not like we'd like to do this but sometimes it's the only way to get anything printed, in particular when multiple nodes are involved and we can't easily use the peer functionality (such as RabbitMQ nodes). |
9b7f21b
to
84f1fe0
Compare
To reproduce: try any test case which timetraps
Thanks for digging further, this was the missing piece for me! Timetrap
timeouts were not reported with a traceback, causing the result
formatting to crash (thus breaking further reporting).
This should be fixed now.
|
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
briefly reviewed code (hope to make a better one next week).
see comments in code
handler. To use this mode, pass the <c>-verbose</c> flag to <c>ct_run</c>. | ||
<c>-verbose</c> is the short form of disabling the builtin | ||
configuration of the hook and reconfiguring it:</p> | ||
<p> |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
dangling
?
This breaks doc generation process (can be checked with scripts/otp_build_check
)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yep, I reworked this when Lukas suggested making it the default and this wasn't updated fully yet. Fixed in 7e0b561
<c>-verbose</c> is the short form of disabling the builtin | ||
configuration of the hook and reconfiguring it:</p> | ||
<p> | ||
<p><c>-enable_builtin_hooks false -ct_hooks cth_log_redirect [{mode,replace}]</c></p> |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
should it be {mode, add} in line above?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Fixed in 7e0b561
<tag><c><![CDATA[-verbose]]></c></tag> | ||
<item><p>Enables output of supervisor reports and other logging messages | ||
directly to the terminal as the test is running. If not supplied, these | ||
messages will be captured and only show up in the HTML report.</p></item> |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
how this should be understood?
having exactly same behavior as before this PR?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yes, before the PR these are printed to the terminal, and without -verbose
they are printed there again by changing the log capture hook
lib/common_test/src/ct_console.erl
Outdated
-module(ct_console). | ||
-export([print_header/1, print_results/1, pluralize/3]). | ||
|
||
%% Colored output formatting charaters |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
typo: charaters -> characters
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thanks! Fixed in 2a0b32a
lib/common_test/src/ct_console.erl
Outdated
case os:getenv("NO_COLOR") of | ||
false -> | ||
Color; | ||
Value when Value =/= "" -> |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I see setting NO_COLOR to true disables colors in terminal output (kind of expected ;-))
But when redirected to text file, it still contains funny characters (file not being just text)
^[[0m22 passed^[[0m in 0 seconds^[[0m
Is this wanted? Please explain.
Pure text files are nice for further processing ...
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Pure text files are nice for further processing ...
Fully agree :D
No, this is not wanted. I pushed 541388d which checks if stdout is a tty and if not disables colored output as well. Note that the terminal width still seems to be determined from the executing terminal though. Should we change that to an e.g. 80 column default, so you don't have different widths after every run?
lib/common_test/src/ct_run.erl
Outdated
@@ -131,8 +132,9 @@ script_start(Args) -> | |||
_ -> "" | |||
end | |||
end, | |||
io:format("~nCommon Test~s starting (cwd is ~ts)~n~n", | |||
[CTVsn,Cwd]), | |||
Header = io_lib:format("common test~s starting", [CTVsn]), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Common Test
spelling is all over the place (code and docs). Should we leave it with capitals?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Sure, I pushed it in 3c37db5
The motivation here is to rely on the Common Test HTML logs to store and contain these logs and keep the terminal clean of output that cannot be attributed to specific running test cases, allowing Common Test to supply wanted logging information on the terminal. Related to erlang#7375.
We had a discussion about next steps with this PR. I know we've came long way with this PR to come to those conclusions, I would wish to give you that feedback much earlier :-/. Main goals are:
Proposal would be (naming is just initial suggestion):
Possibly wanted features:
|
We had a discussion about next steps with this PR.
We would like the current approach to be adjusted, so it fits better into CT application.
I know we've came long way with this PR to come to those conclusions, I would wish to give you that feedback much earlier :-/.
I fully understand, there were a lot of opinionated changes to a very
much core tool here, and regardless I think the value of this pull
request is in exploring some ideas and working out where to go next!
Proposal would be:
[...]
The proposal sounds good to me, I support the suggestion of working with
& extending the hook functionality as needed. My only concern is how we
will be able to cleanly configure `ct:print` to log into a file instead,
but I think it's for the PRs to figure that out.
I'm a bit occupied with job search at the moment (maybe this time I can
find something with Erlang :-)) but I will try to get something up
quickly.
I will close this PR then and open a new one as planned soon :-)
|
Great. It served its purpose well I think.
Yes, we will explore that. I hope that having a known wanted direction we can solve it somehow.
Good look in job search. Your contribution to Erlang/OTP project is significant, I wish it converts into some nice Erlang related opportunity.
I don't have strong opinion if PR1 or PR2 should be first. Maybe we could have such order: Where: |
@jchristgit - could you create a PR containing cth_log_redirect updates only? I am after optional functionality taking logger notifications out of terminal and having them in testcase log HTMLs(as cth_log_redirect name actually suggests) - as you did in this PR. |
I think #7788 should do that? The log reports appear in the HTML for me
either way, and with "-out /dev/null" from that PR you can hide messages
on the console.
|
|
In addition to the existing way of logging to both the CT HTML logs and console, allow users to completely replace the standard logging handler with the log redirect hook, effectively silencing console logging output during Common Test runs. Mostly taken from erlang#7375, with the caveat that "add" mode continues being the default, and no changes outside of the hook take place. Additionally, group cth_log_redirect test cases together to allow for easier module verification.
In addition to the existing way of logging to both the CT HTML logs and console, allow users to completely replace the standard logging handler with the log redirect hook, effectively silencing console logging output during Common Test runs. Mostly taken from erlang#7375, with the caveat that "add" mode continues being the default, and no changes outside of the hook take place. Additionally, group cth_log_redirect test cases together to allow for easier module verification.
In addition to the existing way of logging to both the CT HTML logs and console, allow users to completely replace the standard logging handler with the log redirect hook, effectively silencing console logging output during Common Test runs. Mostly taken from erlang#7375, with the caveat that "add" mode continues being the default, and no changes outside of the hook take place. Additionally, group cth_log_redirect test cases together to allow for easier module verification.
In addition to the existing way of logging to both the CT HTML logs and console, allow users to completely replace the standard logging handler with the log redirect hook, effectively silencing console logging output during Common Test runs. Mostly taken from erlang#7375, with the caveat that "add" mode continues being the default, and no changes outside of the hook take place. Additionally, group cth_log_redirect test cases together to allow for easier module verification.
When running tests at present via
make test
, the developer is met with lots of messages from both the testing script and logger messages emitted through libraries called by the testcases themselves. This clutters the output and makes it hard to distinguish actual test suite failures from regular progress and other logging messages.This commit introduces support for interpreting the
-s
/--silent
/--quiet
option frommake
and utilizing it to run tests in a more quiet manner. Specifically, this means that log output is redirected to/dev/null
, and the banners and disclaimers from the testing script are reduced to a minimum (under the assumption that the person running the tests is familar with them).logger_std_h
is updated to skip logging filesync errors when instructeed to log to/dev/null
. The logging redirect in particular is currently only configured on Unix as I do not have a Windows box to test it with.In
inets
, this reduces the output emitted by the tests on the command line from 2175 to 803 lines.Of course this is all a bit opinionated (see the section below), so feel free to reject it 🙂
Overall motivation and goal
This is less specific to this PR in particular, but more a general comment with the hopes of receiving some additional opinions:
I come mainly from Python and personally find the default test outputs when testing OTP apps to be relatively frustrating to work with for the reasons mentioned above. Common Test has some great features for writing tests, but I personally really miss having some clean default logging that:
.
for passed testss
for skipped testsx
for x-fails (expected failures), (CT doesn't have this)F
for failed tests (failed assertions or explicit fails)E
for errored tests (failed outside of assertions), (not sure if this distinction is possible with CT, pytest performs assertion rewriting)When OTP test cases pass locally and then fail on GitHub, the workflow I currently follow is:
unzip
,tar xzf
themct_logs
index.html
in a browser-> and here I can see the test failure.
For an example of what I'm talking about, this is what starting a test of the
pytest
project withpytest
itself looks like:Output in this form keeps going until the end of the test session, where I get a short report:
I may be missing some knob with the testing scripts or
ct_run
itself here or I may be in the minority in finding the current behaviour unintuitive. If this is not the case, I would be happy to contribute to improve the status quo. Perhaps an event handler could be used for the logging mentioned above?