QtQA::TestScript: increased all exe-related verbosity by 1

Log the commands we run by default.  Without this, it is too hard to
figure out what the test script is doing.

Change-Id: Idfab17d3dce2f4a72f1e95926b1b677765d46e73
Reviewed-on: http://codereview.qt.nokia.com/3230
Reviewed-by: Qt Sanity Bot <qt_sanity_bot@ovi.com>
Reviewed-by: Keith Isdale <keith.isdale@nokia.com>

3 files changed, 17 insertions, 34 deletions

diff --git a/scripts/lib/perl5/QtQA/TestScript.pm b/scripts/lib/perl5/QtQA/TestScript.pm
index ce4005ec..586b7565 100644
--- a/scripts/lib/perl5/QtQA/TestScript.pm
+++ b/scripts/lib/perl5/QtQA/TestScript.pm
@@ -220,7 +220,7 @@ sub exe
 
     local @ENV{@property_env_keys} = values %{$self->{resolved_property}};
 
-    $self->print_when_verbose(1, '+ ', join(' ', @command), "\n");
+    $self->print_when_verbose(0, '+ ', join(' ', @command), "\n");
     $self->_reliable_exe( \%options, @command );
 
     return;
@@ -381,7 +381,7 @@ sub exe_qx
 {
     my ($self, @command) = @_;
 
-    $self->print_when_verbose(2, "qx @command\n");
+    $self->print_when_verbose(1, "qx @command\n");
 
     my $stdout;
     my $stderr;
@@ -391,14 +391,14 @@ sub exe_qx
         ($stdout, $stderr) = capture {
             $status = system( @command );
         };
-        $self->print_when_verbose(3, "qx stdout:\n$stdout\n"
+        $self->print_when_verbose(2, "qx stdout:\n$stdout\n"
                                     ."qx stderr:\n$stderr\n");
     }
     else {
         $stdout = capture_merged {
             $status = system( @command );
         };
-        $self->print_when_verbose(3, "qx stdout & stderr:\n$stdout\n" );
+        $self->print_when_verbose(2, "qx stdout & stderr:\n$stdout\n" );
     }
 
     if ($status != 0) {
diff --git a/scripts/lib/perl5/QtQA/t/10-TestScript.t b/scripts/lib/perl5/QtQA/t/10-TestScript.t
index c9767466..c112c81a 100644
--- a/scripts/lib/perl5/QtQA/t/10-TestScript.t
+++ b/scripts/lib/perl5/QtQA/t/10-TestScript.t
@@ -230,6 +230,7 @@ sub test_exe
         'use Data::Dumper; print Dumper(\@ARGV);',
         @TEST_EXE_ARGS1,
     );
+    my $expected_log = "+ @good_cmd\n$TEST_EXE_ARGS1_DUMP";
 
     # We invoke a subprocess which uses Data::Dumper to print out all
     # arguments.  This is a simple way to check unambiguously what args
@@ -239,7 +240,7 @@ sub test_exe
 
     TODO: {
         local $TODO = 'fix or document argument passing on Windows' if $WINDOWS;
-        is( $stdout, $TEST_EXE_ARGS1_DUMP, 'exe passes arguments correctly'   );
+        is( $stdout, $expected_log, 'exe passes arguments correctly'   );
     }
     is( $stderr, q{},                  'no unexpected warnings or stderr' );
 
@@ -251,7 +252,6 @@ sub test_exe
     # exe should print out one line before running the command, like this:
     #   + cmd with each arg separated by space
     # Note it currently does not attempt to print args with whitespace unambiguously
-    my $expected_log = "+ @good_cmd\n$TEST_EXE_ARGS1_DUMP";
     TODO: {
         local $TODO = 'fix or document argument passing on Windows' if $WINDOWS;
         is( $stdout, $expected_log, 'exe logs correctly' );
@@ -313,7 +313,7 @@ sub test_exe_qx
 
 
 
-    # If verbose 1, makes no difference (exe_qx is intentionally quieter than exe)
+    # If verbose 1, command will be logged before it is run.
     $script->get_options_from_array(['--verbose']);
 
     lives_ok(
@@ -331,36 +331,12 @@ sub test_exe_qx
         is( $merged, $test_merged, 'merged output OK (verbose1)'                  );
     }
 
-    ok( !$log_stdout, 'no log output (verbose1)' );
-    ok( !$log_stderr, 'no log error (verbose1)'  );
-
-
-
-    # If verbose 2, command will be logged before it is run.
-    # Note this `--verbose' accumulates on top of the previous.
-    $script->get_options_from_array(['--verbose']);
-
-    lives_ok(
-        sub {
-            capture { ($stdout, $stderr) = $script->exe_qx(@good_cmd) } \$log_stdout, \$log_stderr;
-            capture { $merged = $script->exe_qx(@good_cmd) };           # discard any log output
-        },
-        'successful command lives (verbose2)'
-    );
-
-    is( $stderr, $test_stderr, 'stderr OK (verbose2)' );
-    TODO: {
-        local $TODO = 'fix or document argument passing on Windows' if $WINDOWS;
-        is( $stdout, $test_stdout, 'exe_qx passes arguments correctly (verbose2)' );
-        is( $merged, $test_merged, 'merged output OK (verbose2)'                  );
-    }
-
-    is( $log_stdout, "qx @good_cmd\n", 'log output OK (verbose2)' );
-    ok( !$log_stderr,                  'no log error (verbose2)'  );
+    is( $log_stdout, "qx @good_cmd\n", 'log output OK (verbose1)' );
+    ok( !$log_stderr,                  'no log error (verbose1)'  );
 
 
 
-    # If verbose 3, command will be logged before it is run, and stdout/stderr is logged
+    # If verbose 2, command will be logged before it is run, and stdout/stderr is logged
     # after it is run.  We need to test the log for merged vs non-merged independently here.
     $script->get_options_from_array(['--verbose']);
 
diff --git a/scripts/lib/perl5/QtQA/t/30-TestScript-reliable-exe.t b/scripts/lib/perl5/QtQA/t/30-TestScript-reliable-exe.t
index 1f75d50e..5a0ad310 100644
--- a/scripts/lib/perl5/QtQA/t/30-TestScript-reliable-exe.t
+++ b/scripts/lib/perl5/QtQA/t/30-TestScript-reliable-exe.t
@@ -87,6 +87,13 @@ sub run_one_test
         );
     };
 
+    # First line of stdout should always be the command.
+    my $logged_command = quotemeta( '+ '.join(' ', @{$command}) );
+    like( $stdout, qr{\A $logged_command \n}xms, "$testname stdout first line looks correct" );
+
+    # Remove first line for subsequent comparison
+    $stdout =~ s{\A [^\n]+ \n}{}xms;
+
     is_or_like( $stdout,  $expected_stdout,  "$testname stdout looks correct" );
     is_or_like( $stderr,  $expected_stderr,  "$testname stderr looks correct" );