pt-kill: Add a --log-dsn option.

This is customer issue 23049.

bin/pt-kill

@@ -1969,6 +1969,7 @@ sub new {
       last_poll   => 0,
       active_cxn  => {},  # keyed off ID
       event_cache => [],
+      _reasons_for_matching => {},
    };
    return bless $self, $class;
 }
@@ -2178,7 +2179,9 @@ sub find {
             PTDEBUG && _d("Query isn't running long enough");
             next QUERY;
          }
-         PTDEBUG && _d('Exceeds busy time');
+         my $reason = 'Exceeds busy time';
+         PTDEBUG && _d($reason);
+         push @{$self->{_reasons_for_matching}->{$query} ||= []}, $reason;
          $matched++;
       }
 
@@ -2187,7 +2190,9 @@ sub find {
             PTDEBUG && _d("Query isn't idle long enough");
             next QUERY;
          }
-         PTDEBUG && _d('Exceeds idle time');
+         my $reason = 'Exceeds idle time';
+         PTDEBUG && _d($reason);
+         push @{$self->{_reasons_for_matching}->{$query} ||= []}, $reason;
          $matched++;
       }
  
@@ -2204,7 +2209,9 @@ sub find {
                PTDEBUG && _d('Query does not match', $property, 'spec');
                next QUERY;
             }
-            PTDEBUG && _d('Query matches', $property, 'spec');
+            my $reason = 'Query matches ' . $property . ' spec';
+            PTDEBUG && _d($reason);
+            push @{$self->{_reasons_for_matching}->{$query} ||= []}, $reason;
             $matched++;
          }
       }
@@ -3658,6 +3665,40 @@ sub main {
       };
    }
 
+   my ($log_dbh, $log_sth, @processlist_columns);
+
+   if ( my $log_dsn = $o->get('log-dsn') ) {
+      my $db    = $log_dsn->{d};
+      my $table = $log_dsn->{t};
+      die "The DSN passed in for --log-dsn must have a database and table set"
+         unless defined $table && defined $db;
+      $log_dbh = get_cxn($dp, $log_dsn, 0);
+
+      my $sql = $o->read_para_after(
+         __FILE__, qr/MAGIC_create_log_table/);
+      $sql =~ s/kill_log/IF NOT EXISTS `$db`.`$table`/;
+
+      # Create the log-table table if desired
+      if ( $o->get('create-log-table') ) {
+         PTDEBUG && _d($sql);
+         $log_dbh->do($sql);
+      }
+
+      my $sth = $log_dbh->prepare("SHOW COLUMNS FROM `$db`.`$table`");
+      $sth->execute();
+      my (undef, @all_log_columns) = map @{$_}, @{$sth->fetchall_arrayref([0])};
+      $sth->finish();
+
+      local $LIST_SEPARATOR = ", ";
+      $log_sth = $log_dbh->prepare(
+         "INSERT INTO `$db`.`$table` (@all_log_columns) VALUES("
+       . join(", ", map { "?" } @all_log_columns)
+       . ")"
+      );
+
+      @processlist_columns = @all_log_columns[3 .. $#all_log_columns];
+   }
+
    # ########################################################################
    # Daemonize only after (potentially) asking for passwords for --ask-pass.
    # ########################################################################
@@ -3866,6 +3907,14 @@ sub main {
                   msg("Error killing $query->{Id}: $EVAL_ERROR");
                }
                else {
+                  if ( $log_sth ) {
+                     my $sql     = 'SELECT @@SERVER_ID';
+                     PTDEBUG && _d($sql);
+                     my ($id)    = $dbh->selectrow_array($sql);
+                     my $ts      = Transformers::ts(localtime);
+                     my $reasons = join "\n", @{ $pl->{_reasons_for_matching}->{$query} };
+                     $log_sth->execute($id, $ts, $reasons, @{$query}{@processlist_columns} );
+                  }
                   msg("Killed $query->{Id}");
                }
             }
@@ -4155,6 +4204,13 @@ type: Array
 Read this comma-separated list of config files; if specified, this must be the
 first option on the command line.
 
+=item --create-log-table
+
+Create the L<"--log-dsn"> table if it does not exist.
+
+This option causes the table specified by L<"--log-dsn"> to be created with the
+default structure shown in the documentation for that option.
+
 =item --daemonize
 
 Fork to the background and detach from the shell.  POSIX operating systems
@@ -4259,6 +4315,35 @@ type: string
 
 Print all output to this file when daemonized.
 
+=item --log-dsn
+
+type: DSN
+
+Store each query killed in this DSN.
+
+The argument specifies a table to store all killed queries.  The
+table must have at least the following columns.  You can add more columns for
+your own special purposes, but they won't be used by pt-kill.  The
+following CREATE TABLE definition is also used for L<"--create-log-table">.
+MAGIC_create_log_table:
+
+   CREATE TABLE kill_log (
+      kill_id     int(10) unsigned NOT NULL AUTO_INCREMENT,
+      server_id   bigint(4) NOT NULL DEFAULT '0',
+      timestamp   DATETIME,
+      reason      TEXT,
+      Id          bigint(4) NOT NULL DEFAULT '0',
+      User        varchar(16) NOT NULL DEFAULT '',
+      Host        varchar(64) NOT NULL DEFAULT '',
+      db          varchar(64) DEFAULT NULL,
+      Command     varchar(16) NOT NULL DEFAULT '',
+      Time        int(7) NOT NULL DEFAULT '0',
+      State       varchar(64) DEFAULT NULL,
+      Info        longtext,
+      Time_ms     bigint(21) DEFAULT '0', # NOTE, TODO: currently not used
+      PRIMARY KEY (kill_id)
+   ) DEFAULT CHARSET=utf8
+
 =item --password
 
 short form: -p; type: string
@@ -4764,6 +4849,14 @@ dsn: user; copy: yes
 
 User for login if not current user.
 
+=item * t
+
+Table to log actions in, if passed through --log-dsn.
+
+=item * d
+
+Database to log actions in, if passed through --log-dsn.
+
 =back
 
 =head1 ENVIRONMENT

lib/Processlist.pm

@@ -75,6 +75,7 @@ sub new {
       last_poll   => 0,
       active_cxn  => {},  # keyed off ID
       event_cache => [],
+      _reasons_for_matching => {},
    };
    return bless $self, $class;
 }
@@ -474,7 +475,15 @@ sub find {
             PTDEBUG && _d("Query isn't running long enough");
             next QUERY;
          }
-         PTDEBUG && _d('Exceeds busy time');
+         my $reason = 'Exceeds busy time';
+         PTDEBUG && _d($reason);
+         # Saving the reasons for each query in the objct is a bit nasty,
+         # but the alternatives are worse:
+         # - Saving internal data in the query
+         # - Instead of using the stringified hashref as a key, using
+         #   a checksum of the hashes' contents. Which could occasionally
+         #   fail miserably due to timing-related issues.
+         push @{$self->{_reasons_for_matching}->{$query} ||= []}, $reason;
          $matched++;
       }
 
@@ -484,7 +493,9 @@ sub find {
             PTDEBUG && _d("Query isn't idle long enough");
             next QUERY;
          }
-         PTDEBUG && _d('Exceeds idle time');
+         my $reason = 'Exceeds idle time';
+         PTDEBUG && _d($reason);
+         push @{$self->{_reasons_for_matching}->{$query} ||= []}, $reason;
          $matched++;
       }
  
@@ -505,7 +516,9 @@ sub find {
                PTDEBUG && _d('Query does not match', $property, 'spec');
                next QUERY;
             }
-            PTDEBUG && _d('Query matches', $property, 'spec');
+            my $reason = 'Query matches ' . $property . ' spec';
+            PTDEBUG && _d($reason);
+            push @{$self->{_reasons_for_matching}->{$query} ||= []}, $reason;
             $matched++;
          }
       }

t/lib/Processlist.t

@@ -9,7 +9,7 @@ BEGIN {
 use strict;
 use warnings FATAL => 'all';
 use English qw(-no_match_vars);
-use Test::More tests => 32;
+use Test::More tests => 33;
 
 use Processlist;
 use PerconaTest;
@@ -600,6 +600,17 @@ my %find_spec = (
    },
 );
 
+my $matching_query =
+      {  'Time'    => '91',
+         'Command' => 'Query',
+         'db'      => undef,
+         'Id'      => '43',
+         'Info'    => 'select * from foo',
+         'User'    => 'msandbox',
+         'State'   => 'executing',
+         'Host'    => 'localhost'
+      };
+
 my @queries = $pl->find(
    [  {  'Time'    => '488',
          'Command' => 'Connect',
@@ -675,33 +686,24 @@ my @queries = $pl->find(
          'State'   => 'Locked',
          'Host'    => 'localhost'
       },
-      {  'Time'    => '91',
+      $matching_query,
-         'Command' => 'Query',
-         'db'      => undef,
-         'Id'      => '43',
-         'Info'    => 'select * from foo',
-         'User'    => 'msandbox',
-         'State'   => 'executing',
-         'Host'    => 'localhost'
-      },
    ],
    %find_spec,
 );
 
-my $expected = [
+my $expected = [ $matching_query ];
-      {  'Time'    => '91',
-         'Command' => 'Query',
-         'db'      => undef,
-         'Id'      => '43',
-         'Info'    => 'select * from foo',
-         'User'    => 'msandbox',
-         'State'   => 'executing',
-         'Host'    => 'localhost'
-      },
-   ];
 
 is_deeply(\@queries, $expected, 'Basic find()');
 
+{
+   # Internal, fragile test!
+   is_deeply(
+      $pl->{_reasons_for_matching}->{$matching_query},
+      [ 'Exceeds busy time', 'Query matches Command spec', 'Query matches Info spec', ],
+      "_reasons_for_matching works"
+   );
+}
+
 %find_spec = (
    busy_time    => 1,
    ignore => {

t/pt-kill/kill.t

@@ -29,7 +29,7 @@ if ( !$dbh ) {
    plan skip_all => 'Cannot connect to sandbox master';
 }
 else {
-   plan tests => 7;
+   plan tests => 20;
 }
 
 my $output;
@@ -56,8 +56,11 @@ ok(
 
 $output = output(
    sub { pt_kill::main('-F', $cnf, qw(--kill --print --run-time 1 --interval 1),
-      '--match-info', 'select sleep\(4\)') },
+            "--match-info", 'select sleep\(4\)',
+         )
+   },
 );
+
 like(
    $output,
    qr/KILL $pid /,
@@ -116,6 +119,133 @@ is(
    'Connection is still alive'
 );
 
+# #############################################################################
+# Test that --log-dsn
+# #############################################################################
+
+$dbh->do("DROP DATABASE IF EXISTS `kill_test`");
+$dbh->do("CREATE DATABASE `kill_test`");
+
+my $sql = OptionParser->read_para_after(
+   "$trunk/bin/pt-kill", qr/MAGIC_create_log_table/);
+$sql =~ s/kill_log/`kill_test`.`log_table`/;
+
+$dbh->do($sql);
+
+{
+   system("/tmp/12345/use -h127.1 -P12345 -umsandbox -pmsandbox -e 'select sleep(4)' >/dev/null&");
+   sleep 0.5;
+   local $@;
+   eval {
+      pt_kill::main('-F', $cnf, qw(--kill --run-time 1 --interval 1),
+         "--match-info", 'select sleep\(4\)',
+         "--log-dsn", q!h=127.1,P=12345,u=msandbox,p=msandbox,d=kill_test,t=log_table!,
+      )
+   };
+   ok !$@, "--log-dsn works if the table exists and --create-log-table wasn't passed in."
+      or diag $@;
+
+   local $@;
+   my $results = eval { $dbh->selectall_arrayref("SELECT * FROM `kill_test`.`log_table`") };
+   ok !$@, "...and we can query the table"
+      or diag $@;
+
+   is @{$results}, 1, "...which contains one entry";
+   use Data::Dumper;
+   my $reason = $dbh->selectrow_array("SELECT reason FROM `kill_test`.`log_table` WHERE kill_id=1");
+   is $reason,
+      'Query matches Info spec',
+      'reason gets set to something sensible';
+
+   TODO: {
+      local $::TODO = "Time_ms currently isn't reported";
+      my $time_ms = $dbh->selectrow_array("SELECT Time_ms FROM `kill_test`.`log_table` WHERE kill_id=1");
+      ok $time_ms;
+   }
+
+   my $result = shift @$results;
+   $result->[6] =~ s/localhost:[0-9]+/localhost/;
+   is_deeply(
+      [ @{$result}[5..8, 10, 11] ],
+      [ 'msandbox', 'localhost', undef, 'Query', 'User sleep', 'select sleep(4)', ],
+      "...and was populated as expected",
+   );
+   
+   system("/tmp/12345/use -h127.1 -P12345 -umsandbox -pmsandbox -e 'select sleep(4)' >/dev/null&");
+   sleep 0.5;
+   local $@;
+   eval {
+      pt_kill::main('-F', $cnf, qw(--kill --run-time 1 --interval 1 --create-log-table),
+         "--match-info", 'select sleep\(4\)',
+         "--log-dsn", q!h=127.1,P=12345,u=msandbox,p=msandbox,d=kill_test,t=log_table!,
+      )
+   };
+   ok !$@, "--log-dsn works if the table exists and --create-log-table was passed in.";
+}
+
+{
+   $dbh->do("DROP TABLE `kill_test`.`log_table`");
+
+   system("/tmp/12345/use -h127.1 -P12345 -umsandbox -pmsandbox -e 'select sleep(4)' >/dev/null&");
+   sleep 0.5;
+   local $@;
+   eval {
+      pt_kill::main('-F', $cnf, qw(--kill --run-time 1 --interval 1 --create-log-table),
+         "--match-info", 'select sleep\(4\)',
+         "--log-dsn", q!h=127.1,P=12345,u=msandbox,p=msandbox,d=kill_test,t=log_table!,
+      )
+   };
+   ok !$@, "--log-dsn works if the table doesn't exists and --create-log-table was passed in.";
+}
+
+{
+   $dbh->do("DROP TABLE `kill_test`.`log_table`");
+
+   local $@;
+   eval {
+      pt_kill::main('-F', $cnf, qw(--kill --run-time 1 --interval 1),
+         "--match-info", 'select sleep\(4\)',
+         "--log-dsn", q!h=127.1,P=12345,u=msandbox,p=msandbox,d=kill_test,t=log_table!,
+      )
+   };
+   like $@,
+      qr/\QTable 'kill_test.log_table' doesn't exist\E/,       #'
+      "By default, --log-dsn doesn't autogenerate a table";
+}
+
+for my $dsn (
+   q!h=127.1,P=12345,u=msandbox,p=msandbox,t=log_table!,
+   q!h=127.1,P=12345,u=msandbox,p=msandbox,d=kill_test!,
+   q!h=127.1,P=12345,u=msandbox,p=msandbox!,
+) {
+   local $@;
+   eval {
+      pt_kill::main('-F', $cnf, qw(--kill --run-time 1 --interval 1),
+         "--match-info", 'select sleep\(4\)',
+         "--log-dsn", $dsn,
+      )
+   };
+   like $@,
+      qr/\QThe DSN passed in for --log-dsn must have a database and table set\E/,
+      "--log-dsn croaks if t= or d= are absent";
+}
+
+# Run it twice
+for (1,2) {
+   system("/tmp/12345/use -h127.1 -P12345 -umsandbox -pmsandbox -e 'select sleep(4)' >/dev/null&");
+   sleep 0.5;
+   pt_kill::main('-F', $cnf, qw(--kill --run-time 1 --interval 1 --create-log-table),
+      "--match-info", 'select sleep\(4\)',
+      "--log-dsn", q!h=127.1,P=12345,u=msandbox,p=msandbox,d=kill_test,t=log_table!,
+   );
+}
+
+my $results = $dbh->selectall_arrayref("SELECT * FROM `kill_test`.`log_table`");
+
+is @{$results}, 2, "Different --log-dsn runs reuse the same table.";
+
+$dbh->do("DROP DATABASE kill_test");
+
 # #############################################################################
 # Done.
 # #############################################################################