Merge lp:~percona-toolkit-dev/percona-toolkit/pt-stalk-quiet into lp:percona-toolkit/2.1

[Daniel Nichter]

[lp:~percona-toolkit-dev/percona-toolkit/pt-stalk-quiet]

525. By Daniel Nichter on 2013-01-24

Fix default log level in log_warn_die.sh.

526. By Daniel Nichter on 2013-01-24

Fix typo in t/pt-stalk/option_sanity.t.

527. By Daniel Nichter on 2013-01-24

Fix error caused on some boxes by using diff when it's not defined.

[Daniel Nichter (daniel-nichter)]

review: Approve

=== modified file 'bin/pt-ioprofile'
--- bin/pt-ioprofile	2013-01-03 00:54:18 +0000
+++ bin/pt-ioprofile	2013-01-24 19:10:25 +0000
@@ -20,23 +20,32 @@
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
 
+ts() {
+   TS=$(date +%F-%T | tr ':-' '_')
+   echo "$TS $*"
+}
+
+info() {
+   [ ${OPT_VERBOSE:-3} -ge 3 ] && ts "$*"
+}
+
 log() {
-   TS=$(date +%F-%T | tr ':-' '_');
-   echo "$TS $*"
+   [ ${OPT_VERBOSE:-3} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   log "$*" >&2
+   [ ${OPT_VERBOSE:-3} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
 die() {
-   warn "$*"
+   ts "$*" >&2
+   EXIT_STATUS=1
    exit 1
 }
 
 _d () {
-   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(log "$*")" >&2
+   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(ts "$*")" >&2
 }
 
 # ###########################################################################
@@ -861,7 +870,7 @@
 # Execute the program if it was not included from another file.
 # This makes it possible to include without executing, and thus test.
 if    [ "${0##*/}" = "$TOOL" ] \
-   || [ "${0##*/}" = "bash" -a "$_" = "$0" ]; then
+   || [ "${0##*/}" = "bash" -a "${_:-""}" = "$0" ]; then
 
    # Parse command line options.  We must do this first so we can
    # see if --daemonize was specified.
 
=== modified file 'bin/pt-mysql-summary'
--- bin/pt-mysql-summary	2013-01-03 00:54:18 +0000
+++ bin/pt-mysql-summary	2013-01-24 19:10:25 +0000
@@ -22,23 +22,32 @@
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
 
+ts() {
+   TS=$(date +%F-%T | tr ':-' '_')
+   echo "$TS $*"
+}
+
+info() {
+   [ ${OPT_VERBOSE:-3} -ge 3 ] && ts "$*"
+}
+
 log() {
-   TS=$(date +%F-%T | tr ':-' '_');
-   echo "$TS $*"
+   [ ${OPT_VERBOSE:-3} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   log "$*" >&2
+   [ ${OPT_VERBOSE:-3} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
 die() {
-   warn "$*"
+   ts "$*" >&2
+   EXIT_STATUS=1
    exit 1
 }
 
 _d () {
-   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(log "$*")" >&2
+   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(ts "$*")" >&2
 }
 
 # ###########################################################################
@@ -2412,7 +2421,7 @@
 # Execute the program if it was not included from another file.
 # This makes it possible to include without executing, and thus test.
 if    [ "${0##*/}" = "$TOOL" ] \
-   || [ "${0##*/}" = "bash" -a "$_" = "$0" ]; then
+   || [ "${0##*/}" = "bash" -a "${_:-""}" = "$0" ]; then
 
    # Set up temporary dir.
    mk_tmpdir
 
=== modified file 'bin/pt-pmp'
--- bin/pt-pmp	2013-01-03 00:54:18 +0000
+++ bin/pt-pmp	2013-01-24 19:10:25 +0000
@@ -215,7 +215,7 @@
 # Execute the program if it was not included from another file.  This makes it
 # possible to include without executing, and thus test.
 if    [ "${0##*/}" = "$TOOL" ] \
-   || [ "${0##*/}" = "bash" -a "$_" = "$0" ]; then
+   || [ "${0##*/}" = "bash" -a "${_:-""}" = "$0" ]; then
    mk_tmpdir
    main "$@"
    rm_tmpdir
 
=== modified file 'bin/pt-sift'
--- bin/pt-sift	2013-01-03 00:54:18 +0000
+++ bin/pt-sift	2013-01-24 19:10:25 +0000
@@ -587,7 +587,7 @@
 # Execute the program if it was not included from another file.  This makes it
 # possible to include without executing, and thus test.
 if    [ "${0##*/}" = "$TOOL" ] \
-   || [ "${0##*/}" = "bash" -a "$_" = "$0" ]; then
+   || [ "${0##*/}" = "bash" -a "${_:-""}" = "$0" ]; then
     main "${@:-""}"
 fi
 
 
=== modified file 'bin/pt-stalk'
--- bin/pt-stalk	2013-01-03 00:54:18 +0000
+++ bin/pt-stalk	2013-01-24 19:10:25 +0000
@@ -22,23 +22,32 @@
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
 
+ts() {
+   TS=$(date +%F-%T | tr ':-' '_')
+   echo "$TS $*"
+}
+
+info() {
+   [ ${OPT_VERBOSE:-3} -ge 3 ] && ts "$*"
+}
+
 log() {
-   TS=$(date +%F-%T | tr ':-' '_');
-   echo "$TS $*"
+   [ ${OPT_VERBOSE:-3} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   log "$*" >&2
+   [ ${OPT_VERBOSE:-3} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
 die() {
-   warn "$*"
+   ts "$*" >&2
+   EXIT_STATUS=1
    exit 1
 }
 
 _d () {
-   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(log "$*")" >&2
+   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(ts "$*")" >&2
 }
 
 # ###########################################################################
@@ -962,6 +971,10 @@
    :
 }
 
+after_interval_sleep() {
+   :
+}
+
 after_stalk() {
    :
 }
@@ -1066,9 +1079,7 @@
    local seconds="$1"
    local msg="${2:-""}"
    if oktorun; then
-      if [ -n "$msg" ]; then
-         log "$msg"
-      fi
+      [ "$msg" ] && info "$msg"
       sleep $seconds
    fi
 }
@@ -1126,7 +1137,11 @@
          fi
 
          local msg="Check results: $OPT_VARIABLE=$value, matched=${matched:-no}, cycles_true=$cycles_true"
-         log "$msg"
+         if [ "$matched" ]; then
+            log "$msg"
+         else
+            info "$msg"
+         fi
       elif [ "$OPT_COLLECT" ]; then
          # Make the next if condition true.
          matched=1
@@ -1140,7 +1155,7 @@
          # ##################################################################
          # Start collecting, maybe.
          # ##################################################################
-         log "Collect triggered"
+         log "Collect $ITER triggered"
 
          # Send email to whomever that collect has been triggered.
          if [ "$OPT_NOTIFY_BY_EMAIL" ]; then
@@ -1166,8 +1181,8 @@
                "$margin"
             if [ $? -eq 0 ]; then
                # There should be enough disk space, so collect.
-               log "$msg"                        >> "$OPT_DEST/$prefix-trigger"
-               log "pt-stalk ran with $RAN_WITH" >> "$OPT_DEST/$prefix-trigger"
+               ts "$msg"                        >> "$OPT_DEST/$prefix-trigger"
+               ts "pt-stalk ran with $RAN_WITH" >> "$OPT_DEST/$prefix-trigger"
                last_prefix="$prefix"
 
                # Plugin hook:
@@ -1181,7 +1196,7 @@
                   collect "$OPT_DEST" "$prefix"
                ) >> "$OPT_DEST/$prefix-output" 2>&1 &
                local collector_pid=$!
-               log "Collector PID $collector_pid"
+               log "Collect $ITER PID $collector_pid"
 
                # Plugin hook:
                after_collect $collector_pid
@@ -1199,6 +1214,7 @@
          # ##################################################################
          # Done collecting.
          # ##################################################################
+         log "Collect $ITER done"
          ITER=$((ITER + 1))
          cycles_true=0
          sleep_ok "$OPT_SLEEP" "Sleeping $OPT_SLEEP seconds after collect"
@@ -1208,6 +1224,9 @@
       else
          # Trigger/check/value is ok, sleep until next check.
          sleep_ok "$OPT_INTERVAL"
+
+         # Plugin hook:
+         after_interval_sleep
       fi
    done
 
@@ -1291,7 +1310,7 @@
 # Execute the program if it was not included from another file.
 # This makes it possible to include without executing, and thus test.
 if    [ "${0##*/}" = "$TOOL" ] \
-   || [ "${0##*/}" = "bash" -a "$_" = "$0" ]; then
+   || [ "${0##*/}" = "bash" -a "${_:-""}" = "$0" ]; then
 
    # Parse command line options.  We must do this first so we can
    # see if --daemonize was specified.
@@ -1737,6 +1756,10 @@
 Called after sleeping L<"--sleep"> seconds for the collector process to finish.
 This hook is called after C<after_collect>.
 
+=item after_interval_sleep
+
+Called after sleeping L<"--interval"> seconds after each trigger check.
+
 =item after_stalk
 
 Called after stalking.  Since pt-stalk stalks forever by default,
@@ -1840,6 +1863,22 @@
 
 The variable to compare against the threshold. See L<"--function"> for details.
 
+=item --verbose
+
+type: int; default: 2
+
+Print more or less information while running.  Since the tool is designed
+to be a long-running daemon, the default verbosity level only prints the
+most important information.  If you run the tool interactively, you may
+want to use a higher verbosity level.
+
+  LEVEL PRINTS
+  ===== =====================================
+  0     Errors
+  1     Warnings
+  2     Matching triggers and collection info
+  3     Non-matching triggers
+
 =item --version
 
 Print tool's version and exit.
 
=== modified file 'bin/pt-summary'
--- bin/pt-summary	2013-01-03 00:54:18 +0000
+++ bin/pt-summary	2013-01-24 19:10:25 +0000
@@ -29,23 +29,32 @@
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
 
+ts() {
+   TS=$(date +%F-%T | tr ':-' '_')
+   echo "$TS $*"
+}
+
+info() {
+   [ ${OPT_VERBOSE:-3} -ge 3 ] && ts "$*"
+}
+
 log() {
-   TS=$(date +%F-%T | tr ':-' '_');
-   echo "$TS $*"
+   [ ${OPT_VERBOSE:-3} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   log "$*" >&2
+   [ ${OPT_VERBOSE:-3} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
 die() {
-   warn "$*"
+   ts "$*" >&2
+   EXIT_STATUS=1
    exit 1
 }
 
 _d () {
-   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(log "$*")" >&2
+   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(ts "$*")" >&2
 }
 
 # ###########################################################################
@@ -2280,7 +2289,7 @@
 # Execute the program if it was not included from another file.  This makes it
 # possible to include without executing, and thus test.
 if    [ "${0##*/}" = "$TOOL" ] \
-   || [ "${0##*/}" = "bash" -a "$_" = "$0" ]; then
+   || [ "${0##*/}" = "bash" -a "${_:-""}" = "$0" ]; then
 
    # Set up temporary dir.
    mk_tmpdir
 
=== modified file 'lib/PerconaTest.pm'
--- lib/PerconaTest.pm	2013-01-03 00:19:16 +0000
+++ lib/PerconaTest.pm	2013-01-24 19:10:25 +0000
@@ -58,7 +58,6 @@
    wait_until
    wait_for
    wait_until_slave_running
-   wait_until_no_lag
    test_log_parser
    test_protocol_parser
    test_packet_parser
@@ -325,6 +324,39 @@
    );
 };
 
+sub kill_program {
+   my (%args) = @_;
+
+   my $pid_file = $args{pid_file};
+   my $pid      = $args{pid};
+
+   if ( $pid_file ) {
+      chomp($pid = `cat $pid_file 2>/dev/null`);
+   }
+
+   if ( $pid ) {
+      PTDEVDEBUG && _d('Killing PID', $pid);
+      kill(15, $pid);
+      wait_until(
+         sub { my $is_alive = kill(0, $pid);  return !$is_alive; },
+         1.5,  # sleep between tries
+         15,   # max time to try
+      );
+      if ( kill(0, $pid) ) {
+         warn "PID $pid did not die; using kill -9\n";
+         kill(9, $pid);
+      }
+   }
+   else {
+      PTDEVDEBUG && _d('No PID to kill');
+   }
+
+   if ( $pid_file && -f $pid_file ) {
+      PTDEVDEBUG && _d('Removing PID file', $pid_file);
+      unlink $pid_file;
+   }
+}
+
 sub not_running {
    my ($cmd) = @_;
    PTDEVDEBUG && _d('Wait until not running:', $cmd);
 
=== modified file 'lib/bash/log_warn_die.sh'
--- lib/bash/log_warn_die.sh	2012-08-13 15:23:18 +0000
+++ lib/bash/log_warn_die.sh	2013-01-24 19:10:25 +0000
@@ -28,23 +28,32 @@
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
 
+ts() {
+   TS=$(date +%F-%T | tr ':-' '_')
+   echo "$TS $*"
+}
+
+info() {
+   [ ${OPT_VERBOSE:-3} -ge 3 ] && ts "$*"
+}
+
 log() {
-   TS=$(date +%F-%T | tr ':-' '_');
-   echo "$TS $*"
+   [ ${OPT_VERBOSE:-3} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   log "$*" >&2
+   [ ${OPT_VERBOSE:-3} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
 die() {
-   warn "$*"
+   ts "$*" >&2
+   EXIT_STATUS=1
    exit 1
 }
 
 _d () {
-   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(log "$*")" >&2
+   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(ts "$*")" >&2
 }
 
 # ###########################################################################
 
=== modified file 't/lib/bash/log_warn_die.sh'
--- t/lib/bash/log_warn_die.sh	2012-06-11 20:51:43 +0000
+++ t/lib/bash/log_warn_die.sh	2013-01-24 19:10:25 +0000
@@ -1,17 +1,15 @@
 #!/usr/bin/env bash
 
-plan 6
-
 source "$LIB_DIR/log_warn_die.sh"
 
-log "Hello world!" > $TEST_PT_TMPDIR/log
+log "Hello world A!" > $TEST_PT_TMPDIR/log
 cmd_ok \
-   "grep -q 'Hello world!' $TEST_PT_TMPDIR/log" \
+   "grep -q 'Hello world A!' $TEST_PT_TMPDIR/log" \
    "log msg"
 
-log "Hello" "world!" > $TEST_PT_TMPDIR/log
+log "Hello" "world B!" > $TEST_PT_TMPDIR/log
 cmd_ok \
-   "grep -q 'Hello world!' $TEST_PT_TMPDIR/log" \
+   "grep -q 'Hello world B!' $TEST_PT_TMPDIR/log" \
    "log msg msg"
 
 is \
@@ -19,14 +17,14 @@
    "0" \
    "Exit status 0"
 
-warn "Hello world!" 2> $TEST_PT_TMPDIR/log
+warn "Hello world C!" 2> $TEST_PT_TMPDIR/log
 cmd_ok \
-   "grep -q 'Hello world!' $TEST_PT_TMPDIR/log" \
+   "grep -q 'Hello world C!' $TEST_PT_TMPDIR/log" \
    "warn msg"
 
-warn "Hello" "world!" 2> $TEST_PT_TMPDIR/log
+warn "Hello" "world D!" 2> $TEST_PT_TMPDIR/log
 cmd_ok \
-   "grep -q 'Hello world!' $TEST_PT_TMPDIR/log" \
+   "grep -q 'Hello world D!' $TEST_PT_TMPDIR/log" \
    "warn msg msg"
 
 is \
@@ -34,6 +32,81 @@
    "1" \
    "Exit status 1"
 
+OPT_VERBOSE=1
+
+info "Hello world 1!" > $TEST_PT_TMPDIR/log
+file_is_empty \
+   $TEST_PT_TMPDIR/log \
+   "verbose=1 info"
+
+log "Hello world 2!" > $TEST_PT_TMPDIR/log
+file_is_empty \
+   $TEST_PT_TMPDIR/log \
+   "verbose=1 log"
+
+warn "Hello world 3!" > $TEST_PT_TMPDIR/log 2>&1
+file_contains \
+   $TEST_PT_TMPDIR/log \
+   "Hello world 3!" \
+   "verbose=1 warn"
+
+OPT_VERBOSE=2
+
+info "Hello world 4!" > $TEST_PT_TMPDIR/log
+file_is_empty \
+   $TEST_PT_TMPDIR/log \
+   "verbose=2 info"
+
+log "Hello world 5!" > $TEST_PT_TMPDIR/log
+file_contains \
+   $TEST_PT_TMPDIR/log \
+   "Hello world 5!" \
+   "verbose=2 log"
+
+warn "Hello world 6!" > $TEST_PT_TMPDIR/log 2>&1
+file_contains \
+   $TEST_PT_TMPDIR/log \
+   "Hello world 6!" \
+   "verbose=2 warn"
+
+OPT_VERBOSE=3
+
+info "Hello world 7!" > $TEST_PT_TMPDIR/log
+file_contains \
+   $TEST_PT_TMPDIR/log \
+   "Hello world 7!" \
+   "verbose=3 info"
+
+log "Hello world 8!" > $TEST_PT_TMPDIR/log
+file_contains \
+   $TEST_PT_TMPDIR/log \
+   "Hello world 8!" \
+   "verbose=3 log"
+
+warn "Hello world 9!" > $TEST_PT_TMPDIR/log 2>&1
+file_contains \
+   $TEST_PT_TMPDIR/log \
+   "Hello world 9!" \
+   "verbose=3 warn"
+
+OPT_VERBOSE=0
+
+info "Hello world 10!" > $TEST_PT_TMPDIR/log
+file_is_empty \
+   $TEST_PT_TMPDIR/log \
+   "verbose=0 info"
+
+log "Hello world 11!" > $TEST_PT_TMPDIR/log
+file_is_empty \
+   $TEST_PT_TMPDIR/log \
+   "verbose=0 log"
+
+warn "Hello world 12!" > $TEST_PT_TMPDIR/log 2>&1
+file_is_empty \
+   $TEST_PT_TMPDIR/log \
+   "verbose=0 warn"
+
 # ###########################################################################
 # Done
 # ###########################################################################
+done_testing
 
=== added file 't/pt-stalk/option_sanity.t'
--- t/pt-stalk/option_sanity.t	1970-01-01 00:00:00 +0000
+++ t/pt-stalk/option_sanity.t	2013-01-24 19:10:25 +0000
@@ -0,0 +1,24 @@
+#!/usr/bin/env perl
+
+BEGIN {
+   die "The PERCONA_TOOLKIT_BRANCH environment variable is not set.\n"
+      unless $ENV{PERCONA_TOOLKIT_BRANCH} && -d $ENV{PERCONA_TOOLKIT_BRANCH};
+   unshift @INC, "$ENV{PERCONA_TOOLKIT_BRANCH}/lib";
+};
+
+use strict;
+use warnings FATAL => 'all';
+use English qw(-no_match_vars);
+use Test::More;
+
+use PerconaTest;
+
+my $output = `$trunk/bin/pt-stalk --help`;
+
+like(
+   $output,
+   qr/^\s+--verbose\s+2/m,
+   "Default --verbose=2"
+);
+
+done_testing;
 
=== modified file 't/pt-stalk/pt-stalk.t'
--- t/pt-stalk/pt-stalk.t	2012-10-23 23:51:59 +0000
+++ t/pt-stalk/pt-stalk.t	2013-01-24 19:10:25 +0000
@@ -28,11 +28,28 @@
 my $pid_file = "/tmp/pt-stalk.pid.$PID";
 my $log_file = "/tmp/pt-stalk.log.$PID";
 my $dest     = "/tmp/pt-stalk.collect.$PID";
+my $int_file = "/tmp/pt-stalk-after-interval-sleep";
 my $pid;
 
-diag(`rm $pid_file 2>/dev/null`);
-diag(`rm $log_file 2>/dev/null`);
-diag(`rm -rf $dest 2>/dev/null`);
+sub cleanup {
+   diag(`rm $pid_file $log_file $int_file 2>/dev/null`);
+   diag(`rm -rf $dest 2>/dev/null`);
+}
+
+sub wait_n_cycles {
+   my ($n) = @_;
+   PerconaTest::wait_until(
+      sub {
+         return 0 unless -f "$dest/after_interval_sleep";
+         my $n_cycles = `wc -l "$dest/after_interval_sleep"  | awk '{print \$1}'`;
+         $n_cycles ||= '';
+         chomp($n_cycles);
+         return ($n_cycles || 0) >= $n; 
+      },
+      1.5,
+      15
+   );
+}
 
 # ###########################################################################
 # Test that it won't run if can't connect to MySQL.
@@ -56,11 +73,14 @@
 # ###########################################################################
 # Test that it runs and dies normally.
 # ###########################################################################
-diag(`rm $pid_file 2>/dev/null`);
-diag(`rm $log_file 2>/dev/null`);
-diag(`rm -rf $dest 2>/dev/null`);
-
-$retval = system("$trunk/bin/pt-stalk --daemonize --pid $pid_file --log $log_file --dest $dest -- --defaults-file=$cnf");
+
+cleanup();
+
+# As of v2.1.9 when --verbose was added, non-matching checks are not
+# printed by default.  So we use the --plugin to tell us when the tool
+# has completed a cycle.
+
+$retval = system("$trunk/bin/pt-stalk --daemonize --pid $pid_file --log $log_file --dest $dest --plugin $trunk/t/pt-stalk/samples/plugin002.sh -- --defaults-file=$cnf");
 
 is(
    $retval >> 8,
@@ -94,21 +114,16 @@
    "pt-stalk is running"
 );
 
-PerconaTest::wait_for_sh("grep -q 'Check results' $log_file >/dev/null");
+wait_n_cycles(2);
+PerconaTest::kill_program(pid_file => $pid_file);
+
 $output = `cat $log_file 2>/dev/null`;
-like(
+unlike(
    $output,
    qr/Check results: Threads_running=\d+, matched=no, cycles_true=0/,
-   "Check results logged"
+   "Non-matching results not logged because --verbose=2"
 ) or diag(`cat $log_file 2>/dev/null`, `cat $dest/*-output 2>/dev/null`);
 
-$retval = system("kill $pid 2>/dev/null");
-is(
-   $retval >> 0,
-   0,
-   "Killed pt-stalk"
-);
-
 PerconaTest::wait_until(sub { !-f $pid_file });
 
 ok(
@@ -123,12 +138,56 @@
    "Caught signal logged"
 ) or diag(`cat $log_file 2>/dev/null`, `cat $dest/*-output 2>/dev/null`);
 
+# #############################################################################
+# --verbose 3 (non-matching results)
+# #############################################################################
+
+cleanup();
+
+$retval = system("$trunk/bin/pt-stalk --daemonize --pid $pid_file --log $log_file --dest $dest --verbose 3 -- --defaults-file=$cnf");
+
+PerconaTest::wait_for_files($pid_file, $log_file);
+PerconaTest::wait_for_sh("grep -q 'Check results' $log_file >/dev/null");
+PerconaTest::kill_program(pid_file => $pid_file);
+
+$output = `cat $log_file 2>/dev/null`;
+like(
+   $output,
+   qr/Check results: Threads_running=\d+, matched=no, cycles_true=0/,
+   "Matching results logged with --verbose 3"
+) or diag(`cat $log_file 2>/dev/null`, `cat $dest/*-output 2>/dev/null`);
+
+# #############################################################################
+# --verbose 1 (just errors and warnings)
+# #############################################################################
+
+cleanup();
+
+$retval = system("$trunk/bin/pt-stalk --daemonize --pid $pid_file --log $log_file --dest $dest --verbose 1 --plugin $trunk/t/pt-stalk/samples/plugin002.sh -- --defaults-file=$cnf");
+
+PerconaTest::wait_for_files($pid_file, $log_file);
+wait_n_cycles(2);
+PerconaTest::kill_program(pid_file => $pid_file);
+
+$output = `cat $log_file 2>/dev/null`;
+
+like(
+   $output,
+   qr/Caught signal, exiting/,
+   "Warning logged (--verbose 1)"
+);
+
+unlike(
+   $output,
+   qr/Start|Collect|Check/i,
+   "No run info log (--verbose 1)"
+);
+
 # ###########################################################################
 # Test collect.
 # ###########################################################################
-diag(`rm $pid_file 2>/dev/null`);
-diag(`rm $log_file 2>/dev/null`);
-diag(`rm $dest/*   2>/dev/null`);
+
+cleanup();
 
 # We'll have to watch Uptime since it's the only status var that's going
 # to be predictable.
@@ -180,10 +239,10 @@
    "Trigger file logs how pt-stalk was ran"
 );
 
-chomp($output = `cat $log_file 2>/dev/null | grep 'Collector PID'`);
+chomp($output = `cat $log_file 2>/dev/null | grep 'Collect [0-9] PID'`);
 like(
    $output,
-   qr/Collector PID \d+/,
+   qr/Collect 1 PID \d+/,
    "Collector PID logged"
 )
 or diag(
@@ -195,9 +254,8 @@
 # ###########################################################################
 # Triggered but --no-collect.
 # ###########################################################################
-diag(`rm $pid_file 2>/dev/null`);
-diag(`rm $log_file 2>/dev/null`);
-diag(`rm $dest/*   2>/dev/null`);
+
+cleanup();
 
 (undef, $uptime) = $dbh->selectrow_array("SHOW STATUS LIKE 'Uptime'");
 $threshold = $uptime + 2;
@@ -209,7 +267,7 @@
 $output = `cat $log_file 2>/dev/null`;
 like(
    $output,
-   qr/Collect triggered/,
+   qr/Collect 1 triggered/,
    "Collect triggered"
 );
 
@@ -227,6 +285,8 @@
 # --config
 # #############################################################################
 
+cleanup();
+
 diag(`cp $ENV{HOME}/.pt-stalk.conf $ENV{HOME}/.pt-stalk.conf.original 2>/dev/null`);
 diag(`cp $trunk/t/pt-stalk/samples/config001.conf $ENV{HOME}/.pt-stalk.conf`);
 
@@ -254,9 +314,8 @@
 # #############################################################################
 # Don't stalk, just collect.
 # #############################################################################
-diag(`rm $pid_file 2>/dev/null`);
-diag(`rm $log_file 2>/dev/null`);
-diag(`rm $dest/*   2>/dev/null`);
+
+cleanup();
 
 $retval = system("$trunk/bin/pt-stalk --no-stalk --run-time 2 --dest $dest --prefix nostalk --pid $pid_file -- --defaults-file=$cnf >$log_file 2>&1");
 
@@ -343,9 +402,7 @@
 # #############################################################################
 # Done.
 # #############################################################################
-diag(`rm $pid_file 2>/dev/null`);
-diag(`rm $log_file 2>/dev/null`);
+cleanup();
 diag(`rm -rf $dest 2>/dev/null`);
 ok($sb->ok(), "Sandbox servers") or BAIL_OUT(__FILE__ . " broke the sandbox");
-
 done_testing;
 
=== added file 't/pt-stalk/samples/plugin002.sh'
--- t/pt-stalk/samples/plugin002.sh	1970-01-01 00:00:00 +0000
+++ t/pt-stalk/samples/plugin002.sh	2013-01-24 19:10:25 +0000
@@ -0,0 +1,5 @@
+#!/bin/sh
+
+after_interval_sleep() {
+   date >> "$OPT_DEST/after_interval_sleep"
+}
 
=== modified file 'util/test-bash-functions'
--- util/test-bash-functions	2012-08-22 20:50:11 +0000
+++ util/test-bash-functions	2013-01-24 19:10:25 +0000
@@ -100,6 +100,7 @@
 result() {
    local result=$1
    local test_name=${2:-""}
+   testno=$((testno + 1))
    if [ $result -eq 0 ]; then
       echo "ok $testno - $TEST_FILE $test_name"
    else
@@ -110,7 +111,6 @@
          cat $TEST_PT_TMPDIR/failed_result | sed -e 's/^/#   /' -e '30q' >&2
       fi
    fi
-   testno=$((testno + 1))
    return $result
 }
 
@@ -121,19 +121,21 @@
    fi
 }
 
+done_testing() {
+   echo "1..$testno"
+}
+
 #
 # The following subs are for the test files to call.
 #
 
 pass() {
    local reason="${1:-""}"
-
    result 0 "$reason"
 }
 
 fail() {
    local reason="${1:-""}"
-
    result 1 "$reason"
 }
 
@@ -177,6 +179,42 @@
    result $? "$test_name"
 }
 
+file_is_empty() {
+   local file=$1
+   local test_name=${2:-""}
+   test_command="-s $file"
+   if [ ! -f "$file" ]; then
+      echo "$file does not exist" > $TEST_PT_TMPDIR/failed_result
+      result 1 "$test_name"
+   fi
+   if [ -s "$file" ]; then
+      echo "$file is not empty:" > $TEST_PT_TMPDIR/failed_result
+      cat "$file" >> $TEST_PT_TMPDIR/failed_result
+      result 1 "$test_name"
+   else
+      result 0 "$test_name"
+   fi
+}
+
+file_contains() {
+   local file="$1"
+   local pat="$2"
+   local test_name=${3:-""}
+   test_command="grep -q '$pat' '$file'"
+   if [ ! -f "$file" ]; then
+      echo "$file does not exist" > $TEST_PT_TMPDIR/failed_result
+      result 1 "$test_name"
+   fi
+   grep -q "$pat" $file
+   if [ $? -ne 0 ]; then
+      echo "$file does not contain '$pat':" > $TEST_PT_TMPDIR/failed_result
+      cat "$file" >> $TEST_PT_TMPDIR/failed_result
+      result 1 "$test_name"
+   else
+      result 0 "$test_name"
+   fi
+}
+
 cmd_ok() {
    local test_command=$1
    local test_name=${2:-""}
@@ -226,7 +264,7 @@
 # Script starts here
 # ############################################################################
 
-testno=1
+testno=0
 failed_tests=0
 
 if [ $# -eq 0 ]; then