From 98ced1a0351b693992635ccd63a4d78c8eb29da7 Mon Sep 17 00:00:00 2001
From: Daniel Nichter <daniel@percona.com>
Date: Thu, 24 Jan 2013 09:17:19 -0700
Subject: [PATCH 1/7] Make add info() log_warn_die.sh and make the subs respect
 OPT_VERBOSE.  Add more test harness subs in util/test-bash-functions.

---
 lib/bash/log_warn_die.sh   | 20 ++++++++---
 t/lib/bash/log_warn_die.sh | 74 ++++++++++++++++++++++++++++++++++++++
 util/test-bash-functions   | 38 ++++++++++++++++++--
 3 files changed, 125 insertions(+), 7 deletions(-)

diff --git a/lib/bash/log_warn_die.sh b/lib/bash/log_warn_die.sh
index aa07e31e..cb6095ac 100644
--- a/lib/bash/log_warn_die.sh
+++ b/lib/bash/log_warn_die.sh
@@ -27,24 +27,34 @@ set -u
 PTFUNCNAME=""
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
+OPT_VERBOSE=${OPT_VERBOSE:-3}
 
-log() {
-   TS=$(date +%F-%T | tr ':-' '_');
+_print() {
+   TS=$(date +%F-%T | tr ':-' '_')
    echo "$TS $*"
 }
 
+info() {
+   [ ${OPT_VERBOSE:-0} -ge 3 ] && _print "$*"
+}
+
+log() {
+   [ ${OPT_VERBOSE:-0} -ge 2 ] && _print "$*"
+}
+
 warn() {
-   log "$*" >&2
+   [ ${OPT_VERBOSE:-0} -ge 1 ] && _print "$*" >&2
    EXIT_STATUS=1
 }
 
 die() {
-   warn "$*"
+   _print "$*" >&2
+   EXIT_STATUS=1
    exit 1
 }
 
 _d () {
-   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(log "$*")" >&2
+   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(_print "$*")" >&2
 }
 
 # ###########################################################################
diff --git a/t/lib/bash/log_warn_die.sh b/t/lib/bash/log_warn_die.sh
index 8d71d089..303e2949 100644
--- a/t/lib/bash/log_warn_die.sh
+++ b/t/lib/bash/log_warn_die.sh
@@ -34,6 +34,80 @@ is \
    "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
 # ###########################################################################
diff --git a/util/test-bash-functions b/util/test-bash-functions
index 2616c7c8..60a1a0f8 100755
--- a/util/test-bash-functions
+++ b/util/test-bash-functions
@@ -127,13 +127,11 @@ plan() {
 
 pass() {
    local reason="${1:-""}"
-
    result 0 "$reason"
 }
 
 fail() {
    local reason="${1:-""}"
-
    result 1 "$reason"
 }
 
@@ -177,6 +175,42 @@ is() {
    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:-""}

From 11fa16382ce7e30b9f756f6fe161de138e892b99 Mon Sep 17 00:00:00 2001
From: Daniel Nichter <daniel@percona.com>
Date: Thu, 24 Jan 2013 09:36:57 -0700
Subject: [PATCH 2/7] Add --verbose to pt-stalk.  Change _print() to ts() in
 log_warn_die.sh.

---
 bin/pt-stalk             | 55 ++++++++++++++++++++++++++++++----------
 lib/bash/log_warn_die.sh | 12 ++++-----
 2 files changed, 48 insertions(+), 19 deletions(-)

diff --git a/bin/pt-stalk b/bin/pt-stalk
index 81a7df90..ae6ddf7d 100755
--- a/bin/pt-stalk
+++ b/bin/pt-stalk
@@ -21,24 +21,34 @@ set -u
 PTFUNCNAME=""
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
+OPT_VERBOSE=${OPT_VERBOSE:-3}
 
-log() {
-   TS=$(date +%F-%T | tr ':-' '_');
+ts() {
+   TS=$(date +%F-%T | tr ':-' '_')
    echo "$TS $*"
 }
 
+info() {
+   [ ${OPT_VERBOSE:-0} -ge 3 ] && ts "$*"
+}
+
+log() {
+   [ ${OPT_VERBOSE:-0} -ge 2 ] && ts "$*"
+}
+
 warn() {
-   log "$*" >&2
+   [ ${OPT_VERBOSE:-0} -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
 }
 
 # ###########################################################################
@@ -1066,9 +1076,7 @@ sleep_ok() {
    local seconds="$1"
    local msg="${2:-""}"
    if oktorun; then
-      if [ -n "$msg" ]; then
-         log "$msg"
-      fi
+      [ "$msg" ] && info "$msg"
       sleep $seconds
    fi
 }
@@ -1126,7 +1134,11 @@ stalk() {
          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 +1152,7 @@ stalk() {
          # ##################################################################
          # 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 +1178,8 @@ stalk() {
                "$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 +1193,7 @@ stalk() {
                   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 +1211,7 @@ stalk() {
          # ##################################################################
          # Done collecting.
          # ##################################################################
+         log "Collect $ITER done"
          ITER=$((ITER + 1))
          cycles_true=0
          sleep_ok "$OPT_SLEEP" "Sleeping $OPT_SLEEP seconds after collect"
@@ -1840,6 +1853,22 @@ type: string; default: Threads_running
 
 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.
diff --git a/lib/bash/log_warn_die.sh b/lib/bash/log_warn_die.sh
index cb6095ac..249ac8de 100644
--- a/lib/bash/log_warn_die.sh
+++ b/lib/bash/log_warn_die.sh
@@ -29,32 +29,32 @@ PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
 OPT_VERBOSE=${OPT_VERBOSE:-3}
 
-_print() {
+ts() {
    TS=$(date +%F-%T | tr ':-' '_')
    echo "$TS $*"
 }
 
 info() {
-   [ ${OPT_VERBOSE:-0} -ge 3 ] && _print "$*"
+   [ ${OPT_VERBOSE:-0} -ge 3 ] && ts "$*"
 }
 
 log() {
-   [ ${OPT_VERBOSE:-0} -ge 2 ] && _print "$*"
+   [ ${OPT_VERBOSE:-0} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   [ ${OPT_VERBOSE:-0} -ge 1 ] && _print "$*" >&2
+   [ ${OPT_VERBOSE:-0} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
 die() {
-   _print "$*" >&2
+   ts "$*" >&2
    EXIT_STATUS=1
    exit 1
 }
 
 _d () {
-   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(_print "$*")" >&2
+   [ "$PTDEBUG" ] && echo "# $PTFUNCNAME: $(ts "$*")" >&2
 }
 
 # ###########################################################################

From b196f50e60b2f57c5ec416151176c5d51acb1328 Mon Sep 17 00:00:00 2001
From: Daniel Nichter <daniel@percona.com>
Date: Thu, 24 Jan 2013 11:13:39 -0700
Subject: [PATCH 3/7] Test --verbose.  Remove global default OPT_VERBOSE from
 log_warn_die.sh so tool's option can set it.

---
 bin/pt-stalk                    |  12 +++-
 lib/PerconaTest.pm              |  34 ++++++++-
 lib/bash/log_warn_die.sh        |   1 -
 t/pt-stalk/option_sanity.t      |  24 +++++++
 t/pt-stalk/pt-stalk.t           | 121 +++++++++++++++++++++++---------
 t/pt-stalk/samples/plugin002.sh |   5 ++
 6 files changed, 162 insertions(+), 35 deletions(-)
 create mode 100644 t/pt-stalk/option_sanity.t
 create mode 100644 t/pt-stalk/samples/plugin002.sh

diff --git a/bin/pt-stalk b/bin/pt-stalk
index ae6ddf7d..f08272e6 100755
--- a/bin/pt-stalk
+++ b/bin/pt-stalk
@@ -21,7 +21,6 @@ set -u
 PTFUNCNAME=""
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
-OPT_VERBOSE=${OPT_VERBOSE:-3}
 
 ts() {
    TS=$(date +%F-%T | tr ':-' '_')
@@ -972,6 +971,10 @@ after_collect_sleep() {
    :
 }
 
+after_interval_sleep() {
+   :
+}
+
 after_stalk() {
    :
 }
@@ -1221,6 +1224,9 @@ stalk() {
       else
          # Trigger/check/value is ok, sleep until next check.
          sleep_ok "$OPT_INTERVAL"
+
+         # Plugin hook:
+         after_interval_sleep
       fi
    done
 
@@ -1750,6 +1756,10 @@ C<after_collect_sleep>.
 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,
diff --git a/lib/PerconaTest.pm b/lib/PerconaTest.pm
index 8c05949a..5da730b4 100644
--- a/lib/PerconaTest.pm
+++ b/lib/PerconaTest.pm
@@ -58,7 +58,6 @@ our @EXPORT      = qw(
    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 wait_for_sh {
    );
 };
 
+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);
diff --git a/lib/bash/log_warn_die.sh b/lib/bash/log_warn_die.sh
index 249ac8de..b100133a 100644
--- a/lib/bash/log_warn_die.sh
+++ b/lib/bash/log_warn_die.sh
@@ -27,7 +27,6 @@ set -u
 PTFUNCNAME=""
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
-OPT_VERBOSE=${OPT_VERBOSE:-3}
 
 ts() {
    TS=$(date +%F-%T | tr ':-' '_')
diff --git a/t/pt-stalk/option_sanity.t b/t/pt-stalk/option_sanity.t
new file mode 100644
index 00000000..66077735
--- /dev/null
+++ b/t/pt-stalk/option_sanity.t
@@ -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;
diff --git a/t/pt-stalk/pt-stalk.t b/t/pt-stalk/pt-stalk.t
index 30048726..464a4d45 100644
--- a/t/pt-stalk/pt-stalk.t
+++ b/t/pt-stalk/pt-stalk.t
@@ -28,11 +28,28 @@ my $cnf      = "/tmp/12345/my.sandbox.cnf";
 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 @@ is(
 # ###########################################################################
 # 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 @@ is(
    "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 @@ like(
    "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 @@ like(
    "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 @@ or diag(
 # ###########################################################################
 # 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 @@ PerconaTest::wait_until(sub { !-f $pid_file });
 $output = `cat $log_file 2>/dev/null`;
 like(
    $output,
-   qr/Collect triggered/,
+   qr/Collect 1 triggered/,
    "Collect triggered"
 );
 
@@ -227,6 +285,8 @@ ok(
 # --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 @@ diag(`cp $ENV{HOME}/.pt-stalk.conf.original $ENV{HOME}/.pt-stalk.conf 2>/dev/nul
 # #############################################################################
 # 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 @@ unlike(
 # #############################################################################
 # 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;
diff --git a/t/pt-stalk/samples/plugin002.sh b/t/pt-stalk/samples/plugin002.sh
new file mode 100644
index 00000000..65093aa1
--- /dev/null
+++ b/t/pt-stalk/samples/plugin002.sh
@@ -0,0 +1,5 @@
+#!/bin/sh
+
+after_interval_sleep() {
+   date >> "$OPT_DEST/after_interval_sleep"
+}

From 738359dd10db0f9a17027123aa20fb05622491ef Mon Sep 17 00:00:00 2001
From: Daniel Nichter <daniel@percona.com>
Date: Thu, 24 Jan 2013 11:16:42 -0700
Subject: [PATCH 4/7] Update log_warn_die.sh in pt-ioprofile, pt-mysql-summary,
 and pt-summary.

---
 bin/pt-ioprofile     | 19 ++++++++++++++-----
 bin/pt-mysql-summary | 19 ++++++++++++++-----
 bin/pt-summary       | 19 ++++++++++++++-----
 3 files changed, 42 insertions(+), 15 deletions(-)

diff --git a/bin/pt-ioprofile b/bin/pt-ioprofile
index 5f4a0c57..91f1de08 100755
--- a/bin/pt-ioprofile
+++ b/bin/pt-ioprofile
@@ -20,23 +20,32 @@ PTFUNCNAME=""
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
 
-log() {
-   TS=$(date +%F-%T | tr ':-' '_');
+ts() {
+   TS=$(date +%F-%T | tr ':-' '_')
    echo "$TS $*"
 }
 
+info() {
+   [ ${OPT_VERBOSE:-0} -ge 3 ] && ts "$*"
+}
+
+log() {
+   [ ${OPT_VERBOSE:-0} -ge 2 ] && ts "$*"
+}
+
 warn() {
-   log "$*" >&2
+   [ ${OPT_VERBOSE:-0} -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
 }
 
 # ###########################################################################
diff --git a/bin/pt-mysql-summary b/bin/pt-mysql-summary
index f5a40676..0c5352d4 100755
--- a/bin/pt-mysql-summary
+++ b/bin/pt-mysql-summary
@@ -22,23 +22,32 @@ PTFUNCNAME=""
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
 
-log() {
-   TS=$(date +%F-%T | tr ':-' '_');
+ts() {
+   TS=$(date +%F-%T | tr ':-' '_')
    echo "$TS $*"
 }
 
+info() {
+   [ ${OPT_VERBOSE:-0} -ge 3 ] && ts "$*"
+}
+
+log() {
+   [ ${OPT_VERBOSE:-0} -ge 2 ] && ts "$*"
+}
+
 warn() {
-   log "$*" >&2
+   [ ${OPT_VERBOSE:-0} -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
 }
 
 # ###########################################################################
diff --git a/bin/pt-summary b/bin/pt-summary
index 4c4ac007..1cfcbfc1 100755
--- a/bin/pt-summary
+++ b/bin/pt-summary
@@ -29,23 +29,32 @@ PTFUNCNAME=""
 PTDEBUG="${PTDEBUG:-""}"
 EXIT_STATUS=0
 
-log() {
-   TS=$(date +%F-%T | tr ':-' '_');
+ts() {
+   TS=$(date +%F-%T | tr ':-' '_')
    echo "$TS $*"
 }
 
+info() {
+   [ ${OPT_VERBOSE:-0} -ge 3 ] && ts "$*"
+}
+
+log() {
+   [ ${OPT_VERBOSE:-0} -ge 2 ] && ts "$*"
+}
+
 warn() {
-   log "$*" >&2
+   [ ${OPT_VERBOSE:-0} -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
 }
 
 # ###########################################################################

From 26cc08d3d9d0c4c32da9c40d97047e9685eeda41 Mon Sep 17 00:00:00 2001
From: Daniel Nichter <daniel@percona.com>
Date: Thu, 24 Jan 2013 11:39:23 -0700
Subject: [PATCH 5/7] Fix default log level in log_warn_die.sh.

---
 bin/pt-ioprofile           |  6 +++---
 bin/pt-mysql-summary       |  6 +++---
 bin/pt-stalk               |  6 +++---
 bin/pt-summary             |  6 +++---
 lib/bash/log_warn_die.sh   |  6 +++---
 t/lib/bash/log_warn_die.sh | 19 +++++++++----------
 t/pt-stalk/option_sanity.t |  2 +-
 util/test-bash-functions   |  8 ++++++--
 8 files changed, 31 insertions(+), 28 deletions(-)

diff --git a/bin/pt-ioprofile b/bin/pt-ioprofile
index 91f1de08..0e81b8af 100755
--- a/bin/pt-ioprofile
+++ b/bin/pt-ioprofile
@@ -26,15 +26,15 @@ ts() {
 }
 
 info() {
-   [ ${OPT_VERBOSE:-0} -ge 3 ] && ts "$*"
+   [ ${OPT_VERBOSE:-3} -ge 3 ] && ts "$*"
 }
 
 log() {
-   [ ${OPT_VERBOSE:-0} -ge 2 ] && ts "$*"
+   [ ${OPT_VERBOSE:-3} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   [ ${OPT_VERBOSE:-0} -ge 1 ] && ts "$*" >&2
+   [ ${OPT_VERBOSE:-3} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
diff --git a/bin/pt-mysql-summary b/bin/pt-mysql-summary
index 0c5352d4..48ea5c9d 100755
--- a/bin/pt-mysql-summary
+++ b/bin/pt-mysql-summary
@@ -28,15 +28,15 @@ ts() {
 }
 
 info() {
-   [ ${OPT_VERBOSE:-0} -ge 3 ] && ts "$*"
+   [ ${OPT_VERBOSE:-3} -ge 3 ] && ts "$*"
 }
 
 log() {
-   [ ${OPT_VERBOSE:-0} -ge 2 ] && ts "$*"
+   [ ${OPT_VERBOSE:-3} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   [ ${OPT_VERBOSE:-0} -ge 1 ] && ts "$*" >&2
+   [ ${OPT_VERBOSE:-3} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
diff --git a/bin/pt-stalk b/bin/pt-stalk
index f08272e6..3add242b 100755
--- a/bin/pt-stalk
+++ b/bin/pt-stalk
@@ -28,15 +28,15 @@ ts() {
 }
 
 info() {
-   [ ${OPT_VERBOSE:-0} -ge 3 ] && ts "$*"
+   [ ${OPT_VERBOSE:-3} -ge 3 ] && ts "$*"
 }
 
 log() {
-   [ ${OPT_VERBOSE:-0} -ge 2 ] && ts "$*"
+   [ ${OPT_VERBOSE:-3} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   [ ${OPT_VERBOSE:-0} -ge 1 ] && ts "$*" >&2
+   [ ${OPT_VERBOSE:-3} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
diff --git a/bin/pt-summary b/bin/pt-summary
index 1cfcbfc1..3fc9c51a 100755
--- a/bin/pt-summary
+++ b/bin/pt-summary
@@ -35,15 +35,15 @@ ts() {
 }
 
 info() {
-   [ ${OPT_VERBOSE:-0} -ge 3 ] && ts "$*"
+   [ ${OPT_VERBOSE:-3} -ge 3 ] && ts "$*"
 }
 
 log() {
-   [ ${OPT_VERBOSE:-0} -ge 2 ] && ts "$*"
+   [ ${OPT_VERBOSE:-3} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   [ ${OPT_VERBOSE:-0} -ge 1 ] && ts "$*" >&2
+   [ ${OPT_VERBOSE:-3} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
diff --git a/lib/bash/log_warn_die.sh b/lib/bash/log_warn_die.sh
index b100133a..541f7c3c 100644
--- a/lib/bash/log_warn_die.sh
+++ b/lib/bash/log_warn_die.sh
@@ -34,15 +34,15 @@ ts() {
 }
 
 info() {
-   [ ${OPT_VERBOSE:-0} -ge 3 ] && ts "$*"
+   [ ${OPT_VERBOSE:-3} -ge 3 ] && ts "$*"
 }
 
 log() {
-   [ ${OPT_VERBOSE:-0} -ge 2 ] && ts "$*"
+   [ ${OPT_VERBOSE:-3} -ge 2 ] && ts "$*"
 }
 
 warn() {
-   [ ${OPT_VERBOSE:-0} -ge 1 ] && ts "$*" >&2
+   [ ${OPT_VERBOSE:-3} -ge 1 ] && ts "$*" >&2
    EXIT_STATUS=1
 }
 
diff --git a/t/lib/bash/log_warn_die.sh b/t/lib/bash/log_warn_die.sh
index 303e2949..49cbfcb1 100644
--- a/t/lib/bash/log_warn_die.sh
+++ b/t/lib/bash/log_warn_die.sh
@@ -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 @@ is \
    "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 \
@@ -111,3 +109,4 @@ file_is_empty \
 # ###########################################################################
 # Done
 # ###########################################################################
+done_testing
diff --git a/t/pt-stalk/option_sanity.t b/t/pt-stalk/option_sanity.t
index 66077735..b199dc46 100644
--- a/t/pt-stalk/option_sanity.t
+++ b/t/pt-stalk/option_sanity.t
@@ -17,7 +17,7 @@ my $output = `$trunk/bin/pt-stalk --help`;
 
 like(
    $output,
-   qr/^\s+--verbose\s+2/m,
+   qr/^\s+--vebose\s+2/m,
    "Default --verbose=2"
 );
 
diff --git a/util/test-bash-functions b/util/test-bash-functions
index 60a1a0f8..53639158 100755
--- a/util/test-bash-functions
+++ b/util/test-bash-functions
@@ -100,6 +100,7 @@ run_test() {
 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 @@ result() {
          cat $TEST_PT_TMPDIR/failed_result | sed -e 's/^/#   /' -e '30q' >&2
       fi
    fi
-   testno=$((testno + 1))
    return $result
 }
 
@@ -121,6 +121,10 @@ plan() {
    fi
 }
 
+done_testing() {
+   echo "1..$testno"
+}
+
 #
 # The following subs are for the test files to call.
 #
@@ -260,7 +264,7 @@ diag() {
 # Script starts here
 # ############################################################################
 
-testno=1
+testno=0
 failed_tests=0
 
 if [ $# -eq 0 ]; then

From a56097fe6cb6cb118807ef97a17802ffe4b0a144 Mon Sep 17 00:00:00 2001
From: Daniel Nichter <daniel@percona.com>
Date: Thu, 24 Jan 2013 11:45:44 -0700
Subject: [PATCH 6/7] Fix typo in t/pt-stalk/option_sanity.t.

---
 t/pt-stalk/option_sanity.t | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/t/pt-stalk/option_sanity.t b/t/pt-stalk/option_sanity.t
index b199dc46..66077735 100644
--- a/t/pt-stalk/option_sanity.t
+++ b/t/pt-stalk/option_sanity.t
@@ -17,7 +17,7 @@ my $output = `$trunk/bin/pt-stalk --help`;
 
 like(
    $output,
-   qr/^\s+--vebose\s+2/m,
+   qr/^\s+--verbose\s+2/m,
    "Default --verbose=2"
 );
 

From b4cfe5b26c10755d9f80113320129d5ebe6a9fed Mon Sep 17 00:00:00 2001
From: Daniel Nichter <daniel@percona.com>
Date: Thu, 24 Jan 2013 12:08:09 -0700
Subject: [PATCH 7/7] Fix error caused on some boxes by using diff when it's
 not defined.

---
 bin/pt-ioprofile     | 2 +-
 bin/pt-mysql-summary | 2 +-
 bin/pt-pmp           | 2 +-
 bin/pt-sift          | 2 +-
 bin/pt-stalk         | 2 +-
 bin/pt-summary       | 2 +-
 6 files changed, 6 insertions(+), 6 deletions(-)

diff --git a/bin/pt-ioprofile b/bin/pt-ioprofile
index 0e81b8af..f73b97ef 100755
--- a/bin/pt-ioprofile
+++ b/bin/pt-ioprofile
@@ -870,7 +870,7 @@ main() {
 # 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.
diff --git a/bin/pt-mysql-summary b/bin/pt-mysql-summary
index 48ea5c9d..8691b59f 100755
--- a/bin/pt-mysql-summary
+++ b/bin/pt-mysql-summary
@@ -2421,7 +2421,7 @@ main() {
 # 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
diff --git a/bin/pt-pmp b/bin/pt-pmp
index eb545746..b8b00dba 100755
--- a/bin/pt-pmp
+++ b/bin/pt-pmp
@@ -215,7 +215,7 @@ main() {
 # 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
diff --git a/bin/pt-sift b/bin/pt-sift
index 5be9e9b6..16df99ac 100755
--- a/bin/pt-sift
+++ b/bin/pt-sift
@@ -587,7 +587,7 @@ main() {
 # 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
 
diff --git a/bin/pt-stalk b/bin/pt-stalk
index 3add242b..8adbd5bc 100755
--- a/bin/pt-stalk
+++ b/bin/pt-stalk
@@ -1310,7 +1310,7 @@ main() {
 # 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.
diff --git a/bin/pt-summary b/bin/pt-summary
index 3fc9c51a..32e864b7 100755
--- a/bin/pt-summary
+++ b/bin/pt-summary
@@ -2289,7 +2289,7 @@ sigtrap() { local PTFUNCNAME=sigtrap;
 # 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