Re: [openstack-dev] testr help
On Wed, Mar 12 2014, John Dennis wrote:
> On 03/12/2014 01:22 PM, Zane Bitter wrote:
>> On 10/03/14 20:29, Robert Collins wrote:
>>> Which bits look raw? It should only show text/* attachments, non-text
>>> should be named but not dumped.
>>
>> I was thinking of the:
>>
>> pythonlogging:'': {{{
>>
>> part.
>
> Yes, this is the primary culprit, it's output obscures most everything
> else concerning test results. Sometimes it's essential information.
> Therefore you should be able to control whether it's displayed or not.
The pythonlogging section didn't used to be so verbose, at least for
Heat's unit tests. I submitted 3 bugs to clean up the test output a few
weeks ago:
https://bugs.launchpad.net/heat/+bug/1281226
https://bugs.launchpad.net/oslo/+bug/1280454
https://bugs.launchpad.net/oslo/+bug/1280435
___
OpenStack-dev mailing list
OpenStack-dev@lists.openstack.org
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
Re: [openstack-dev] testr help
On 03/12/2014 01:22 PM, Zane Bitter wrote:
> On 10/03/14 20:29, Robert Collins wrote:
>> Which bits look raw? It should only show text/* attachments, non-text
>> should be named but not dumped.
>
> I was thinking of the:
>
> pythonlogging:'': {{{
>
> part.
Yes, this is the primary culprit, it's output obscures most everything
else concerning test results. Sometimes it's essential information.
Therefore you should be able to control whether it's displayed or not.
--
John
___
OpenStack-dev mailing list
OpenStack-dev@lists.openstack.org
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
Re: [openstack-dev] testr help
On 10/03/14 20:29, Robert Collins wrote:
Which bits look raw? It should only show text/* attachments, non-text
should be named but not dumped.
I was thinking of the:
pythonlogging:'': {{{
part.
- ZB
___
OpenStack-dev mailing list
OpenStack-dev@lists.openstack.org
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
Re: [openstack-dev] testr help
On Mon, Mar 10, 2014 at 7:20 PM, Zane Bitter wrote:
> On 10/03/14 16:04, Clark Boylan wrote:
>
>> On Mon, Mar 10, 2014 at 11:31 AM, Zane Bitter wrote:
>>
>>> Thanks Clark for this great write-up. However, I think the solution to
>>> the
>>> problem in question is richer commands and better output formatting, not
>>> discarding information.
>>>
>>>
>>> On 07/03/14 16:30, Clark Boylan wrote:
>>>
But running tests in parallel introduces some fun problems. Like where
do you send logging and stdout output. If you send it to the console
it will be interleaved and essentially useless. The solution to this
problem (for which I am probably to blame) is to have each test
collect the logging, stdout, and stderr associated to that test and
attach it to that tests subunit reporting. This way you get all of the
output associated with a single test attached to that test and don't
have crazy interleaving that needs to be demuxed. The capturing of
>>>
>>>
>>> This is not really a problem unique to parallel test runners. Printing to
>>> the console is just not a great way to handle stdout/stderr in general
>>> because it messes up the output of the test runner, and nose does exactly
>>> the same thing as testr in collecting them - except that nose combines
>>> messages from the 3 sources and prints the output for human consumption,
>>> rather than in separate groups surrounded by lots of {{{random braces}}}.
>>>
>>> Except nose can make them all the same file descriptor and let
>> everything multiplex together. Nose isn't demuxing arbitrary numbers
>> of file descriptors from arbitrary numbers of processes.
>>
>
> Can't each subunit process do the same thing?
>
> As a user, here's how I want it to work:
> - Each subunit process works like nose - multiplexing the various streams
> of output together and associating it with a particular test - except that
> nothing is written to the console but instead returned to testr in subunit
> format.
> - testr reads the subunit data and saves it to the test repository.
> - testr prints a report to the console based on the data it just
> received/saved.
>
> How it actually seems to work:
> - A magic pixie creates a TestCase class with a magic incantation to
> capture your stdout/stderr/logging without breaking other test runners.
> - Or they don't! You're hosed. The magic incantation is undocumented.
> - You change all of your TestCases to inherit from the class with the
> magic pixie dust.
> - Each subunit process associates the various streams of output (if you
> set it up to) with a particular test, but keeps them separate so that if
> you want to figure out the order of events you have to direct them all to
> the same channel - which, in practice, means you can only use logging
> (since some of the events you are interested in probably already exist in
> the code as logs).
> - when you want to debug a test, you have to all the tedious loigging
> setup if it doesn't already exist in the file. It probably won't, because
> flake8 would have made you delete it unless it's being used already.
> - testr reads the subunit data and saves it to the test repository.
> - testr prints a report to the console based on the data it just
> received/saved, though parts of it look like a raw data dump.
>
> While there may be practical reasons why it currently works like the
> latter, I would submit that there is no technical reason it could not work
> like the former. In particular, there is nothing about the concept of
> running the tests in parallel that would prevent it, just as there is
> nothing about what nose does that would prevent two copies of nose from
> running at the same time on different sets of tests.
>
>
> this data is toggleable in the test suite using environment variables
and is off by default so that when you are not using testr you don't
get this behavior [0]. However we seem to have neglected log capture
toggles.
>>>
>>>
>>> Oh wow, there is actually a way to get the stdout and stderr? Fantastic!
>>> Why
>>> on earth are these disabled?
>>>
>>> See above, testr has to deal with multiple writers to stdout and
>> stderr, you really don't want them all going to the same place when
>> using testr (which is why stdout and stderr are captured when running
>> testr but not otherwise).
>>
>
> Ah, OK, I think I understand now. testr passes the environment variables
> automatically, so you only have to know the magic incantation at the time
> you're writing the test, not when you're running it.
>
>
> Please, please, please don't turn off the logging too. That's the only
>>> tool
>>> left for debugging now that stdout goes into a black hole.
>>>
>>> Logging goes into the same "black hole" today, I am suggesting that we
>> make this toggleable like we have made stdout and stderr capturing
>> toggleable. FWIW this isn't a black hole it is all captured on disk
>> and you can refer back to it at any time (
Re: [openstack-dev] testr help
On 11 March 2014 12:20, Zane Bitter wrote: >> Except nose can make them all the same file descriptor and let >> everything multiplex together. Nose isn't demuxing arbitrary numbers >> of file descriptors from arbitrary numbers of processes. > > > Can't each subunit process do the same thing? Roughly yes. > As a user, here's how I want it to work: > - Each subunit process works like nose - multiplexing the various streams > of output together and associating it with a particular test - except that > nothing is written to the console but instead returned to testr in subunit > format. subunit certainly supports that. We don't have glue in subunit.run to intercept stdout and stderr automatically and do the association. There are some nuances in getting that *right* that are fairly important (such as not breaking tunnelled debugger use), but I'm very open to the idea of such a thing existing. testtools.run shouldn't multiplex like that (it interferes with pdb) but should perhaps permit it. > - testr reads the subunit data and saves it to the test repository. Which it does. > - testr prints a report to the console based on the data it just > received/saved. Which it does. > How it actually seems to work: > - A magic pixie creates a TestCase class with a magic incantation to > capture your stdout/stderr/logging without breaking other test runners. testr doesn't actually have anything to do with this - its a environment variable in .testr.conf that OpenStack uses. OpenStack has a particularly egregious logging environment, and its inherited nose based test had no friendly capturing/management of that. > - Or they don't! You're hosed. The magic incantation is undocumented. > - You change all of your TestCases to inherit from the class with the magic > pixie dust. > - Each subunit process associates the various streams of output (if you set > it up to) with a particular test, but keeps them separate so that if you > want to figure out the order of events you have to direct them all to the > same channel - which, in practice, means you can only use logging (since > some of the events you are interested in probably already exist in the code > as logs). stdout is buffered by default, stderr is unbuffered by default, logging is on the other side of a mutex - if you have any concurrency going on in your test process (which many do), there is absolutely no guarantee of relative ordering between different sources unless that's done in the generating process - something subunit.run may be able to help with (see above). > - when you want to debug a test, you have to all the tedious loigging setup > if it doesn't already exist in the file. It probably won't, because flake8 > would have made you delete it unless it's being used already. > - testr reads the subunit data and saves it to the test repository. > - testr prints a report to the console based on the data it just > received/saved, though parts of it look like a raw data dump. Which bits look raw? It should only show text/* attachments, non-text should be named but not dumped. > While there may be practical reasons why it currently works like the latter, > I would submit that there is no technical reason it could not work like the > former. In particular, there is nothing about the concept of running the > tests in parallel that would prevent it, just as there is nothing about what > nose does that would prevent two copies of nose from running at the same > time on different sets of tests. The key bit that isn't visible isn't implemented yet, which is a desire to demultiplex stdin from the testr console to the backends, to permit pdb usage in tests. It works in single-worker mode today (across processes) but not in multi-worker mode. > It just seems bizarre to me that the _tests_ have to figure out what test > runner they are being run by and redirect their output to the correct > location to oblige it. Surely the point of a test runner is to do the Right > Thing(TM) for any test, regardless of what it knows about the test runner. Test runners should provide a homogeneous, consistent environment for tests - for sure. >>> BTW, since I'm on the subject, testr would be a lot more >>> confidence-inspiring if running `testr failing` immediately after running >>> `testr` reported the same number of failures, or indeed if running >>> `testr` It should. There as a double-accounting bug in testtools some months back, but you should get the same failure count in testr last as from testr run, since it pulls from the same data. > It makes sense for the case where the test runner has died without reporting > data, but why should it be reported as a separate failure when it has > reported data that testr has regarded as valid enough to use and display? testr synthesises failed tests for a backend in two cases: a) if a test starts but doesn't finish, that is presumed to be a backend failure regardless of backend exit code (e.g. because of code that cal
Re: [openstack-dev] testr help
On Mon, Mar 10, 2014 at 4:20 PM, Zane Bitter wrote:
> On 10/03/14 16:04, Clark Boylan wrote:
>>
>> On Mon, Mar 10, 2014 at 11:31 AM, Zane Bitter wrote:
>>>
>>> Thanks Clark for this great write-up. However, I think the solution to
>>> the
>>> problem in question is richer commands and better output formatting, not
>>> discarding information.
>>>
>>>
>>> On 07/03/14 16:30, Clark Boylan wrote:
But running tests in parallel introduces some fun problems. Like where
do you send logging and stdout output. If you send it to the console
it will be interleaved and essentially useless. The solution to this
problem (for which I am probably to blame) is to have each test
collect the logging, stdout, and stderr associated to that test and
attach it to that tests subunit reporting. This way you get all of the
output associated with a single test attached to that test and don't
have crazy interleaving that needs to be demuxed. The capturing of
>>>
>>>
>>>
>>> This is not really a problem unique to parallel test runners. Printing to
>>> the console is just not a great way to handle stdout/stderr in general
>>> because it messes up the output of the test runner, and nose does exactly
>>> the same thing as testr in collecting them - except that nose combines
>>> messages from the 3 sources and prints the output for human consumption,
>>> rather than in separate groups surrounded by lots of {{{random braces}}}.
>>>
>> Except nose can make them all the same file descriptor and let
>> everything multiplex together. Nose isn't demuxing arbitrary numbers
>> of file descriptors from arbitrary numbers of processes.
>
>
> Can't each subunit process do the same thing?
>
> As a user, here's how I want it to work:
> - Each subunit process works like nose - multiplexing the various streams
> of output together and associating it with a particular test - except that
> nothing is written to the console but instead returned to testr in subunit
> format.
> - testr reads the subunit data and saves it to the test repository.
> - testr prints a report to the console based on the data it just
> received/saved.
>
> How it actually seems to work:
> - A magic pixie creates a TestCase class with a magic incantation to
> capture your stdout/stderr/logging without breaking other test runners.
> - Or they don't! You're hosed. The magic incantation is undocumented.
> - You change all of your TestCases to inherit from the class with the magic
> pixie dust.
> - Each subunit process associates the various streams of output (if you set
> it up to) with a particular test, but keeps them separate so that if you
> want to figure out the order of events you have to direct them all to the
> same channel - which, in practice, means you can only use logging (since
> some of the events you are interested in probably already exist in the code
> as logs).
If you want this behavior then do as nose does and give logging,
stdout, and stderr the same file descriptor to write to. (I think the
current implementation uses StringIO as a sink, just give them all the
same sink).
> - when you want to debug a test, you have to all the tedious loigging setup
> if it doesn't already exist in the file. It probably won't, because flake8
> would have made you delete it unless it's being used already.
I don't understand this, you use oslo logging and the fake logger fixture, done.
> - testr reads the subunit data and saves it to the test repository.
> - testr prints a report to the console based on the data it just
> received/saved, though parts of it look like a raw data dump.
>
> While there may be practical reasons why it currently works like the latter,
> I would submit that there is no technical reason it could not work like the
> former. In particular, there is nothing about the concept of running the
> tests in parallel that would prevent it, just as there is nothing about what
> nose does that would prevent two copies of nose from running at the same
> time on different sets of tests.
>
>
this data is toggleable in the test suite using environment variables
and is off by default so that when you are not using testr you don't
get this behavior [0]. However we seem to have neglected log capture
toggles.
>>>
>>>
>>>
>>> Oh wow, there is actually a way to get the stdout and stderr? Fantastic!
>>> Why
>>> on earth are these disabled?
>>>
>> See above, testr has to deal with multiple writers to stdout and
>> stderr, you really don't want them all going to the same place when
>> using testr (which is why stdout and stderr are captured when running
>> testr but not otherwise).
>
>
> Ah, OK, I think I understand now. testr passes the environment variables
> automatically, so you only have to know the magic incantation at the time
> you're writing the test, not when you're running it.
>
>
>>> Please, please, please don't turn off the logging too. That's the only
>>> tool
>>> left for debugging now that s
Re: [openstack-dev] testr help
On 10/03/14 16:04, Clark Boylan wrote:
On Mon, Mar 10, 2014 at 11:31 AM, Zane Bitter wrote:
Thanks Clark for this great write-up. However, I think the solution to the
problem in question is richer commands and better output formatting, not
discarding information.
On 07/03/14 16:30, Clark Boylan wrote:
But running tests in parallel introduces some fun problems. Like where
do you send logging and stdout output. If you send it to the console
it will be interleaved and essentially useless. The solution to this
problem (for which I am probably to blame) is to have each test
collect the logging, stdout, and stderr associated to that test and
attach it to that tests subunit reporting. This way you get all of the
output associated with a single test attached to that test and don't
have crazy interleaving that needs to be demuxed. The capturing of
This is not really a problem unique to parallel test runners. Printing to
the console is just not a great way to handle stdout/stderr in general
because it messes up the output of the test runner, and nose does exactly
the same thing as testr in collecting them - except that nose combines
messages from the 3 sources and prints the output for human consumption,
rather than in separate groups surrounded by lots of {{{random braces}}}.
Except nose can make them all the same file descriptor and let
everything multiplex together. Nose isn't demuxing arbitrary numbers
of file descriptors from arbitrary numbers of processes.
Can't each subunit process do the same thing?
As a user, here's how I want it to work:
- Each subunit process works like nose - multiplexing the various
streams of output together and associating it with a particular test -
except that nothing is written to the console but instead returned to
testr in subunit format.
- testr reads the subunit data and saves it to the test repository.
- testr prints a report to the console based on the data it just
received/saved.
How it actually seems to work:
- A magic pixie creates a TestCase class with a magic incantation to
capture your stdout/stderr/logging without breaking other test runners.
- Or they don't! You're hosed. The magic incantation is undocumented.
- You change all of your TestCases to inherit from the class with the
magic pixie dust.
- Each subunit process associates the various streams of output (if
you set it up to) with a particular test, but keeps them separate so
that if you want to figure out the order of events you have to direct
them all to the same channel - which, in practice, means you can only
use logging (since some of the events you are interested in probably
already exist in the code as logs).
- when you want to debug a test, you have to all the tedious loigging
setup if it doesn't already exist in the file. It probably won't,
because flake8 would have made you delete it unless it's being used already.
- testr reads the subunit data and saves it to the test repository.
- testr prints a report to the console based on the data it just
received/saved, though parts of it look like a raw data dump.
While there may be practical reasons why it currently works like the
latter, I would submit that there is no technical reason it could not
work like the former. In particular, there is nothing about the concept
of running the tests in parallel that would prevent it, just as there is
nothing about what nose does that would prevent two copies of nose from
running at the same time on different sets of tests.
this data is toggleable in the test suite using environment variables
and is off by default so that when you are not using testr you don't
get this behavior [0]. However we seem to have neglected log capture
toggles.
Oh wow, there is actually a way to get the stdout and stderr? Fantastic! Why
on earth are these disabled?
See above, testr has to deal with multiple writers to stdout and
stderr, you really don't want them all going to the same place when
using testr (which is why stdout and stderr are captured when running
testr but not otherwise).
Ah, OK, I think I understand now. testr passes the environment variables
automatically, so you only have to know the magic incantation at the
time you're writing the test, not when you're running it.
Please, please, please don't turn off the logging too. That's the only tool
left for debugging now that stdout goes into a black hole.
Logging goes into the same "black hole" today, I am suggesting that we
make this toggleable like we have made stdout and stderr capturing
toggleable. FWIW this isn't a black hole it is all captured on disk
and you can refer back to it at any time (the UI around doing this
could definitely be better though).
Hmm, now that you mention it, I remember Clint did the setup work in
Heat to get the logging working. So maybe we have to do the same for
stdout and stderr. At the moment they really do go into a black hole -
we can't see them in the testr output at all a
Re: [openstack-dev] testr help
On Mon, Mar 10, 2014 at 11:31 AM, Zane Bitter wrote:
> Thanks Clark for this great write-up. However, I think the solution to the
> problem in question is richer commands and better output formatting, not
> discarding information.
>
>
> On 07/03/14 16:30, Clark Boylan wrote:
>>
>> But running tests in parallel introduces some fun problems. Like where
>> do you send logging and stdout output. If you send it to the console
>> it will be interleaved and essentially useless. The solution to this
>> problem (for which I am probably to blame) is to have each test
>> collect the logging, stdout, and stderr associated to that test and
>> attach it to that tests subunit reporting. This way you get all of the
>> output associated with a single test attached to that test and don't
>> have crazy interleaving that needs to be demuxed. The capturing of
>
>
> This is not really a problem unique to parallel test runners. Printing to
> the console is just not a great way to handle stdout/stderr in general
> because it messes up the output of the test runner, and nose does exactly
> the same thing as testr in collecting them - except that nose combines
> messages from the 3 sources and prints the output for human consumption,
> rather than in separate groups surrounded by lots of {{{random braces}}}.
>
Except nose can make them all the same file descriptor and let
everything multiplex together. Nose isn't demuxing arbitrary numbers
of file descriptors from arbitrary numbers of processes.
>
>> this data is toggleable in the test suite using environment variables
>> and is off by default so that when you are not using testr you don't
>> get this behavior [0]. However we seem to have neglected log capture
>> toggles.
>
>
> Oh wow, there is actually a way to get the stdout and stderr? Fantastic! Why
> on earth are these disabled?
>
See above, testr has to deal with multiple writers to stdout and
stderr, you really don't want them all going to the same place when
using testr (which is why stdout and stderr are captured when running
testr but not otherwise).
>
> Please, please, please don't turn off the logging too. That's the only tool
> left for debugging now that stdout goes into a black hole.
>
Logging goes into the same "black hole" today, I am suggesting that we
make this toggleable like we have made stdout and stderr capturing
toggleable. FWIW this isn't a black hole it is all captured on disk
and you can refer back to it at any time (the UI around doing this
could definitely be better though).
>
>> Now onto indirectly answering some of the questions you have. If a
>> single unittest is producing thousands of lines of log output that is
>> probably a bug. The test scope is too large or the logging is too
>> verbose or both. To work around this we probably need to make the
>> fakeLogger fixture toggleable with configurable log level. Then you
>> could do something like `OS_LOG_LEVEL=error tox` and avoid getting all
>> of the debug level logs.
>
>
> Fewer logs is hardly ever what you want when debugging a unit test.
>
I agree, but in general Openstack does a terrible job at logging
particularly when you look at the DEBUG level. There is too much noise
and not enough consistency. Being able to set the level you want to
capture at or turn off capturing is a good thing.
>
> I think what John is looking for is a report at the end of each test run
> that just lists the tests that failed instead of all the details (like
> `testr failing --list`), or perhaps the complete list of tests with the
> coloured pass/fail like IIRC nose does. Since testr's killer feature is to
> helpfully store all of the results for later, maybe this output is all you
> need in the first instance (along with a message telling the user what
> command to run to see the full output, of course), or at least that could be
> an option.
>
This is a good idea. Could be done by having testr output info without
any subunit attachments.
>
>> For examining test results you can `testr load $SUBUNIT_LOG_FILE` then
>> run commands like `testr last`, `testr failing`, `testr slowest`, and
>> `testr stats` against that run (if you want details on the last run
>> you don't need an explicit load). There are also a bunch of tools that
>> come with python-subunit like subunit-filter, subunit2pyunit,
>> subunit-stats, and so on that you can use to do additional processing.
>
>
> It sounds like what John wants to do is pass a filter to something like
> `testr failing` or `testr last` to only report a subset of the results, in
> much the same way as it's possible to pass a filter to `testr` to only run a
> subset of the tests.
>
> BTW, since I'm on the subject, testr would be a lot more
> confidence-inspiring if running `testr failing` immediately after running
> `testr` reported the same number of failures, or indeed if running `testr`
> twice in a row was guaranteed to report the same number of failures
> (assuming that the tests themselves are deterministic). I can't imagine
Re: [openstack-dev] testr help
On Mon, Mar 10, 2014 at 12:21 PM, John Dennis wrote: > On 03/10/2014 02:31 PM, Zane Bitter wrote: >> Fewer logs is hardly ever what you want when debugging a unit test. >> >> I think what John is looking for is a report at the end of each test run >> that just lists the tests that failed instead of all the details (like >> `testr failing --list`), or perhaps the complete list of tests with the >> coloured pass/fail like IIRC nose does. Since testr's killer feature is >> to helpfully store all of the results for later, maybe this output is >> all you need in the first instance (along with a message telling the >> user what command to run to see the full output, of course), or at least >> that could be an option. > >> It sounds like what John wants to do is pass a filter to something like >> `testr failing` or `testr last` to only report a subset of the results, >> in much the same way as it's possible to pass a filter to `testr` to >> only run a subset of the tests. > > Common vocabulary is essential to discuss this. A test result as emitted > by subunit is a metadata collection indexed by keys. To get the list of > failing tests one iterates over the set of results and looks for the > absense of the "successful" key in the result. That's the set of test > failures, as such it's a filter on the test results. > > Therefore I see filtering as the act of producing a subset of the test > results (i.e, only those failing, or only those whose names match a > regexp, or the intersection of those). That is a filtered result set. > The filtering is performed by examining the key/value in each result > metadata to yield a subset of the results. > > Next you have to display that filtered result set. When each result is > displayed one should be able to specify which pieces of metadata get > displayed. In my mind that's not filtering, it's a display option. One > common display option would be to emit only the test name. Another might > be to display the test name and the captured log data. As it stands now > it seems to display every piece of metadata in the result which is what > is producing the excessive verbosity. > > Hopefully I'm making sense, yes/no? > Makes sense to me. We should poke lifeless and get him to chime in. Clark ___ OpenStack-dev mailing list OpenStack-dev@lists.openstack.org http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
Re: [openstack-dev] testr help
On 03/10/2014 02:31 PM, Zane Bitter wrote: > Fewer logs is hardly ever what you want when debugging a unit test. > > I think what John is looking for is a report at the end of each test run > that just lists the tests that failed instead of all the details (like > `testr failing --list`), or perhaps the complete list of tests with the > coloured pass/fail like IIRC nose does. Since testr's killer feature is > to helpfully store all of the results for later, maybe this output is > all you need in the first instance (along with a message telling the > user what command to run to see the full output, of course), or at least > that could be an option. > It sounds like what John wants to do is pass a filter to something like > `testr failing` or `testr last` to only report a subset of the results, > in much the same way as it's possible to pass a filter to `testr` to > only run a subset of the tests. Common vocabulary is essential to discuss this. A test result as emitted by subunit is a metadata collection indexed by keys. To get the list of failing tests one iterates over the set of results and looks for the absense of the "successful" key in the result. That's the set of test failures, as such it's a filter on the test results. Therefore I see filtering as the act of producing a subset of the test results (i.e, only those failing, or only those whose names match a regexp, or the intersection of those). That is a filtered result set. The filtering is performed by examining the key/value in each result metadata to yield a subset of the results. Next you have to display that filtered result set. When each result is displayed one should be able to specify which pieces of metadata get displayed. In my mind that's not filtering, it's a display option. One common display option would be to emit only the test name. Another might be to display the test name and the captured log data. As it stands now it seems to display every piece of metadata in the result which is what is producing the excessive verbosity. Hopefully I'm making sense, yes/no? -- John ___ OpenStack-dev mailing list OpenStack-dev@lists.openstack.org http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
Re: [openstack-dev] testr help
Thanks Clark for this great write-up. However, I think the solution to
the problem in question is richer commands and better output formatting,
not discarding information.
On 07/03/14 16:30, Clark Boylan wrote:
But running tests in parallel introduces some fun problems. Like where
do you send logging and stdout output. If you send it to the console
it will be interleaved and essentially useless. The solution to this
problem (for which I am probably to blame) is to have each test
collect the logging, stdout, and stderr associated to that test and
attach it to that tests subunit reporting. This way you get all of the
output associated with a single test attached to that test and don't
have crazy interleaving that needs to be demuxed. The capturing of
This is not really a problem unique to parallel test runners. Printing
to the console is just not a great way to handle stdout/stderr in
general because it messes up the output of the test runner, and nose
does exactly the same thing as testr in collecting them - except that
nose combines messages from the 3 sources and prints the output for
human consumption, rather than in separate groups surrounded by lots of
{{{random braces}}}.
this data is toggleable in the test suite using environment variables
and is off by default so that when you are not using testr you don't
get this behavior [0]. However we seem to have neglected log capture
toggles.
Oh wow, there is actually a way to get the stdout and stderr? Fantastic!
Why on earth are these disabled?
Please, please, please don't turn off the logging too. That's the only
tool left for debugging now that stdout goes into a black hole.
Now onto indirectly answering some of the questions you have. If a
single unittest is producing thousands of lines of log output that is
probably a bug. The test scope is too large or the logging is too
verbose or both. To work around this we probably need to make the
fakeLogger fixture toggleable with configurable log level. Then you
could do something like `OS_LOG_LEVEL=error tox` and avoid getting all
of the debug level logs.
Fewer logs is hardly ever what you want when debugging a unit test.
I think what John is looking for is a report at the end of each test run
that just lists the tests that failed instead of all the details (like
`testr failing --list`), or perhaps the complete list of tests with the
coloured pass/fail like IIRC nose does. Since testr's killer feature is
to helpfully store all of the results for later, maybe this output is
all you need in the first instance (along with a message telling the
user what command to run to see the full output, of course), or at least
that could be an option.
For examining test results you can `testr load $SUBUNIT_LOG_FILE` then
run commands like `testr last`, `testr failing`, `testr slowest`, and
`testr stats` against that run (if you want details on the last run
you don't need an explicit load). There are also a bunch of tools that
come with python-subunit like subunit-filter, subunit2pyunit,
subunit-stats, and so on that you can use to do additional processing.
It sounds like what John wants to do is pass a filter to something like
`testr failing` or `testr last` to only report a subset of the results,
in much the same way as it's possible to pass a filter to `testr` to
only run a subset of the tests.
BTW, since I'm on the subject, testr would be a lot more
confidence-inspiring if running `testr failing` immediately after
running `testr` reported the same number of failures, or indeed if
running `testr` twice in a row was guaranteed to report the same number
of failures (assuming that the tests themselves are deterministic). I
can't imagine why one of the subunit processes reporting a test failure
is considered a failure in itself (that's what it's supposed to do!),
particularly when `testr failing` manages to filter them out OK.
(I understand that some of the things mentioned above may already have
been improved since the latest 0.0.18 release. I can't actually find the
repo at the moment to check, because it's not linked from PyPI or
Launchpad and 'testrepository' turns out to be an extremely common name
for things on the Internet.)
cheers,
Zane.
___
OpenStack-dev mailing list
OpenStack-dev@lists.openstack.org
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
Re: [openstack-dev] testr help
On 03/07/2014 04:30 PM, Clark Boylan wrote: > Now onto indirectly answering some of the questions you have. If a > single unittest is producing thousands of lines of log output that is > probably a bug. The test scope is too large or the logging is too > verbose or both. To work around this we probably need to make the > fakeLogger fixture toggleable with configurable log level. Then you > could do something like `OS_LOG_LEVEL=error tox` and avoid getting all > of the debug level logs. > > For examining test results you can `testr load $SUBUNIT_LOG_FILE` then > run commands like `testr last`, `testr failing`, `testr slowest`, and > `testr stats` against that run (if you want details on the last run > you don't need an explicit load). There are also a bunch of tools that > come with python-subunit like subunit-filter, subunit2pyunit, > subunit-stats, and so on that you can use to do additional processing. Thanks Clark!! That's great information it's helping me piece the pieces together. Here is where I think I'm stuck. The subunit test result stream seems to have "details" which it attaches to the test result. For the failing tests it often includes: pythonlogging stacktrace Both very useful pieces of information. I don't want to get rid of them in the test results because I'll make use of them while fixing problems. Instead what I want to do is toggle the display of this extra detail information on or off when I run any of the commands that show me test results. What I can't figure out is how to toggle the display of pythonlogging and stacktrace on or off so that I can either get a simple summary or full detail (but only when I need it). I thought subunit-filter might be the right tool, but I don't see anyway to toggle various pieces of detail data using that tool. Once again, thanks for your help. -- John ___ OpenStack-dev mailing list OpenStack-dev@lists.openstack.org http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
Re: [openstack-dev] testr help
On 03/07/2014 04:33 PM, Steve Kowalik wrote: > On 07/03/14 12:56, John Dennis wrote: >> Question: How do you list just the failing tests? I don't want to see >> the contents of the logging data stored under the pythonlogging: key. >> Ideally I'd like to see the name of the test, what the failure was, and >> possibly the associated stacktrace. Should be simple right? But I can't >> figure it out. > > "testr failing" or "testr failing --list". See also "testr run --failing". Thanks, but those are exactly the problematic commands. The issue is the output contains huge amounts of log data that obscures everything else. >From what I can figure out the test result contains "details" which is a set of additional information. I see two pieces of detail information pythonlogging traceback It's valuable information but I need to omit it in order to see the list of failures. So what I'm trying to figure out is how do I toggle the display of the detail information so I can just get a summary of the failing tests. -- John ___ OpenStack-dev mailing list OpenStack-dev@lists.openstack.org http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
Re: [openstack-dev] testr help
On 07/03/14 12:56, John Dennis wrote: Question: How do you list just the failing tests? I don't want to see the contents of the logging data stored under the pythonlogging: key. Ideally I'd like to see the name of the test, what the failure was, and possibly the associated stacktrace. Should be simple right? But I can't figure it out. "testr failing" or "testr failing --list". See also "testr run --failing". Cheers, -- Steve "...In the UNIX world, people tend to interpret `non-technical user' as meaning someone who's only ever written one device driver." - Daniel Pead ___ OpenStack-dev mailing list OpenStack-dev@lists.openstack.org http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
Re: [openstack-dev] testr help
On Fri, Mar 7, 2014 at 12:56 PM, John Dennis wrote: > I've read the following documents as well as the doc for subunit and > testtools but I'm still missing some big picture usage. > > https://wiki.openstack.org/wiki/Testr > https://testrepository.readthedocs.org/en/latest/index.html > > The biggest problem seems to be whenever tests are listed I get > thousands of lines of logging information and any information about the > test is obscured by the enormous volume of logging data. > > From what I can figure out the files in .testrepository are in subunit > version 1 protocol format. It seems to be a set of key/value pairs where > the key is the first word on the line followed by a colon. It seems like > one should be able to list just certain keys. > > Question: How do you list just the failing tests? I don't want to see > the contents of the logging data stored under the pythonlogging: key. > Ideally I'd like to see the name of the test, what the failure was, and > possibly the associated stacktrace. Should be simple right? But I can't > figure it out. > > Question: Suppose I'm debugging why a test failed. This is the one time > I actually do want to see the pythonlogging data, but only for exactly > the test I'm interested in. How does one do that? > > Question: Is there any simple how-to's or any cohesive documentation? > I've read everything I can find but really simple tasks seem to elude > me. The suite is composed of implementations from testtools, subunit and > testr, each of which has decent doc but it's not always clear how these > pieces fit together into one piece of functionality. OpenStack seems to > have added something into the mix with the capture of the logging > stream, something which is not covered anywhere in the testtools, > subunit nor testtools doc that I can find. Any hints, suggestions or > pointers would be deeply appreciated. > > -- > John > > ___ > OpenStack-dev mailing list > OpenStack-dev@lists.openstack.org > http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev I am going to do my best here. Testtools is essentially a replacement for unittest. Similar to unittest2 but with saner python3 support and it fits into the testrepository + subunit ecosystem. Subunit wraps your test classes (unittest/testtools/etc) and outputs test results in the subunit protocol which is a streaming test result protocol. Subunit is useful because it allows you to run multiple test runners in parallel and aggregate their results in a central test runner runner. This is what testr does. Testr will list your tests using discover, partition the list of tests into N sets where N is the number of CPUs you have (at least how we use it, N can be arbitrary if you choose), run N test runners each given a different test partition, and collect the results in the .testrepository dir. This behavior is great because it allows us to run tests in parallel (even across different machines if we need to) with live streaming updates. This allows us to have tests that take less wall time while still getting the coverage we want. It will eventually allow us to do more optimistic branching and reporting in Zuul because we can learn immediately when the first test fails, report that, then continue running the remaining tests to provide a full picture back to developers. But running tests in parallel introduces some fun problems. Like where do you send logging and stdout output. If you send it to the console it will be interleaved and essentially useless. The solution to this problem (for which I am probably to blame) is to have each test collect the logging, stdout, and stderr associated to that test and attach it to that tests subunit reporting. This way you get all of the output associated with a single test attached to that test and don't have crazy interleaving that needs to be demuxed. The capturing of this data is toggleable in the test suite using environment variables and is off by default so that when you are not using testr you don't get this behavior [0]. However we seem to have neglected log capture toggles. Now onto indirectly answering some of the questions you have. If a single unittest is producing thousands of lines of log output that is probably a bug. The test scope is too large or the logging is too verbose or both. To work around this we probably need to make the fakeLogger fixture toggleable with configurable log level. Then you could do something like `OS_LOG_LEVEL=error tox` and avoid getting all of the debug level logs. For examining test results you can `testr load $SUBUNIT_LOG_FILE` then run commands like `testr last`, `testr failing`, `testr slowest`, and `testr stats` against that run (if you want details on the last run you don't need an explicit load). There are also a bunch of tools that come with python-subunit like subunit-filter, subunit2pyunit, subunit-stats, and so on that you can use to do additional processing. [0] https:
[openstack-dev] testr help
I've read the following documents as well as the doc for subunit and testtools but I'm still missing some big picture usage. https://wiki.openstack.org/wiki/Testr https://testrepository.readthedocs.org/en/latest/index.html The biggest problem seems to be whenever tests are listed I get thousands of lines of logging information and any information about the test is obscured by the enormous volume of logging data. >From what I can figure out the files in .testrepository are in subunit version 1 protocol format. It seems to be a set of key/value pairs where the key is the first word on the line followed by a colon. It seems like one should be able to list just certain keys. Question: How do you list just the failing tests? I don't want to see the contents of the logging data stored under the pythonlogging: key. Ideally I'd like to see the name of the test, what the failure was, and possibly the associated stacktrace. Should be simple right? But I can't figure it out. Question: Suppose I'm debugging why a test failed. This is the one time I actually do want to see the pythonlogging data, but only for exactly the test I'm interested in. How does one do that? Question: Is there any simple how-to's or any cohesive documentation? I've read everything I can find but really simple tasks seem to elude me. The suite is composed of implementations from testtools, subunit and testr, each of which has decent doc but it's not always clear how these pieces fit together into one piece of functionality. OpenStack seems to have added something into the mix with the capture of the logging stream, something which is not covered anywhere in the testtools, subunit nor testtools doc that I can find. Any hints, suggestions or pointers would be deeply appreciated. -- John ___ OpenStack-dev mailing list OpenStack-dev@lists.openstack.org http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
