Test --verbose. Remove global default OPT_VERBOSE from log_warn_die.sh so tool's option can set it.

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,

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);

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 ':-' '_')

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;

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`);
+sub cleanup {
-diag(`rm $log_file 2>/dev/null`);
+   diag(`rm $pid_file $log_file $int_file 2>/dev/null`);
-diag(`rm -rf $dest 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`);
+cleanup();
-diag(`rm $dest/*   2>/dev/null`);
 
 # 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`);
+cleanup();
-diag(`rm $dest/*   2>/dev/null`);
 
 (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`);
+cleanup();
-diag(`rm $dest/*   2>/dev/null`);
 
 $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`);
+cleanup();
-diag(`rm $log_file 2>/dev/null`);
 diag(`rm -rf $dest 2>/dev/null`);
 ok($sb->ok(), "Sandbox servers") or BAIL_OUT(__FILE__ . " broke the sandbox");
-
 done_testing;

t/pt-stalk/samples/plugin002.sh

@@ -0,0 +1,5 @@
+#!/bin/sh
+
+after_interval_sleep() {
+   date >> "$OPT_DEST/after_interval_sleep"
+}