Merge lp:~percona-toolkit-dev/percona-toolkit/fix-1082104-pt-deadlock-logger-username-dash into lp:percona-toolkit/2.1

[Brian Fraser]

[Daniel Nichter (daniel-nichter)]

Why not just $w = qr/([\w-]+)/ ?

[Brian Fraser (fraserbn)]

That would leave pt-deadlock-logger still broken for a bunch of valid usernames, ala イウサネイム, or some—user (em dash, not hyphen-minus), or a bunch of stuff you can imagine. `&%$!!%·` is totally valid, and the kind of thing someone mischievous might use to deadlock a server. The \S version is pretty broad, but I think only broken for usernames with whitespace in them.

[Daniel Nichter (daniel-nichter)]

Need to bzr add t/pt-deadlock-logger/samples/bug_1082104.txt

[Daniel Nichter (daniel-nichter)]

Why the (?!pat) in qr/((?!\b[0-9]+\b)\S+)/? Is there a case where the next thing might be numbers, so the negative look-ahead prevents matching that?

[Brian Fraser (fraserbn)]

I don't really know -- I can't find docs for the deadlock output anywhere -- but usernames can never be all numbers, so should there be numbers somewhere in that line, pt-dl won't get confused.

[Daniel Nichter (daniel-nichter)]

I think the extra check for number isn't needed. Right now we're doing:

 m/$ip $u(?: (.*))?$/;

So the user patter is already anchored on the IP, and the IP won't change. So all we need is the next item after that IP. I think \S+ is fine and we'll probably never support `user name` because MySQL would have to quote that but, like you noted, InnoDB output does whatever it wants, and it doesn't seem to quote stuff, so we'd never be able to know that user name is actually `user name`. Thus we can just document this limitation: user names with spaces will not be logged properly; only the first "word" in the username will be logged.

[lp:~percona-toolkit-dev/percona-toolkit/fix-1082104-pt-deadlock-logger-username-dash]

468. By Brian Fraser on 2012-12-12

Added t/pt-deadlock-logger/samples/bug_1082104.txt & changed the username regex per Daniel's comments

[Brian Fraser (fraserbn)]

Alright, sounds good. I changed the regex & added some lines in the limitations. Also added the missing logfile.

[Brian Fraser (fraserbn)]

review: Approve

[Daniel Nichter (daniel-nichter)]

review: Approve

=== modified file 'bin/pt-deadlock-logger'
--- bin/pt-deadlock-logger	2012-12-03 03:48:11 +0000
+++ bin/pt-deadlock-logger	2012-12-12 05:45:24 +0000
@@ -3757,7 +3757,8 @@
 my $t  = qr/((?:\d+ \d+)|(?:[A-Fa-f0-9]+))/;                # Transaction ID
 my $i = qr/((?:\d{1,3}\.){3}\d+)/;    # IP address
 my $n = qr/([^`\s]+)/;                # MySQL object name
-my $w = qr/(\w+)/;                    # Words
+my $u = qr/(\S+)/;                    # Username. This is somewhat wrong, but
+                                      # usernames with spaces are rare enough.
 my $s = qr/(\d{6} .\d:\d\d:\d\d)/;    # InnoDB timestamp
 
 # A thread's proc_info can be at least 98 different things I've found in the
@@ -4082,7 +4083,7 @@
                # the most useful marker for where I have to start guessing.
                ( $hostname, $ip ) = $thread_line =~ m/query id \d+(?: ([A-Za-z]\S+))? $i/m;
                if ( defined $ip ) {
-                  ($user, $query_status) = $thread_line =~ m/$ip $w(?: (.*))?$/;
+                  ($user, $query_status) = $thread_line =~ m/$ip $u(?: (.*))?$/;
                }
                else {
                   # OK, there wasn't an IP address.
@@ -4094,7 +4095,7 @@
                      # query_status.
                      # It's basically impossible to know which is which.
                      ( $hostname, $user, $query_status ) = $thread_line
-                        =~ m/query id \d+(?: ([A-Za-z]\S+))?(?: $w(?: (.*))?)?$/m;
+                        =~ m/query id \d+(?: ([A-Za-z]\S+))?(?: $u(?: (.*))?)?$/m;
                   }
                   else {
                      $user = 'system user';
@@ -4387,6 +4388,10 @@
 both wait-for locks and get more information.  If the two waited-for locks are
 not on the same table, more than two transactions were involved in the deadlock.
 
+Finally, keep in mind that, because usernames with spaces are not quoted by
+InnoDB, the tool will generally misreport the second word of these usernames
+as the hostname.
+
 =head1 OPTIONS
 
 This tool accepts additional command-line arguments.  Refer to the

=== modified file 't/pt-deadlock-logger/bugs.t'
--- t/pt-deadlock-logger/bugs.t	2012-06-03 18:47:00 +0000
+++ t/pt-deadlock-logger/bugs.t	2012-12-12 05:45:24 +0000
@@ -9,7 +9,7 @@
 use strict;
 use warnings FATAL => 'all';
 use English qw(-no_match_vars);
-use Test::More tests => 1;
+use Test::More;
 
 use PerconaTest;
 use Sandbox;
@@ -68,6 +68,59 @@
 );
 
 # #############################################################################
+# https://bugs.launchpad.net/percona-toolkit/+bug/1082104
+# pt-deadlock-logger problem when the user have a dash in the name
+# #############################################################################
+
+$innodb_status_sample = load_file("t/pt-deadlock-logger/samples/bug_1082104.txt");
+
+is_deeply(
+   pt_deadlock_logger::parse_deadlocks($innodb_status_sample),
+   {
+      '1' => {
+          db => 'test',
+          hostname => 'localhost',
+          id => 1,
+          idx => 'PRIMARY',
+          ip => '',
+          lock_mode => 'X',
+          lock_type => 'RECORD',
+          query => 'update a set movie_id=96 where id =2',
+          server => '',
+          tbl => 'a',
+          thread => '19',
+          ts => '2011-12-12T22:52:42',
+          txn_id => 0,
+          txn_time => '161',
+          user => 'ro-ot',
+          victim => 0,
+          wait_hold => 'w'
+      },
+      '2' => {
+          db => 'test',
+          hostname => 'localhost',
+          id => 2,
+          idx => 'PRIMARY',
+          ip => '',
+          lock_mode => 'X',
+          lock_type => 'RECORD',
+          query => 'update a set movie_id=98 where id =4',
+          server => '',
+          tbl => 'a',
+          thread => '18',
+          ts => '2011-12-12T22:52:42',
+          txn_id => 0,
+          txn_time => '1026',
+          user => 'ro-ot',
+          victim => 1,
+          wait_hold => 'w'
+      }
+   },
+   "Bug 1082104: pt-deadlock-logger shows host as user when the username has a dash in the name",
+);
+
+# #############################################################################
 # Done.
 # #############################################################################
+done_testing;
 exit;

=== added file 't/pt-deadlock-logger/samples/bug_1082104.txt'
--- t/pt-deadlock-logger/samples/bug_1082104.txt	1970-01-01 00:00:00 +0000
+++ t/pt-deadlock-logger/samples/bug_1082104.txt	2012-12-12 05:45:24 +0000
@@ -0,0 +1,53 @@
+=====================================
+070915 15:34:37 INNODB MONITOR OUTPUT
+=====================================
+Per second averages calculated from the last 24 seconds
+------------------------
+LATEST DETECTED DEADLOCK
+------------------------
[phone]:52:42
+*** (1) TRANSACTION:
+TRANSACTION 3405, ACTIVE 161 sec starting index read
+mysql tables in use 1, locked 1
+LOCK WAIT 3 lock struct(s), heap size 376, 3 row lock(s), undo log entries 2
+MySQL thread id 19, OS thread handle 0x7fac301e4700, query id 180 localhost ro-ot Updating
+update a set movie_id=96 where id =2
+*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
+RECORD LOCKS space id 0 page no 307 n bits 72 index `PRIMARY` of table `test`.`a` trx id 3405 lock_mode X locks rec but not gap waiting
+Record lock, heap no 3 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
+ 0: len 4; hex 80000002; asc ;;
+ 1: len 6; hex 000000003404; asc 4 ;;
+ 2: len 7; hex 040000163b2515; asc ;% ;;
+ 3: len 4; hex 80000063; asc c;;
+ 4: len 1; hex 01; asc ;;
+ 5: len 8; hex 8000124a7c1acb8c; asc J| ;;
+
+*** (2) TRANSACTION:
+TRANSACTION 3404, ACTIVE 1026 sec starting index read
+mysql tables in use 1, locked 1
+3 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
+MySQL thread id 18, OS thread handle 0x7fac30225700, query id 181 localhost ro-ot Updating
+update a set movie_id=98 where id =4
+*** (2) HOLDS THE LOCK(S):
+RECORD LOCKS space id 0 page no 307 n bits 72 index `PRIMARY` of table `test`.`a` trx id 3404 lock_mode X locks rec but not gap
+Record lock, heap no 3 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
+ 0: len 4; hex 80000002; asc ;;
+ 1: len 6; hex 000000003404; asc 4 ;;
+ 2: len 7; hex 040000163b2515; asc ;% ;;
+ 3: len 4; hex 80000063; asc c;;
+ 4: len 1; hex 01; asc ;;
+ 5: len 8; hex 8000124a7c1acb8c; asc J| ;;
+
+*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
+RECORD LOCKS space id 0 page no 307 n bits 72 index `PRIMARY` of table `test`.`a` trx id 3404 lock_mode X locks rec but not gap waiting
+Record lock, heap no 5 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
+ 0: len 4; hex 80000004; asc ;;
+ 1: len 6; hex 000000003405; asc 4 ;;
+ 2: len 7; hex 0500000e7017e8; asc p ;;
+ 3: len 4; hex 80000062; asc b;;
+ 4: len 1; hex 01; asc ;;
+ 5: len 8; hex 8000124a7c1acbb6; asc J| ;;
+
+*** WE ROLL BACK TRANSACTION (2)
+END OF INNODB MONITOR OUTPUT
+============================