Add and fix test case for special 'no query' events.

lib/SlowLogParser.pm

@@ -235,8 +235,28 @@ sub parse_event {
             # this only if we've seen the user/host line.
             if ( !$found_arg && $pos == $len ) {
                PTDEBUG && _d("Did not find arg, looking for special cases");
-               local $INPUT_RECORD_SEPARATOR = ";\n";
+               local $INPUT_RECORD_SEPARATOR = ";\n";  # get next line
                if ( defined(my $l = $next_event->()) ) {
+                  if ( $l =~ /^\s*[A-Z][a-z_]+: / ) {
+                     PTDEBUG && _d("Found NULL query before", $l);
+                     # https://bugs.launchpad.net/percona-toolkit/+bug/1082599
+                     # This is really pathological but it happens:
+                     #   header_for_query_1
+                     #   SET timestamp=123;
+                     #   use db;
+                     #   header_for_query_2
+                     # In this case, "get next line" ^ will actually fetch
+                     # header_for_query_2 and the first line of any arg data,
+                     # so to get the rest of the arg data, we switch back to
+                     # the default input rec. sep.
+                     local $INPUT_RECORD_SEPARATOR = ";\n#";
+                     my $rest_of_event = $next_event->();
+                     push @{$self->{pending}}, $l . $rest_of_event;
+                     push @properties, 'cmd', 'Query', 'arg', '/* No query */';
+                     push @properties, 'bytes', 0;
+                     $found_arg++;
+                  }
+                  else {
                      chomp $l;
                      $l =~ s/^\s+//;
                      PTDEBUG && _d("Found admin statement", $l);
@@ -244,6 +264,7 @@ sub parse_event {
                      push @properties, 'bytes', length($properties[-1]);
                      $found_arg++;
                   }
+               }
                else {
                   # Unrecoverable -- who knows what happened.  This is possible,
                   # for example, if someone does something like "head -c 10000

t/lib/SlowLogParser.t

@@ -9,8 +9,8 @@ BEGIN {
 use strict;
 use warnings FATAL => 'all';
 use English qw(-no_match_vars);
-use Test::More tests => 48;
 
+use Test::More;
 use SlowLogParser;
 use PerconaTest;
 
@@ -1296,6 +1296,59 @@ test_log_parser(
    ],
 );
 
+# #############################################################################
+# pt-query-digest fails to parse timestamp with no query
+# https://bugs.launchpad.net/percona-toolkit/+bug/1082599
+# #############################################################################
+test_log_parser(
+   parser => $p,
+   file   => "$sample/slow056.txt",
+   result => [
+      {  Lock_time     => '0.000000',
+         Query_time    => '0.000102',
+         Rows_read     => '0',
+         Rows_affected => '0',
+         Rows_examined => '0',
+         Rows_sent     => '0',
+         arg           => '/* No query */',
+         bytes         => '0',
+         cmd           => 'Query',
+         pos_in_log    => '0',
+         ts            => '121123 19:56:06',
+         Thread_id     => '558038',
+         Last_errno    => 0,
+         Killed        => 0,
+         db            => 'test_db',
+         host          => '',
+         Schema        => 'test_db',
+         ip            => '127.0.0.1',
+         timestamp     => '1111111111',
+         user          => 'root',
+      },
+      {
+         ts             => '121123 19:56:06',
+         Killed         => '0',
+         Last_errno     => '0',
+         Lock_time      => '0.000197',
+         Query_time     => '0.002515',
+         Rows_affected  => '1',
+         Rows_examined  => '1',
+         Rows_read      => '0',
+         Rows_sent      => '0',
+         Schema         => 'test_db',
+         Thread_id      => '558032',
+         arg            => 'update t set b = b + 30 where user_id=1',
+         bytes          => 39,
+         cmd            => 'Query',
+         host           => '',
+         ip             => '127.0.0.1',
+         pos_in_log     => 596,
+         timestamp      => '2222222222',
+         user           => 'root',
+      },
+   ],
+);
+
 # #############################################################################
 # Done.
 # #############################################################################
@@ -1310,4 +1363,4 @@ like(
    qr/Complete test coverage/,
    '_d() works'
 );
-exit;
+done_testing;

t/lib/samples/slowlogs/slow056.txt

@@ -0,0 +1,12 @@
+# Time: 121123 19:56:06.0000001967
+# User@Host: root[root] @  [127.0.0.1]
+# Thread_id: 558038  Schema: test_db  Last_errno: 0  Killed: 0
+# Query_time: 0.000102  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0  Rows_affected: 0  Rows_read: 0
+SET timestamp=1111111111;
+use test_db;
+# Time: 121123 19:56:06.0000002134
+# User@Host: root[root] @  [127.0.0.1]
+# Thread_id: 558032  Schema: test_db  Last_errno: 0  Killed: 0
+# Query_time: 0.002515  Lock_time: 0.000197  Rows_sent: 0  Rows_examined: 1  Rows_affected: 1  Rows_read: 0
+SET timestamp=2222222222;
+update t set b = b + 30 where user_id=1;