How to see log output of passing browser_tests running locally?

[James Cook]

I noticed today that when I run browser_tests I get very concise output, like this:

[1/7] ExtensionApiTest.IncognitoNoScript (5505 ms)

[2/7] ExtensionApiTest.IncognitoPopup (6027 ms)

[3/7] ExtensionApiTest.IncognitoDisabledByPref (6813 ms)

...

Sometimes I want to see the log output of these passing tests, for example, when I'm adding debug spam to understand code.  I don't see a flag to print the output in browser_tests --help or browser_tests --gtest_help.

Is there some way I can make it print the output for passing tests?

James

[Paweł Hajdan, Jr.]

With https://codereview.chromium.org/46043019 and --test-launcher-print-test-stdio=always you should get the needed functionality.

It's not yet in --help - I'll gladly take a CL to add it, or I can also just add it when I can.

Paweł

--
--
Chromium Developers mailing list: chromi...@chromium.org
View archives, change email options, or unsubscribe:
http://groups.google.com/a/chromium.org/group/chromium-dev

[Satoru Takabayashi]

I was also puzzled by the concise output, and found this thread after some digging. Would it make sense to change the default back to be verbose? I often run specific tests locally when I'm writing or debugging tests, hence verbose output is more convenient. I think the concise output is great for bots.

Satoru

[Paweł Hajdan, Jr.]

Sorry about that. I'd be fine with changing the defaults - maybe let's see what other people think, and in case of no comments you can just remind me or send a CL for that.

I'll be changing some things buildbot-side, which will also make it easier to pass a "quiet" option on the bots.

Paweł

[Nico Weber]

On Wed, Oct 30, 2013 at 2:14 PM, Paweł Hajdan, Jr. <phajd...@chromium.org> wrote:

Sorry about that. I'd be fine with changing the defaults - maybe let's see what other people think, and in case of no comments you can just remind me or send a CL for that.

I'll be changing some things buildbot-side, which will also make it easier to pass a "quiet" option on the bots.

Shouldn't we change the tests to not print so much instead of suppressing stdout by default? Is stderr suppressed too?

[Satoru Takabayashi]

On Thu, Oct 31, 2013 at 6:17 AM, Nico Weber <tha...@chromium.org> wrote:

On Wed, Oct 30, 2013 at 2:14 PM, Paweł Hajdan, Jr. <phajd...@chromium.org> wrote:

Sorry about that. I'd be fine with changing the defaults - maybe let's see what other people think, and in case of no comments you can just remind me or send a CL for that.

I'll be changing some things buildbot-side, which will also make it easier to pass a "quiet" option on the bots.

Shouldn't we change the tests to not print so much instead of suppressing stdout by default? Is stderr suppressed too?

Yes. stderr too. What I usually do is to add LOG(ERROR) to printf-debug tests, and the output is suppressed by default now.

BTW, with --test-launcher-print-test-stdio=always, I noticed that output was buffered until the test ends. This is inconvenient for browser tests, which take about 30 seconds to fail by timeout, and you cannot see the output until they timed out. Would it be difficult to make this unbuffered? To workaround this, I ended up using --single_process flag. 

[James Cook]

+1 to keeping the default verbose

[Sadrul Chowdhury]

Continuing from the discussion on https://codereview.chromium.org/61363002

On 2013/11/06 19:47:19, Paweł Hajdan Jr. wrote:
> On 2013/11/06 17:39:55, sadrul wrote:
> > It would hurt the bots even less to add a custom flag to suppress the
> > stdout/stderr. We should not require developers to remember all the flags they
> > need to use. The bots can remember that with much more ease.
>
> Sadrul, I'm happy to continue the discussion off-Rietveld. Short response for
> now: arguably there are cases when running locally you want to run the tests as
> fast as possible (and with retries for stability). When you are debugging,
> passing one flag is reasonable IMHO. Assumption that developers are always
> debugging is just not true I think, unless there is evidence (can be just many
> people agreeing with that).

This is precisely my point. Developers are usually not always
debugging the tests. Which is exactly why the developers will forget
this special flag they have to use, and waste time looking for it when
they do have to debug. It's easy for the bots, on the other hand, to
always use the flag to suppress the output.

> Feel free to do a poll or something -

Have we always made such decisions based on polls/votes?

Sadrul

> for now I'm
> just trying to add an option that does address the issue in some (maybe
> imperfect) way.

> To unsubscribe from this group and stop receiving emails from it, send an
> email to chromium-dev...@chromium.org.

[Paweł Hajdan, Jr.]

On Thu, Nov 7, 2013 at 12:04 PM, Sadrul Chowdhury <sad...@chromium.org> wrote:

Continuing from the discussion on https://codereview.chromium.org/61363002

On 2013/11/06 19:47:19, Paweł Hajdan Jr. wrote:
> On 2013/11/06 17:39:55, sadrul wrote:
> > It would hurt the bots even less to add a custom flag to suppress the
> > stdout/stderr. We should not require developers to remember all the flags they
> > need to use. The bots can remember that with much more ease.
>
> Sadrul, I'm happy to continue the discussion off-Rietveld. Short response for
> now: arguably there are cases when running locally you want to run the tests as
> fast as possible (and with retries for stability). When you are debugging,
> passing one flag is reasonable IMHO. Assumption that developers are always
> debugging is just not true I think, unless there is evidence (can be just many
> people agreeing with that).

This is precisely my point. Developers are usually not always
debugging the tests. Which is exactly why the developers will forget
this special flag they have to use, and waste time looking for it when
they do have to debug. It's easy for the bots, on the other hand, to
always use the flag to suppress the output.

I'm open to reversing the defaults given enough data. For now I added an option so that it's possible to debug the tests easily with the new launcher. FWIW the option is --test-launcher-developer-mode . To anyone participating in the discussion: please sync your tree, check it out (--brave-new-test-launcher --test-launcher-developer-mode) and let me know what you think.

Note that there are two types of test runs developers do:

1. Run tests (all or subset) as quickly and reliably as possible to validate a local change to the code. Given that parallelization can speed this up several times depending on the number of CPU cores, and test retries help with reliability, both are very important for this scenario.

2. Debug specific failing tests (sometimes new tests being added). Here the priority is ease of debugging (including printf-based debugging).

Furthermore, bots do exactly scenario (1) above.

The question now is - what do developers do more often: (1) or (2)? Should we be doing (1) locally more often now that it's faster and more stable? Feedback loops are obviously faster locally than with trybots.

 

> Feel free to do a poll or something -

Have we always made such decisions based on polls/votes?

I've seen a couple of polls on blink-dev. Here the question is: how do you get the data which scenario (1 or 2) do developers do more often? How do you back with data claims whether majority of developers knows or wants something or not? That can also be part of the discussion, but so far I don't see a widespread criticism of the defaults.

Please note I'm aware of different workflows and styles. Hey, I'm using version control workflow that is not documented anywhere and officially not supported. I'd like to support whatever people are doing that helps them be productive (or even is essential to productivity) that fits well with other parts of testing infrastructure. Defaults are more tricky - while the current ones make sense to me, I can be convinced otherwise.

Paweł

[Alexei Svitkine]

Can it default to (1) and when a test fails, its output is shown in format (2)? (i.e. have the test runner buffer the output for each test and print it at the end for any failing test)

--

[Paweł Hajdan, Jr.]

I think this is also what the new test launcher does. Please let me know if you'd like to see something different, with specific examples of what you see and what you'd like to see instead.

Paweł

On Sun, Nov 10, 2013 at 9:32 AM, Greg Thompson <g...@google.com> wrote:

This is more or less what chrome_frame_tests.exe does. It has been very useful.

[Scott Violet]

+1 to keeping the default verbose.

At a minium the bots should output the new flag (much like we do with
single_process).

-Scott

[Dana Jansens]

On Thu, Nov 7, 2013 at 1:33 PM, Paweł Hajdan, Jr. <phajd...@chromium.org> wrote:

On Thu, Nov 7, 2013 at 12:04 PM, Sadrul Chowdhury <sad...@chromium.org> wrote:

Continuing from the discussion on https://codereview.chromium.org/61363002

On 2013/11/06 19:47:19, Paweł Hajdan Jr. wrote:
> On 2013/11/06 17:39:55, sadrul wrote:
> > It would hurt the bots even less to add a custom flag to suppress the
> > stdout/stderr. We should not require developers to remember all the flags they
> > need to use. The bots can remember that with much more ease.
>
> Sadrul, I'm happy to continue the discussion off-Rietveld. Short response for
> now: arguably there are cases when running locally you want to run the tests as
> fast as possible (and with retries for stability). When you are debugging,
> passing one flag is reasonable IMHO. Assumption that developers are always
> debugging is just not true I think, unless there is evidence (can be just many
> people agreeing with that).

This is precisely my point. Developers are usually not always
debugging the tests. Which is exactly why the developers will forget
this special flag they have to use, and waste time looking for it when
they do have to debug. It's easy for the bots, on the other hand, to
always use the flag to suppress the output.

I'm open to reversing the defaults given enough data. For now I added an option so that it's possible to debug the tests easily with the new launcher. FWIW the option is --test-launcher-developer-mode . To anyone participating in the discussion: please sync your tree, check it out (--brave-new-test-launcher --test-launcher-developer-mode) and let me know what you think.

FWIW the first thing I did was add the --test-launcher-developer-mode to my script to run cc_unittests, as well as --test-launcher-jobs=1 (and now --single-process-tests) whenever a --gtest_filter is present or I'm running the tests in valgrind or gdb.

It's a lot of flags to remember or add to scripts IMO. I'd rather the bots have the hard work, and you have flags to let devs speed things up if they need/want it. Also IMHO retries are probably harmful outside of bots, as it hides flakiness further from developers who are running tests and maybe even in the process of introducing flakiness, or working in the area of flakiness.

I think in my ideal world I'd just have a --parallel flag that can be used to run them in parallel, and maybe a --quiet flag to turn off stdio if people/bots like that behaviour.

 

Note that there are two types of test runs developers do:

1. Run tests (all or subset) as quickly and reliably as possible to validate a local change to the code. Given that parallelization can speed this up several times depending on the number of CPU cores, and test retries help with reliability, both are very important for this scenario.

2. Debug specific failing tests (sometimes new tests being added). Here the priority is ease of debugging (including printf-based debugging).

Furthermore, bots do exactly scenario (1) above.

The question now is - what do developers do more often: (1) or (2)? Should we be doing (1) locally more often now that it's faster and more stable? Feedback loops are obviously faster locally than with trybots.

 

> Feel free to do a poll or something -

Have we always made such decisions based on polls/votes?

I've seen a couple of polls on blink-dev. Here the question is: how do you get the data which scenario (1 or 2) do developers do more often? How do you back with data claims whether majority of developers knows or wants something or not? That can also be part of the discussion, but so far I don't see a widespread criticism of the defaults.

Please note I'm aware of different workflows and styles. Hey, I'm using version control workflow that is not documented anywhere and officially not supported. I'd like to support whatever people are doing that helps them be productive (or even is essential to productivity) that fits well with other parts of testing infrastructure. Defaults are more tricky - while the current ones make sense to me, I can be convinced otherwise.

Paweł

--

[John Abd-El-Malek]

+1

The default should not be to change behavior from before Pawel's refactorings, i.e. the change to switch test launchers is an internal implementation detail. The test output suddenly shouldn't get dropped for developers who then have to hunt around for command line flags. This is why I have requested that during this refactoring behavior changes get called out in cl descriptions, and to be added as a reviewer to check this, but that didn't happen.

Regarding 1 & 2, my own experience, and seeing others, it's that developers are overwhelmingly doing 2 and not 1. Running tests locally is often not very useful given the XX configs that trybots run. i.e. who cares if the one config that I'm running passes the one test target, but what really matters to me is that all the tests are passing on all the bots.

[Paweł Hajdan, Jr.]

Alright, I think we have everyone in favor of the defaults changes and no one against. I'll work on getting the defaults changed this way. Please note --brave-new-test-launcher is still opt-in for developers, so you can get the "old" behavior by not passing that flag. I'm sorry for temporary changes in test debugging for people using browser tests (content_browsertests, browser_tests, interactive_ui_tests and so on). Note that the new test launcher is not just refactoring, it is more. The new launcher supports running tests in parallel, which gtest doesn't. It is also more stable and does test retries currently needed on the bots. That means having some behavior changes.

Anyway, I'll just get this fixed. I'll let you know when it's done - I started working on it now.

Paweł

[Paweł Hajdan, Jr.]

Feel free to comment on https://codereview.chromium.org/59623015/

Paweł

[Scott Violet]

For unit tests we now have to pass in --single-process-tests to be
able to run in a debugger. Don't the same arguments in this thread
imply the default should --single-process-tests for unit tests and the
bots pass in something special?

-Scott

On Tue, Nov 12, 2013 at 5:23 PM, Paweł Hajdan, Jr.

[Jeffrey Yasskin]

FWIW, -1 on slowing down the default local execution by passing
--single-process-tests. I believe it's possible to detect that the
current process is running under gdb, and switch to single-process
mode in exactly that case: http://stackoverflow.com/a/3597785/943619

[Scott Violet]

I'm equally fine with automatically switching to single-process-tests
if supplying a filter that identifies one test.

-Scott

[Paweł Hajdan, Jr.]

Responding to all three comments: I'd prefer not to do any of these things. I think I have carefully considered the reasons, but I'm obviously open to further discussion. Here's my story:

1. For browser_tests it was always required to pass --single_process for debugging. It always had a launcher which makes that necessary. Browser cannot be reinitialized in the same address space. The point here is that there is an example established for years that I remember no complaints about.

1a. Maybe I should make it more clear how to debug the tests. Printing something at the beggining and/or end of test execution would be totally fine for me - what do you think?

2. Defaulting to --single-process-tests is equivalent to not using the new test launcher at all. I consider that a loss. The whole idea was to run code much closer to what bots are running. Number of parallel jobs and handling of stdout are minor differences. But I'd really like the control logic of how tests are selected, batched and order to be the same for bots and developers.

3. I prefer not to do too much magic when we detect presence of gdb. Note that I'm not against any magic - in fact, we e.g. increase many timeouts in the presence of debugger (and print a message about that so it's not silent). The problem here is: how do you know whether the developer wants to debug the test or the launcher? It's not obvious, although debugging tests would probably be more common. When debugging, I really prefer the behavior of the program not to change significantly in a potentially very surprising way.

Paweł

[Dana Jansens]

On Tue, Dec 10, 2013 at 9:33 AM, Scott Violet <s...@chromium.org> wrote:

I'm equally fine with automatically switching to single-process-tests
if supplying a filter that identifies one test.

My local scripts use single-process-tests whenever i use a filter of any kind. This has been useful for me.

[Scott Violet]

On Tue, Dec 10, 2013 at 10:28 AM, Paweł Hajdan, Jr.
<phajd...@chromium.org> wrote:
> Responding to all three comments: I'd prefer not to do any of these things.
> I think I have carefully considered the reasons, but I'm obviously open to
> further discussion. Here's my story:
>
> 1. For browser_tests it was always required to pass --single_process for
> debugging. It always had a launcher which makes that necessary. Browser
> cannot be reinitialized in the same address space. The point here is that
> there is an example established for years that I remember no complaints
> about.
>
> 1a. Maybe I should make it more clear how to debug the tests. Printing
> something at the beggining and/or end of test execution would be totally
> fine for me - what do you think?

Given the infrequency of debugging unit tests the cycle has now become:
1. Start gdb, set breaks points and all that.
2. Run test. See breakpoints not hit. Think. Remember Pawel did this
change. Curse Pawel:) Run outside of gdb to get switches.
3. Rerun gdb.

I suspect I am not alone here. So, this change basically is requiring
*everyone* to do more work then they use to.

I personally prefer the old single process flow. Yes, that means I
don't get the benefits of sharding, but generally when I'm running
tests on the command line I want to debug them. At a minimum if there
is a filter that identifies only one test that should be a cue to run
single process.

-Scott

[Brett Wilson]

I agree. If I'm running unit tests locally I'm probably checking
something manually, and I will never remember how to disable sharding.
I always hated this about the UI tests (never remembering how to debug
them) and now it seems like even small unit tests work this way.

Brett

[Robert Sesek]

Could we use base::debug::BeingDebugged() to check if the test binary is being run in the debugger, and if so, do not shard the tests?

rsesek / @chromium.org

[Dana Jansens]

On Tue, Dec 10, 2013 at 1:10 PM, Robert Sesek <rse...@chromium.org> wrote:

Could we use base::debug::BeingDebugged() to check if the test binary is being run in the debugger, and if so, do not shard the tests?

Can it also detect valgrind?  (Just pointing out there's more cases than debugger.)

[Paweł Hajdan, Jr.]

Change in review: https://codereview.chromium.org/101223009/

I really want to put developers first here - users of the test launcher.

Further feedback welcome.

Paweł