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

ct: Allow running tests more silently / improve ct_run's terminal output #7375

Closed
wants to merge 22 commits into from

Conversation

jchristgit
Copy link
Contributor

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 from make 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:

  • shows me the progression of the test suite at a glance
    • green . for passed tests
    • yellow s for skipped tests
    • yellow x for x-fails (expected failures), (CT doesn't have this)
    • red F for failed tests (failed assertions or explicit fails)
    • red E for errored tests (failed outside of assertions), (not sure if this distinction is possible with CT, pytest performs assertion rewriting)
    • information about the current test file and overall progress
  • captures anything emitted to stdout / stderr by the test cases and only prints it when a failure occurs (or a more verbose mode is used).

When OTP test cases pass locally and then fail on GitHub, the workflow I currently follow is:

  • download the test results for the failed app (I often work on a weak machine and the full logs usually lag my browser too much)
  • unzip, tar xzf them
  • Head into ct_logs
  • Open index.html in a browser
  • Sort by test result to get failed results at the top
    -> 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 with pytest itself looks like:

image

Output in this form keeps going until the end of the test session, where I get a short report:

image

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?

@github-actions
Copy link
Contributor

github-actions bot commented Jun 7, 2023

CT Test Results

       4 files     187 suites   53m 0s ⏱️
1 914 tests 1 555 ✔️ 186 💤 173
2 444 runs  2 050 ✔️ 219 💤 175

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

@garazdawi garazdawi self-assigned this Jun 8, 2023
@garazdawi
Copy link
Contributor

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.

@jchristgit
Copy link
Contributor Author

Good morning! Thank you for the quick review.

Have you tried using https://github.com/ferd/cth_readable to limit the output? I think it should work without rebar3.

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"

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.

This sounds good. Digging into Common Test a bit more, I found cth_log_redirect. With a small change, this hook could replace the default logger to fully capture logs into CT (currently it adds a new handler), and another small change to capture all logs in there (not just sasl and error_logger as it seems currently?). What do you think about:

  • adding the "replace default logger and capture all logs" functionality via a hook option
  • documenting the hook option in the hooks user guide chapter
  • and using said hook option in the OTP testing script when quiet is passed?

That way we can keep information from logs in the CT HTML output for detailed tests whilst slimming down shell output.

@garazdawi
Copy link
Contributor

I think that sounds like a good idea! What do you think @u3s ?

@u3s
Copy link
Contributor

u3s commented Jun 9, 2023

I think that sounds like a good idea! What do you think @u3s ?

I would like to have such knob available in ct_run

Common Test has some great features for writing tests, but I personally really miss having some clean default logging

  • me too :-) especially when checking legacy tests - I would like to see that something is going on, and it is progressing. short and quite compressed preferably (the more test case results can be visualized on secondary display the better!)
  • one thing someone can do is to open index.html while execution is ongoing and track progress in the browser. but this requires a browser, i usually use emacs eww which can be run in terminal, but still this is HTML and is not that terminal friendly and you have to refresh the page manually in worst case :-(
  • cth_readable is still a bit verbose (one line per test case is a lot if you have some hundreds of legacy tests to check) (maybe there is some adjustment in that code that could be more compressed in output)
  • because of above I've scribbled a CTH module that collects information about test progress and writes them to text file which I could watch or tail_f.
  • output contains current test suite progress, totals and some timing info. it can visualize thousands of test case results on a single terminal screenshot. looks something like this:
    image

When OTP test cases pass locally and then fail on GitHub, the workflow I currently follow is:

Can't you open https://erlang.github.io/prs/7375/ct_logs/index.html ? Is this too heavy?

captures anything emitted to stdout / stderr by the test cases and only prints it when a failure occurs (or a more verbose mode is used).

Yes. This would be great.

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

  • mee too :-)

That way we can keep information from logs in the CT HTML output for detailed tests whilst slimming down shell output.

Yes, I would prefer HTML logs to stay verbose but it would be great to have an option for trimming shell.

@jchristgit jchristgit force-pushed the more-silent-tests branch 2 times, most recently from 42beeb4 to acb9434 Compare June 9, 2023 12:15
@jchristgit
Copy link
Contributor Author

I would like to have such knob available in ct_run

I have updated my commit such that cth_log_redirect now accepts an option mode, which tells it whether to add to or replace the default logging handlers. Adding - the old behaviour - remains as the default. I can also update this such that replacing is the default behaviour.

  • cth_readable is still a bit verbose (one line per test case is a lot if you have some hundreds of legacy tests to check) (maybe there is some adjustment in that code that could be more compressed in output)

I think cth_readable_compact_shell would be the handler you are looking for. For non-passed cases I think it still outputs a lot more though.

  • because of above I've scribbled a CTH module that collects information about test progress and writes them to text file which I could watch or tail_f.
  • output contains current test suite progress, totals and some timing info. it can visualize thousands of test case results on a single terminal screenshot.

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!

Can't you open https://erlang.github.io/prs/7375/ct_logs/index.html ? Is this too heavy?

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 self() instead of group_leader()): https://github.com/jchristgit/otp/actions/runs/5205444327. There are some notes about test failures on the test log page but for full details I need to download the result archive, common_test_test_results, which comes in at 605 MB. This is probably an extreme example (the other results are always much smaller), but I don't have any online HTML preview there.

captures anything emitted to stdout / stderr by the test cases and only prints it when a failure occurs (or a more verbose mode is used).

Yes. This would be great.

I will see what I can do to help adding something like this 🙂

@jchristgit jchristgit force-pushed the more-silent-tests branch 2 times, most recently from b5ea032 to e11a4b8 Compare June 9, 2023 19:47
@jhogberg jhogberg added team:VM Assigned to OTP team VM team:PS Assigned to OTP team PS labels Jun 12, 2023
Comment on lines +178 to -175
%% 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;
Copy link
Contributor

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?

Comment on lines +178 to -175
%% 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;
Copy link
Contributor

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?

Copy link
Contributor Author

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.

Copy link
Contributor Author

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...

Copy link
Contributor

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.

Comment on lines +178 to -175
%% 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;
Copy link
Contributor

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.

@u3s
Copy link
Contributor

u3s commented Jun 21, 2023

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?

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?

@jchristgit
Copy link
Contributor Author

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.

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?

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.

I will check this out!

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?

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:

  • first this PR to reduce output from the test script and allow redirecting all logs
  • another to quiet down CT's startup log a bit (I don't really need to know about test suite recompiles unless something failed)
  • if that matured a bit, a documented option -brief (or anything else) for ct_run, that will be used to enable the new output format
  • changes to some matured OTP test suites to e.g. use ct:log instead of ct:pal
  • adding the event handler / hook to show progress while running tests (like your PR)
  • collecting failed tests in the event handler and reporting failures at the end
  • adding colour and other goodies.

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.

@u3s
Copy link
Contributor

u3s commented Jun 22, 2023

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.

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 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.

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?

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:

  • first this PR to reduce output from the test script and allow redirecting all logs
  • another to quiet down CT's startup log a bit (I don't really need to know about test suite recompiles unless something failed)
  • if that matured a bit, a documented option -brief (or anything else) for ct_run, that will be used to enable the new output format

Yes. I think we should try to leave default as is.

  • changes to some matured OTP test suites to e.g. use ct:log instead of ct:pal
  • adding the event handler / hook to show progress while running tests (like your PR)
  • collecting failed tests in the event handler and reporting failures at the end
  • adding colour and other goodies.

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 🙂

  • 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 ...
  • 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 ...
  • I need some to rethink and consult wanted approach. I will let you know about the outcome.

@jchristgit
Copy link
Contributor Author

jchristgit commented Jun 22, 2023 via email

@u3s
Copy link
Contributor

u3s commented Jun 23, 2023

  • 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 ...

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.

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).
What do you think? @garazdawi

@jchristgit
Copy link
Contributor Author

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?

@u3s
Copy link
Contributor

u3s commented Jul 11, 2023

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.

@garazdawi
Copy link
Contributor

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 ct:pal and ct:print should be captured by default. If "-verbose error" is set then it will be printed with the error. If the user want to print to stdout when in compact mode they can call io:format(user | standard_error,... to force the output, not that I see why anyone would like to do this. As you have discovered there are testcases today that try to circumvent CT I/O capture and also there are testcases in C that write debug output directly to stdout/stderr, which will be impossible to capture.

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?

@jchristgit
Copy link
Contributor Author

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 -verbose flag to restore the previous behaviour. Could you clarify whether this should just concern printing the log output from ct:pal and ct:print along with skipped / failed test case results as before, or other output as well? (From that I can determine whether the test server or ct_run itself will need to be changed).

Another question: to allow to span the terminal nicely I would like to make use of prim_tty:window_size - more specifically the tty_geometry message - but as I understand it it's only usable from interactive shells started via the group driver. SSH and the default shell seem to make use of it (and I can use it in the shell). When I try to use it from within ct_run's startup I run into a timeout. Is there a straightforward way to receive the terminal geometry that I'm missing?

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?

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 ct:break/3 that takes options, including a flush option to flush captured messages?

@garazdawi
Copy link
Contributor

Could you clarify whether this should just concern printing the log output from ct:pal and ct:print along with skipped / failed test case results as before, or other output as well?

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.

Another question: to allow to span the terminal nicely I would like to make use of prim_tty:window_size - more specifically the tty_geometry message - but as I understand it it's only usable from interactive shells started via the group driver. SSH and the default shell seem to make use of it (and I can use it in the shell). When I try to use it from within ct_run's startup I run into a timeout. Is there a straightforward way to receive the terminal geometry that I'm missing?

You should be able to do io:columns(user) to fetch the window width.

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?

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 ct:break/3 that takes options, including a flush option to flush captured messages?

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.

@essen
Copy link
Contributor

essen commented Jul 17, 2023

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 ssl warnings) so I print an informative ct:pal to indicate this output is not an error.

Happy to add a -verbose to the command line. But the gotcha mentioned in my first paragraph should probably be documented somewhere if silent becomes the default.

If the user want to print to stdout when in compact mode they can call io:format(user | standard_error,... to force the output, not that I see why anyone would like to do this

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).

@jchristgit jchristgit force-pushed the more-silent-tests branch 2 times, most recently from 9b7f21b to 84f1fe0 Compare July 19, 2023 10:04

Verified

This commit was signed with the committer’s verified signature.

Verified

This commit was signed with the committer’s verified signature.

Verified

This commit was signed with the committer’s verified signature.
@jchristgit
Copy link
Contributor Author

jchristgit commented Sep 21, 2023 via email

Copy link
Contributor

@u3s u3s left a 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>
Copy link
Contributor

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)

Copy link
Contributor Author

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>
Copy link
Contributor

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?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed in 7e0b561

Comment on lines +272 to +275
<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>
Copy link
Contributor

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?

Copy link
Contributor Author

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

-module(ct_console).
-export([print_header/1, print_results/1, pluralize/3]).

%% Colored output formatting charaters
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

typo: charaters -> characters

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks! Fixed in 2a0b32a

case os:getenv("NO_COLOR") of
false ->
Color;
Value when Value =/= "" ->
Copy link
Contributor

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 ...

Copy link
Contributor Author

@jchristgit jchristgit Sep 23, 2023

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?

@@ -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]),
Copy link
Contributor

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?

Copy link
Contributor Author

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

Verified

This commit was signed with the committer’s verified signature.

Verified

This commit was signed with the committer’s verified signature.

Verified

This commit was signed with the committer’s verified signature.

Verified

This commit was signed with the committer’s verified signature.

Verified

This commit was signed with the committer’s verified signature.
jchristgit added a commit to jchristgit/otp that referenced this pull request Sep 23, 2023

Verified

This commit was signed with the committer’s verified signature.
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.

Verified

This commit was signed with the committer’s verified signature.

Verified

This commit was signed with the committer’s verified signature.
@u3s u3s added this to the OTP-27.0 milestone Sep 27, 2023
@u3s
Copy link
Contributor

u3s commented Sep 29, 2023

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'm hoping that, maybe with a small detour, we will end up with a more futureproof and flexible solution.

Main goals are:

  1. not assuming too much about user preference - give them possibility to decide (leave legacy output available for ones needing it)
  2. be able to handle scenarios when a user wants: both outputs (legacy stdout and new execution progress summary) or none of those at all
  3. make CT internal code changes more generic and easier to maintain
  4. re-use ct_hooks interface (extend if needed) for purpose of displaying progress execution reports (seems to be designed for doing stuff in sync with test execution)
  5. provide tools for simplifying 3rd party libs - e.g. rebar3

Proposal would be (naming is just initial suggestion):

  1. split this PR into 2 main ones providing new arguments to CT run
  2. PR1 "-out LEGACY_STDOUT_FILE", if specified:
    • redirects logger reports and ct:print(+friends from CT API) to text file
    • not redirecting erlang:display, io:fwrite(user - so hook module could print to terminal
  3. PR2 providing builtin CT hook for displaying short progress execution report on terminal
  4. leave discussion about changing default behavior for later stage as it is not trivial and it would be better to have PR1 and PR2 ready (I mean default CT behavior, OTP make output can be included in PR2 ... I think)
  5. so in first stage, ct_run would require both new arguments for getting 'silent' output (something like: ct_run -out legacy_out.txt -ct_hooks summary_report

Possibly wanted features:

  1. (PR2) checking how hook module could receive part of stdout in case of testcase failure (if not straightforward could become PR3)
  2. quick thought, when displaying partial stdout in case of failure (it would be good to display testcase name and group - information useful for retesting just failures (maybe present already in code proposal - I'm not sure))
  3. (PR1)link to stdout file in index.html (next to COMMON TEST FRAMEWORK LOG link)

@jchristgit
Copy link
Contributor Author

jchristgit commented Sep 30, 2023 via email

@jchristgit jchristgit closed this Sep 30, 2023
@u3s
Copy link
Contributor

u3s commented Oct 2, 2023

We had a discussion about next steps with this PR. We would like the current approach to be adjusted...

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!

Great. It served its purpose well I think.

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.

Yes, we will explore that. I hope that having a known wanted direction we can solve it somehow.

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.

Good look in job search. Your contribution to Erlang/OTP project is significant, I wish it converts into some nice Erlang related opportunity.

I will close this PR then and open a new one as planned soon :-)

I don't have strong opinion if PR1 or PR2 should be first. Maybe we could have such order:
PR2' - PR1 - PR2'' -PR3

Where:
PR2' - (no dependencies) is hook handler printing expected summary to text file (could be a value on its own and merged quick)
PR1 - (no dependencies) '-out' parameter in ct_run
PR2'' - (depends on PR1) adjustment of hook handler, so it logs to terminal
PR3 - (depends on PR1) enhances hook handler to include failed related terminal output

@u3s
Copy link
Contributor

u3s commented Nov 18, 2023

@jchristgit - could you create a PR containing cth_log_redirect updates only?
I think it would be useful and go a quick path, being simple.

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.

@jchristgit
Copy link
Contributor Author

jchristgit commented Nov 19, 2023 via email

@u3s
Copy link
Contributor

u3s commented Nov 20, 2023

  • I'm afraid ct: Add -out parameter to ct_run #7788 might take much longer than wanted (bigger API change, potentially some code re-org, concept not clear etc.)
  • cth_log_redirect update in this PR is just an option for hook handler - might be mergeable quicker and could be a nice improvement companion together with ct: cte_track event handler #7427 (so we see improvement in GH actions test runs output quicker)

jchristgit added a commit to jchristgit/otp that referenced this pull request Nov 20, 2023

Verified

This commit was signed with the committer’s verified signature.
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.
jchristgit added a commit to jchristgit/otp that referenced this pull request Nov 20, 2023

Verified

This commit was signed with the committer’s verified signature.
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.
jchristgit added a commit to jchristgit/otp that referenced this pull request Nov 20, 2023

Verified

This commit was signed with the committer’s verified signature.
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.
@jchristgit
Copy link
Contributor Author

I opened #7891 which implements just the cth_log_redirect changes from this PR. Feel free to close #7788 (it's an alternative approach with the destination file as opposed to add / replace modes) if no -out parameter should be added.

jchristgit added a commit to jchristgit/otp that referenced this pull request Nov 22, 2023

Verified

This commit was signed with the committer’s verified signature.
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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Planned Focus issue added in sprint planning team:PS Assigned to OTP team PS
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

6 participants