ordering problem with "system_func" test

ordering problem with "system_func" test

[Quentin Barnes]

I'm using 20070519 snapshot on a 2.6.21.1 ARM kernel.

The "system_func" test is giving me intermittent results.  I saw #4466
go by, but I'm running the test after that change.

What's happening for me is that the output messages can appear in
different orders, but the its expect script is always expecting the
messages in the same order -- "$user" -> "sys_open" -> "DONE".

Below shows sample successful and failed runs.  What's the bug here?
Is system_func.stp written in such a way to always guarantee the
output message order on all architectures (so the exp script is
right, but my Systemtap port or kernel is somehow broken) or is the
script broken always assuming only one output order is possible?

Quentin


Here's a successful run:
==========
root^M
sys_open^M
cat: __xyzzy123ABC__: No such file or directory^M
^M
Waititing for processes to exit^M
DONE^M
PASS: system_func
testcase /usr/src/systemtap-20070519/testsuite/systemtap.samples/system_func.exp completed in 74 seconds
==========

Here's a failed run:
==========
sys_open^M
DONE^M
^M
Waititing for processes to exit^M
cat: __xyzzy123ABC__: No such file or directory^M
root^M
FAIL: system_func (0,1,0)  

testcase /usr/src/systemtap-20070519/testsuite/systemtap.samples/system_func.exp completed in 114 seconds
==========

Quentin

Re: ordering problem with "system_func" test

[Martin Hunt]

On Wed, 2007-05-23 at 15:49 -0500, Quentin Barnes wrote:
> I'm using 20070519 snapshot on a 2.6.21.1 ARM kernel.
> 
> The "system_func" test is giving me intermittent results.  I saw #4466
> go by, but I'm running the test after that change.

Looks like maybe the pattern isn't anchored correctly. I checked in a
fix. Let me know if that does not help.

Martin

Re: ordering problem with "system_func" test

[Quentin Barnes]

On Wed, May 23, 2007 at 05:41:22PM -0400, Martin Hunt wrote:
>On Wed, 2007-05-23 at 15:49 -0500, Quentin Barnes wrote:
>> I'm using 20070519 snapshot on a 2.6.21.1 ARM kernel.
>> 
>> The "system_func" test is giving me intermittent results.  I saw #4466
>> go by, but I'm running the test after that change.
>
>Looks like maybe the pattern isn't anchored correctly. I checked in a
>fix. Let me know if that does not help.

Nope, it didn't help.  It doesn't solve the arbitrary ordering
problem.  After each match, what appears in the buffer up to that
match is discarded and can't be rematched.  The exp_continue doesn't
restart from the beginning of the original complete buffer, but from
the point of the last match.

Below is an approach that solves it by creating a regular pattern
for all three possibities for concurrent matching.

In the first version, it 'cheats' by using the default match for
$user.  The second version is a more pedantic method, but it uses
the oft maligned "eval".

I don't know Expect all that well, so there might be another way not
so clumsy to solve this problem.  Maybe there's a way to suck the
whole output string in until eof into a variable and then to pattern
matching on it.

>Martin

Quentin

--- system_func.exp.orig	2007-05-23 21:20:04.000000000 -0500
+++ system_func.exp	2007-05-23 21:25:31.000000000 -0500
@@ -7,9 +7,14 @@ set saw_user 0
 set user [exec whoami]
 expect {
     -timeout 30
-    -re "^$user\[^\r\]*\[\r\n\]*" {incr saw_user; exp_continue}
-    -re {^sys_open[^\r]*[\r\n]*} {incr open; exp_continue }
-    -re {DONE[^\r]*[\r\n]*} {incr done; exp_continue }
+    -re "($user|sys_open|DONE)\r" {
+	switch $expect_out(1,string) {
+	    sys_open {incr open}
+	    DONE     {incr done}
+	    default  {incr saw_user}
+	}
+	exp_continue
+    }
     timeout { fail "$test (timeout)" }
     eof { }
 }



--- system_func.exp.orig	2007-05-23 21:20:04.000000000 -0500
+++ system_func.exp	2007-05-23 21:25:31.000000000 -0500
@@ -7,9 +7,14 @@ set saw_user 0
 set user [exec whoami]
 expect {
     -timeout 30
-    -re "^$user\[^\r\]*\[\r\n\]*" {incr saw_user; exp_continue}
-    -re {^sys_open[^\r]*[\r\n]*} {incr open; exp_continue }
-    -re {DONE[^\r]*[\r\n]*} {incr done; exp_continue }
+    -re "($user|sys_open|DONE)\r" {
+	eval "switch $expect_out(1,string) {
+	    \"$user\" {incr saw_user}
+	    sys_open  {incr open}
+	    DONE      {incr done}
+	}"
+	exp_continue
+    }
     timeout { fail "$test (timeout)" }
     eof { }
 }