Systemtap .sum vs .log

Systemtap .sum vs .log

[Kris Van Hees]

In followup to our conversation on the conference call...  The summary file
does not capture the ERROR messages from runtest, and those are significant
in the processing of test results.

Whenm e.g. the staprun executable is not setuid root (or equiv privs), some
tests print out an ERROR about this, but the test result is (for some tests)
actually reported as XFAIL.  Now, per the discussion on the call, that should
be interpreted as a PASS.  So...  the summary file ends up listing a test
result that will get reported as a PASS when it most definitely was not a
successful test execution.

That kind of cases can be resolved based on the verbose log.

Another problem (brought to light by a question from David Wilder) is that
the dejagnu summary output seems to be inconsistent with the actual log
messages (both in the summary and verbose logs):

                                stap    Grep                    
                                ----    ----                    
PASS (expected passes)          463     462                     
FAIL (unexpected failures)       19      19                     
XFAIL (expected failures)       152     152                     
XPASS (unknown successes)         1       0                     
KFAIL (known failures             5       5                     
UNTESTED (untested)              26      26                     
UNSUPOPRTED (unsupported)         2       2                     

As you can see, dejagnu is reporting 1 extra PASS, and 1 extra XPASS, yet
a grep on the log cannot find those two entries.  Does anyone have any idea
where they are coming from?

As to the potential for non-public information making its way into the verbose
log...  If and when that occurs, I am certain that it would be treated as a
high priority bug in systemtap or its testsuite, and that it would be resolved
rather quickly.  For example, the samba build (and test) farm has a long
history of doing this kind of stuff (and they have had their share of somewhat
unexpected things happening).  The main thing usually is to ensure that all
testing is done in a sufficiently safe environment, both in terms of not
letting anything leak out that shouldn't, and in terms of ensuring that a
misbehaving test won't cause more damage.

	Cheers,
	Kris

Re: Systemtap .sum vs .log

[David Wilder]

Kris Van Hees wrote:
> In followup to our conversation on the conference call...  The summary file
> does not capture the ERROR messages from runtest, and those are significant
> in the processing of test results.
> 
> Whenm e.g. the staprun executable is not setuid root (or equiv privs), some
> tests print out an ERROR about this, but the test result is (for some tests)
> actually reported as XFAIL.  Now, per the discussion on the call, that should
> be interpreted as a PASS.  So...  the summary file ends up listing a test
> result that will get reported as a PASS when it most definitely was not a
> successful test execution.
> 
> That kind of cases can be resolved based on the verbose log.
> 
> Another problem (brought to light by a question from David Wilder) is that
> the dejagnu summary output seems to be inconsistent with the actual log
> messages (both in the summary and verbose logs):
> 
>                                 stap    Grep                    
>                                 ----    ----                    
> PASS (expected passes)          463     462                     
> FAIL (unexpected failures)       19      19                     
> XFAIL (expected failures)       152     152                     
> XPASS (unknown successes)         1       0                     
> KFAIL (known failures             5       5                     
> UNTESTED (untested)              26      26                     
> UNSUPOPRTED (unsupported)         2       2                     
> 
> As you can see, dejagnu is reporting 1 extra PASS, and 1 extra XPASS, yet
> a grep on the log cannot find those two entries.  Does anyone have any idea
> where they are coming from?
> 
> As to the potential for non-public information making its way into the verbose
> log...  If and when that occurs, I am certain that it would be treated as a
> high priority bug in systemtap or its testsuite, and that it would be resolved
> rather quickly.  For example, the samba build (and test) farm has a long
> history of doing this kind of stuff (and they have had their share of somewhat
> unexpected things happening).  The main thing usually is to ensure that all
> testing is done in a sufficiently safe environment, both in terms of not
> letting anything leak out that shouldn't, and in terms of ensuring that a
> misbehaving test won't cause more damage.
> 
> 	Cheers,


Here is the difference, the systemtap.sum has one more PASS line that is 
missing from systemtap.log.

# grep ^PASS: systemtap.sum > pass.sum
# grep ^PASS: systemtap.log > pass.log
# diff -Naru pass.log pass.sum
--- pass.log    2007-10-11 14:07:41.000000000 -0700
+++ pass.sum    2007-10-11 14:07:28.000000000 -0700
@@ -346,6 +346,7 @@
  PASS: systemtap.printf/string1.stp
  PASS: 
/home/src/stap/src-20071006/testsuite/systemtap.printf/string2.stp passed
  PASS: args search for staprun (/usr/local/bin/staprun)
+PASS: args compile
  PASS: args search for probe module (args_3085.ko)
  PASS: args search for tmpdir (/tmp/stapwfd7KX)
  PASS: args search for probe module (/tmp/stapwfd7KX/args_3085.ko)


I don't see any XPASS in ether the .sum or .log.  However there is a 
single KPASS in both logs.    KPASS ?? known successes ???, must be a bug.

Re: Systemtap .sum vs .log

[Frank Ch. Eigler]

Kris Van Hees wrote:
> In followup to our conversation on the conference call...  The summary file
> does not capture the ERROR messages from runtest, and those are significant
> in the processing of test results. [...]

That is a reasonable point, but ...
That ERROR message does not come from runtest but from systemtap.
There are other ERROR messages from systemtap that do not constitute
errors (e.g. parseko/cmdline06.stp).

> When e.g. the staprun executable is not setuid root (or equiv
> privs), some tests print out an ERROR about this, [...]  actually
> reported as XFAIL.  [...]

This should be a rare if any case.  The only time when this setuid
business is tested is for pass-5 tests run by "make installcheck".
There are not many (if any) xfail pass-5 tests.

> Another problem (brought to light by a question from David Wilder)
> is that the dejagnu summary output seems to be inconsistent with the
> actual log messages (both in the summary and verbose logs):

The .sum file contains the judgement of dejagnu.  Some peculiar test
cases took it upon themseves to add stuff like
     puts "PASS: $test"
into the .exp files, in addition to the appropriate
     pass $test
Some of the former have been removed; perhaps you just came across
a straggler with a price on its head.

Or not ...

David Wilder <dwilder@us.ibm.com> writes:

> Here is the difference, the systemtap.sum has one more PASS line that
> is missing from systemtap.log.
> [...]
>  PASS: args search for staprun (/usr/local/bin/staprun)
> +PASS: args compile
>  PASS: args search for probe module (args_3085.ko)
> [...]

Dunno why that line would be missing from the .log file.  I don't see
that discrepancy in some of my recent .log/.sum files I checked.

>  PASS: args search for probe module (/tmp/stapwfd7KX/args_3085.ko)

But parenthesized comments like (....) should probably not be quite so
installation-specific.  That prevents mechanical regression analysis
across installations.

> I don't see any XPASS in ether the .sum or .log.  However there is a
> single KPASS in both logs.    KPASS ?? known successes ???, must be a
> bug.

KPASS means that a test was declared a "known failure" i.e., KFAIL,
but nevertheless passed.  This is considered a failure by dejagnu,
but we should treat it as good news.  The "setup_kfail" predicate
in the dejagnu test case could be narrowed or eliminated for tests
that have graduated from the "known failure" category.

- FChE

Re: Systemtap .sum vs .log

[Kris Van Hees]

On Thu, Oct 11, 2007 at 05:58:02PM -0400, Frank Ch. Eigler wrote:
> > When e.g. the staprun executable is not setuid root (or equiv
> > privs), some tests print out an ERROR about this, [...]  actually
> > reported as XFAIL.  [...]
> 
> This should be a rare if any case.  The only time when this setuid
> business is tested is for pass-5 tests run by "make installcheck".
> There are not many (if any) xfail pass-5 tests.

Actually, a plain 'make check' resulted in exactly this case last night.
One of the tests that triggered it was:

	parseko/cmdline09.stp

The test triggers an error (because staprun isn't setuid), yet it reports
XFAIL as result (because the test case expects a failure - just not this
one).  This of course means the test case is faulty, but I would never have
found it without access to the .log output.  Based on the .sum file, this is
simply an expected failure (and thus per today's conf call, a success).

	Cheers,
	Kris

Re: Systemtap .sum vs .log

[Frank Ch. Eigler]

Hi -

On Thu, Oct 11, 2007 at 08:15:32PM -0400, Kris Van Hees wrote:
> [...]
> > This should be a rare if any case.  The only time when this setuid
> > business is tested is for pass-5 tests run by "make installcheck".
> > There are not many (if any) xfail pass-5 tests.
> 
> Actually, a plain 'make check' resulted in exactly this case last night.
> One of the tests that triggered it was:
> 	parseko/cmdline09.stp

It is a buggy test case.  It is meant to evoke a "ERROR: Module name
... is too long." message, which it does if the testsuite is being run
as root.  Without that, you get instead the "ERROR: .... setuid"
message, which is absolutely a bug as we shouldn't get that far.

> [...]  This of course means the test case is faulty, but I would
> never have found it without access to the .log output.  [...]

That's true to an extent - but even with .log analysis, you'd have
gotten either one ERROR: or the other, one being a false positive.

- FChE