[PATCH] testprogs: Ignore escape characters when printing test name (was Re: [PATCHES] Add 'net tdb' command to allow debugging of contended records in locking.tdb)

[Christof Schmitt]

On Tue, May 02, 2017 at 04:07:11PM -0700, Christof Schmitt via samba-technical wrote:
> On Fri, Apr 28, 2017 at 03:04:59PM -0700, Christof Schmitt via samba-technical wrote:
> > [1689(10768)/2100 at 1h51m38s] samba4.blackbox.trust_ntlm(fl2008r2dc:local)
> > [1690(10790)/2100 at 1h51m39s] samba4.blackbox.trust_ntlm(fl2003dc:local)
> > [1691(10812)/2100 at 1h51m40s] samba4.blackbox.trust_ntlm(ad_member:local)
> > UNEXPECTED(error): samba4.blackbox.trust_ntlm.Test01 rpcclient getusername with LOCALADMEMBERtime: 2017-04-28 01:12:50.225336Z(ad_member:local)
> > REASON: Exception: Exception: Test was never started
> > UNEXPECTED(error): samba4.blackbox.trust_ntlm.Test01 rpcclient getusername with LOCALADMEMBERtime: 2017-04-28 01:12:50.223650Z(ad_member:local) (samba.subunit.RemotedTestCase)
> > REASON: was started but never finished!
> > 
> > FAILED (0 failures, 2 errors and 0 unexpected successes in 0 testsuites)
> > 
> > 
> > I am still debugging, something seems to be tripping up the tracking in
> > selftest/subunithelper.py. Running a 'make test' for the affected testcase and
> > the new net_tdb testcase works.
> 
> FYI,
> 
> the same problem also hits when trying to push a different patchset (the
> idmap_rfc2307 fixes). The exact same problem also hits on a private
> autobuild build with just some debugging enabled. The output after
> "rpcclient getusername with" is suspicious; it is supposed to be the
> user name, but here it shows the test environment and then also adds the
> timestamp. Adding the timestamp in the name is likely the cause for the
> subunithelp.py not being able to identify the running test. I am still
> trying to find out why this is messed up in the first place.

Found the issue. This only triggers for users starting with the
letter c, and that would only be by user on sn-devel. See attached
patch.

Christof
-------------- next part --------------
From 44ab637c542f2cc78913cd6b68ac3bbcd24a7472 Mon Sep 17 00:00:00 2001
From: Christof Schmitt <cs at samba.org>
Date: Fri, 5 May 2017 01:10:56 +0200
Subject: [PATCH] testprogs: Ignore escape characters when printing test name

Long story: This was triggered by the addition of the test_trust_ntlm.sh
script in commits 3caca9b and 2de1994. test_trust_ntlm.sh creates a
variable CREDS="$REALM\\$USERNAME%$PASSWORD" that is then used as part
of the test name. subunit.sh uses echo to print the name that is then
picked up by subunithelper.py. test_trust_ntlm.sh also uses /bin/sh as
shell which can be a POSIX compliant shell like dash.

This combination broke 'make test' for any username starting with the
letter c. In this case CREDS contains the escape sequence \c that is
defined to stop producing further output at this point. dash implements
this feature and the echo in subunit.sh as a result skips the output
after \c, including skipping the newline. This means that the data
received by subunithelper.py contains the timestamp from the next line
in the test name, which then breaks the testcase tracking.

Fix this by replacing the echo in subunit.sh with a printf that does not
trigger the special handling of escape characters.

Signed-off-by: Christof Schmitt <cs at samba.org>
---
 testprogs/blackbox/subunit.sh | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/testprogs/blackbox/subunit.sh b/testprogs/blackbox/subunit.sh
index 5c81ce2..aca53f7 100755
--- a/testprogs/blackbox/subunit.sh
+++ b/testprogs/blackbox/subunit.sh
@@ -28,14 +28,14 @@ timestamp() {
 subunit_start_test () {
   # emit the current protocol start-marker for test $1
   timestamp
-  echo "test: $1"
+  printf 'test: %s\n' "$1"
 }
 
 
 subunit_pass_test () {
   # emit the current protocol test passed marker for test $1
   timestamp
-  echo "success: $1"
+  printf 'success: %s\n' "$1"
 }
 
 # This is just a hack as we have some broken scripts
@@ -48,7 +48,7 @@ subunit_fail_test () {
   # we use stdin because the failure message can be arbitrarily long, and this
   # makes it convenient to write in scripts (using <<END syntax.
   timestamp
-  echo "failure: $1 ["
+  printf 'failure: %s [\n' "$1"
   cat -
   echo "]"
 }
@@ -60,7 +60,7 @@ subunit_error_test () {
   # we use stdin because the failure message can be arbitrarily long, and this
   # makes it convenient to write in scripts (using <<END syntax.
   timestamp
-  echo "error: $1 ["
+  printf 'error: %s [\n' "$1"
   cat -
   echo "]"
 }
@@ -70,7 +70,7 @@ subunit_skip_test () {
   # the error text.
   # we use stdin because the failure message can be arbitrarily long, and this
   # makes it convenient to write in scripts (using <<END syntax.
-  echo "skip: $1 ["
+  printf 'skip: %s [\n' "$1"
   cat -
   echo "]"
 }
-- 
1.8.3.1