percona/percona-toolkit
1
0
Fork 0
mirror of https://github.com/percona/percona-toolkit.git synced 2025-09-10 21:19:59 +00:00
Code Issues Packages Projects Releases Wiki Activity
Files
f517675eb49c5f45b5115ebc2352e5a2bd720e32
percona-toolkit/t/lib/PgLogParser.t

605 lines
23 KiB
Perl
Raw Blame History

#!/usr/bin/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 tests => 41;
use PgLogParser;
use SysLogParser;
use PerconaTest;
my $p = new PgLogParser;
# Run some tests of duration_to_secs().
my @duration_tests = (
['10.870 ms' => '0.01087'],
['0.084312 sec' => '0.084312'],
);
foreach my $test ( @duration_tests ) {
is (
$p->duration_to_secs($test->[0]),
$test->[1],
"Duration for $test->[0] == $test->[1]");
}
# duration_to_secs() should not accept garbage at the end of its argument.
throws_ok (
sub {
$p->duration_to_secs('duration: 1.565 ms statement: SELECT 1');
},
qr/Unknown suffix/,
'duration_to_secs does not like crap at the end',
);
# Tests of 'pending'.
is($p->pending, undef, 'Nothing in pending');
is_deeply([$p->pending('foo', 1)], ['foo', 1, undef], 'Store foo in pending');
is_deeply([$p->pending], ['foo', 1, 1], 'Get foo from pending');
is($p->pending, undef, 'Nothing in pending');
# Tests of 'get_meta'
my @meta = (
['c=4b7074b4.985,u=fred,D=jim', {
Session_id => '4b7074b4.985',
user => 'fred',
db => 'jim',
}],
['c=4b7074b4.985, user=fred, db=jim', {
Session_id => '4b7074b4.985',
user => 'fred',
db => 'jim',
}],
['c=4b7074b4.985 user=fred db=jim', {
Session_id => '4b7074b4.985',
user => 'fred',
db => 'jim',
}],
);
foreach my $meta ( @meta ) {
is_deeply({$p->get_meta($meta->[0])}, $meta->[1], "Meta for $meta->[0]");
}
# A simple log of a session.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-log-001.txt',
result => [
{ ts => '2010-02-08 15:31:48.685',
host => '[local]',
db => '[unknown]',
user => '[unknown]',
arg => 'connection received',
Session_id => '4b7074b4.985',
pos_in_log => 0,
bytes => 19,
cmd => 'Admin',
},
{ ts => '2010-02-08 15:31:48.687',
user => 'fred',
db => 'fred',
arg => 'connection authorized',
Session_id => '4b7074b4.985',
pos_in_log => 107,
bytes => 21,
cmd => 'Admin',
},
{ ts => '2010-02-08 15:31:50.872',
db => 'fred',
user => 'fred',
arg => 'select 1;',
Query_time => '0.01087',
Session_id => '4b7074b4.985',
pos_in_log => 217,
bytes => length('select 1;'),
cmd => 'Query',
},
{ ts => '2010-02-08 15:31:58.515',
db => 'fred',
user => 'fred',
arg => "select\n1;",
Query_time => '0.013918',
Session_id => '4b7074b4.985',
pos_in_log => 384,
bytes => length("select\n1;"),
cmd => 'Query',
},
{ ts => '2010-02-08 15:32:06.988',
db => 'fred',
user => 'fred',
host => '[local]',
arg => 'disconnection',
Session_id => '4b7074b4.985',
pos_in_log => 552,
bytes => length('disconnection'),
cmd => 'Admin',
},
],
);
# A log that has no fancy line-prefix with user/db/session info. It also begins
# with an entry whose header is missing. And it ends with a line that has no
# 'duration' line afterwards.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-log-002.txt',
result => [
{ ts => '2004-05-07 11:58:22',
arg => "SELECT groups.group_name,groups.unix_group_name,\n"
. "\tgroups.type_id,users.user_name,users.realname,\n"
. "\tnews_bytes.forum_id,news_bytes.summary,news_bytes.post_date,news_bytes.details \n"
. "\tFROM users,news_bytes,groups \n"
. "\tWHERE news_bytes.group_id='98' AND news_bytes.is_approved <> '4' \n"
. "\tAND users.user_id=news_bytes.submitted_by \n"
. "\tAND news_bytes.group_id=groups.group_id \n"
. "\tORDER BY post_date DESC LIMIT 10 OFFSET 0",
pos_in_log => 147,
bytes => 404,
cmd => 'Query',
Query_time => '0.00268',
},
{ ts => '2004-05-07 11:58:36',
arg => 'begin; select getdatabaseencoding(); commit',
cmd => 'Query',
pos_in_log => 641,
bytes => 43,
},
],
);
# A log that has no line-prefix at all. It also has durations and statements on
# the same line.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-log-003.txt',
result => [
{ arg => "SELECT * FROM users WHERE user_id='692'",
pos_in_log => 0,
bytes => 39,
cmd => 'Query',
Query_time => '0.001565',
},
{ arg => "SELECT groups.group_name,groups.unix_group_name,\n"
. "\t\tgroups.type_id,users.user_name,users.realname,\n"
. "\t\tnews_bytes.forum_id,news_bytes.summary,news_bytes.post_date,news_bytes.details \n"
. "\t\tFROM users,news_bytes,groups \n"
. "\t\tWHERE news_bytes.is_approved=1 \n"
. "\t\tAND users.user_id=news_bytes.submitted_by \n"
. "\t\tAND news_bytes.group_id=groups.group_id \n"
. "\t\tORDER BY post_date DESC LIMIT 5 OFFSET 0",
cmd => 'Query',
pos_in_log => 77,
bytes => 376,
Query_time => '0.00164',
},
{ arg => "SELECT total FROM forum_group_list_vw WHERE group_forum_id='4606'",
pos_in_log => 498,
bytes => 65,
cmd => 'Query',
Query_time => '0.000529',
},
],
);
# A simple log of a session.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-log-004.txt',
result => [
{ ts => '2010-02-10 08:39:56.835',
host => '[local]',
db => '[unknown]',
user => '[unknown]',
arg => 'connection received',
Session_id => '4b72b72c.b44',
pos_in_log => 0,
bytes => 19,
cmd => 'Admin',
},
{ ts => '2010-02-10 08:39:56.838',
user => 'fred',
db => 'fred',
arg => 'connection authorized',
Session_id => '4b72b72c.b44',
pos_in_log => 107,
bytes => 21,
cmd => 'Admin',
},
{ ts => '2010-02-10 08:40:34.681',
db => 'fred',
user => 'fred',
arg => 'select 1;',
Query_time => '0.001308',
Session_id => '4b72b72c.b44',
pos_in_log => 217,
bytes => length('select 1;'),
cmd => 'Query',
},
{ ts => '2010-02-10 08:44:31.368',
db => 'fred',
user => 'fred',
host => '[local]',
arg => 'disconnection',
Session_id => '4b72b72c.b44',
pos_in_log => 321,
bytes => length('disconnection'),
cmd => 'Admin',
},
],
);
# A log that shows that continuation lines don't have to start with a TAB, and
# not all queries must be followed by a duration.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-log-005.txt',
result => [
{ ts => '2004-05-07 12:00:01',
arg => 'begin; select getdatabaseencoding(); commit',
pos_in_log => 0,
bytes => 43,
cmd => 'Query',
Query_time => '0.000801',
},
{ ts => '2004-05-07 12:00:01',
arg => "update users set unix_status = 'A' where user_id in (select\n"
. "distinct u.user_id from users u, user_group ug WHERE\n"
. "u.user_id=ug.user_id and ug.cvs_flags='1' and u.status='A')",
pos_in_log => 126,
bytes => 172,
cmd => 'Query',
},
{ ts => '2004-05-07 12:00:01',
arg => 'SELECT 1 FROM ONLY "public"."supported_languages" x '
. 'WHERE "language_id" = $1 FOR UPDATE OF x',
pos_in_log => 332,
bytes => 92,
cmd => 'Query',
},
],
);
# A log with an error.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-log-006.txt',
result => [
{ ts => '2004-05-07 12:01:06',
arg => 'SELECT plugin_id, plugin_name FROM plugins',
pos_in_log => 0,
bytes => 42,
cmd => 'Query',
Query_time => '0.002161',
},
{ ts => '2004-05-07 12:01:06',
arg => "SELECT \n\t\t\t\tgroups.type,\n"
. "\t\t\t\tnews_bytes.details \n"
. "\t\t\tFROM \n"
. "\t\t\t\tnews_bytes,\n"
. "\t\t\t\tgroups \n"
. "\t\t\tWHERE \n"
. "\t\t\t\tnews_bytes.group_id=groups.group_id \n"
. "\t\t\tORDER BY \n"
. "\t\t\t\tdate \n"
. "\t\t\tDESC LIMIT 30 OFFSET 0",
pos_in_log => 125,
bytes => 185,
cmd => 'Query',
Error_msg => 'No such attribute groups.type',
},
{ ts => '2004-05-07 12:01:06',
arg => 'SELECT plugin_id, plugin_name FROM plugins',
pos_in_log => 412,
bytes => 42,
cmd => 'Query',
Query_time => '0.002161',
},
],
);
# A log with informational messages.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-log-007.txt',
result => [
{ arg => 'SELECT plugin_id, plugin_name FROM plugins',
pos_in_log => 20,
bytes => 42,
cmd => 'Query',
Query_time => '0.002991',
},
],
);
# Test that meta-data in connection/disconnnection lines is captured.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-log-008.txt',
result => [
{ ts => '2010-02-08 15:31:48',
host => '[local]',
arg => 'connection received',
pos_in_log => 0,
bytes => 19,
cmd => 'Admin',
},
{ ts => '2010-02-08 15:31:48',
user => 'fred',
db => 'fred',
arg => 'connection authorized',
pos_in_log => 64,
bytes => 21,
cmd => 'Admin',
},
{ ts => '2010-02-08 15:32:06',
db => 'fred',
user => 'fred',
host => '[local]',
arg => 'disconnection',
pos_in_log => 141,
bytes => length('disconnection'),
cmd => 'Admin',
},
],
);
# Simple sample of syslog output. It has a complexity: there is a trailing
# orphaned duration line, which can appear to be for the statement -- but isn't.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-syslog-001.txt',
result => [
{ pos_in_log => 0,
bytes => 1193,
cmd => 'Query',
Query_time => '3.617465',
arg => "select t.tid,t.title,m.name,gn.name,to_char( t.retail_reldate, 'mm-dd-yy' ) as retail_reldate,coalesce(s0c100r0.units,0) as"
." w0c100r0units,'NA' as w0c100r0dollars,'NA' as w0c100r0arp,coalesce(s0c1r0.units,0) as w0c1r0units,'NA' as w0c1r0dollars,'NA' as"
." w0c1r0arp,coalesce(s0c2r0.units,0) as w0c2r0units,coalesce(s0c2r0.dollars,0) as w0c2r0dollars,arp(s0c2r0.dollars, s0c2r0.units)"
." as w0c2r0arp from title t left outer join sublabel sl on t.sublabel_rel = sl.key left outer join label s on sl.lid = s.id left"
." outer join label d on s.did = d.id left outer join sale_200601 s0c100r0 on t.tid = s0c100r0.tid and s0c100r0.week = 200601 and"
." s0c100r0.channel = 100 and s0c100r0.region = 0 left outer join sale_200601 s0c1r0 on t.tid = s0c1r0.tid and s0c1r0.week ="
." 200601 and s0c1r0.channel = 1 and s0c1r0.region = 0 left outer join sale_200601 s0c2r0 on t.tid = s0c2r0.tid and s0c2r0.week ="
." 200601 and s0c2r0.channel = 2 and s0c2r0.region = 0 left outer join media m on t.media = m.key left outer join genre_n gn on"
." t.genre_n = gn.key where ((((upper(t.title) like '%MATRIX%' or upper(t.artist) like '%MATRIX%') ))) and t.blob in ('L', 'M',"
." 'R') and t.source_dvd != 'IN' order by t.title asc limit 100",
},
],
);
# Syslog output with a query that has an error.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-syslog-002.txt',
result => [
{ ts => '2010-02-08 09:52:41.526',
pos_in_log => 0,
bytes => 31,
cmd => 'Query',
Query_time => '0.008309',
arg => "select * from pg_stat_bgwriter;",
db => 'fred',
user => 'fred',
Session_id => '4b701056.1dc6',
},
{ ts => '2010-02-08 09:52:57.807',
pos_in_log => 282,
bytes => 29,
cmd => 'Query',
arg => "create index ix_a on foo (a);",
Error_msg => 'relation "ix_a" already exists',
db => 'fred',
user => 'fred',
Session_id => '4b701056.1dc6',
},
],
);
# Syslog output with a query that has newlines *and* a query line that's too
# long and is broken across 2 lines in the log.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-syslog-003.txt',
result => [
{ ts => '2010-02-08 09:53:51.724',
pos_in_log => 0,
bytes => 526,
cmd => 'Query',
Query_time => '0.150472',
arg => "SELECT n.nspname as \"Schema\","
. "\n c.relname as \"Name\","
. "\n CASE c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 'i' THEN 'index' WHEN 'S' THEN 'sequence' WHEN 's' THEN"
. " 'special' END as \"Type\","
. "\n r.rolname as \"Owner\""
. "\nFROM pg_catalog.pg_class c"
. "\n JOIN pg_catalog.pg_roles r ON r.oid = c.relowner"
. "\n LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace"
. "\nWHERE c.relkind IN ('r','v','S','')"
. "\n AND n.nspname <> 'pg_catalog'"
. "\n AND n.nspname !~ '^pg_toast'"
. "\n AND pg_catalog.pg_table_is_visible(c.oid)"
. "\nORDER BY 1,2;",
db => 'fred',
user => 'fred',
Session_id => '4b701056.1dc6',
},
],
);
# Syslog output with a query that has newlines with tabs translated to ^I
# characters.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-syslog-004.txt',
result => [
{ pos_in_log => 0,
bytes => 357,
cmd => 'Query',
arg => "SELECT groups.group_name,groups.unix_group_name,"
. "\n\tgroups.type,users.user_name,users.realname,"
. "\n\tnews_bytes.forum_id,news_bytes.summary,news_bytes.date,news_bytes.details "
. "\n\tFROM users,news_bytes,groups "
. "\n\tWHERE news_bytes.is_approved=1 "
. "\n\tAND users.user_id=news_bytes.submitted_by "
. "\n\tAND news_bytes.group_id=groups.group_id "
. "\n\tORDER BY date DESC LIMIT 10 OFFSET 0",
},
],
);
# This is basically the same as t/lib/samples/pg/pg-log-001.txt but it's in
# syslog format. It's interesting and complicated because the disconnect
# message is broken across two lines in the file by syslog, although this would
# not be done in PostgreSQL's own logging format.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-syslog-005.txt',
result => [
{ ts => '2010-02-10 09:03:26.918',
host => '[local]',
db => '[unknown]',
user => '[unknown]',
arg => 'connection received',
Session_id => '4b72bcae.d01',
pos_in_log => 0,
bytes => 19,
cmd => 'Admin',
},
{ ts => '2010-02-10 09:03:26.922',
user => 'fred',
db => 'fred',
arg => 'connection authorized',
Session_id => '4b72bcae.d01',
pos_in_log => 152,
bytes => 21,
cmd => 'Admin',
},
{ ts => '2010-02-10 09:03:36.645',
db => 'fred',
user => 'fred',
arg => 'select 1;',
Query_time => '0.000627',
Session_id => '4b72bcae.d01',
pos_in_log => 307,
bytes => length('select 1;'),
cmd => 'Query',
},
{ ts => '2010-02-10 09:03:39.075',
db => 'fred',
user => 'fred',
host => '[local]',
arg => 'disconnection',
Session_id => '4b72bcae.d01',
pos_in_log => 456,
bytes => length('disconnection'),
cmd => 'Admin',
},
],
);
# This is interesting because it has a mix of lines that are genuinely broken
# with a newline, and thus start with ^I; and lines that are broken by syslog
# for being too long. It has a line that's just too long and is broken in a
# place there's no space, which is unusual. It also starts and ends with a
# newline, so it's a good test of whether chomping/trimming is done right.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-syslog-006.txt',
result => [
{ pos_in_log => 0,
bytes => 657,
cmd => 'Query',
Query_time => '0.117042',
arg => "\ninsert into weblog"
. " (username,remoteid,generalsitearea,refererhost,refererfull,searchterms,cookie,useragent,query,requesteduri,bot,elapsedtime)"
. "\nvalues"
. " (upper('asdfg'),upper('127.0.0.1'),upper(NULL),upper('localhost'),upper('<a href=\"http://localhost/nosymbol-Ameriprise-Financial-Inc-Fun\" target=\"_new\">http://localhost/nosymbol-Ameriprise-Financial-Inc-Fun</a>"
. "d-Buy-Sell-Own-zz-zi125340.html'),upper(NULL),upper('temp-id=s2ByrI6TKLEoDJXG3g3NEBoRWF6Z3t'),upper('Mozilla/4.0 (compatible;"
. " MSIE 7.0; Windows NT 5.2; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR"
. " 3.0.04506.30)'),upper(''),upper('/AAON-Aaon-Inc-Stock-Buy-Sell-Own-zz-zs2331501.html'),'f','1')"
. "\n"
},
],
);
# This file has a few different things in it: embedded newline in a string, long
# non-broken strings, ERROR line that doesn't describe the previous line but
# rather is followed by a STATEMENT line.
test_log_parser(
parser => $p,
file => 't/lib/samples/pg/pg-syslog-007.txt',
result => [
{ Query_time => '0.039219',
Session_id => '12345',
arg =>
"select 'a very long sentence a very long sentence a very long "
. "sentence a very long sentence a very long sentence a very "
. "long sentence a very long sentence ;\n';",
bytes => 159,
cmd => 'Query',
db => 'fred',
pos_in_log => 0,
ts => '2010-02-12 06:00:54.566',
user => 'fred'
},
{ Query_time => '0.000589',
Session_id => '12345',
arg =>
"select 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
. "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
. "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
. "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"
. "aaaaaaaaaaaaaaaaaaaaaaaa';",
bytes => 280,
cmd => 'Query',
db => 'fred',
pos_in_log => '388',
ts => '2010-02-12 06:01:09.854',
user => 'fred',
},
{
Query_time => '0.000556',
Session_id => '12345',
arg => "select '\nhello';",
bytes => 16,
cmd => 'Query',
db => 'fred',
pos_in_log => '939',
ts => '2010-02-12 06:01:22.860',
user => 'fred'
},
{ Error_msg => 'unrecognized configuration parameter "foobar"',
Session_id => '12345',
arg => "show foobar;",
bytes => length('show foobar;'),
cmd => 'Query',
db => 'fred',
pos_in_log => '1139',
ts => '2010-02-12 06:03:14.307',
user => 'fred',
},
],
);
# #############################################################################
# Done.
# #############################################################################
my $output = '';
{
local *STDERR;
open STDERR, '>', \$output;
$p->_d('Complete test coverage');
}
like(
$output,
qr/Complete test coverage/,
'_d() works'
);
exit;
Reference in New Issue View Git Blame Copy Permalink