From 26522d20fd6c5ec04f519b7524c44f1d6815a341 Mon Sep 17 00:00:00 2001 From: dm-2 <45519614+dm-2@users.noreply.github.com> Date: Tue, 27 Sep 2022 21:41:17 +0100 Subject: [PATCH] PT-2080 Add JSON logging to pt-kill (#543) * Add JSON output support to pt-kill Introduces new flags `--log-json` and `--log-json-fields` to control JSON output: - `--log-json`: when combined with `--print`, outputs kill information in JSON format instead of plain text, with the same fields as the `kill_log` table when using `--log-dsn` - `--log-json-fields`: when combined with `--log-json`, adds user-defined key-value pairs to the JSON document that is output (such as cluster name or hostname); parameter value is in the format of `key1:value1,key2:value2` * Convert --log-json to write to file, remove dependency on --print, update docs The `--log-json` parameter now takes a file path value, and writes JSON output to this file. The `--print` parameter is now independent and does not need to be specified to use `--log-json`. Docs updated for clarity. * Add chksm to JSON output, make JSON key names consistent - Adds chksm outout to JSON output to make it easier to group similar queries - Moves chksm code so that it is always executed, is accessible within the `log-json` scope, and isn't duplicated - Change JSON key names to consistently use uppercase letters at start of words, change `ts` to `Timestamp` * Update docs to match changed field names * Rename JSON parameter, output to STDOUT, fix tests, add test for --json, bug fix for --query-id - `--json` parameter must now be used in conjunction with `--print`; JSON output replaces normal `--print` output when `--json` is also specified - `--json` output is now sent to STDOUT instead of a specified file, as its new behaviour is to change the output format of `--print` instead of logging to a file - Renamed `--log-json` and `--log-json-fields` parameters to `--json` and `--json-fields` to better represent their new behaviour - Refactored checksum code to prevent test failures when `$query->{'Info'}` is empty - Added test for `--json` and `--json-fields` parameters - Fixed bug where specifying `--query-id` would cause errors when `$query->{'Info'}` is empty * Fix typo: Unkown -> Unknown --- bin/pt-kill | 114 +++++++++++++++++++++++++++++++++++++++++----- t/pt-kill/match.t | 12 ++++- 2 files changed, 113 insertions(+), 13 deletions(-) diff --git a/bin/pt-kill b/bin/pt-kill index 6cb6ce63..073c3c75 100755 --- a/bin/pt-kill +++ b/bin/pt-kill @@ -7373,21 +7373,50 @@ sub main { MATCHING_QUERY: foreach my $query ( @queries ) { + my $qinfo = ( $query->{Info} || 'NULL' ); + if( $o->get('fingerprint') && $qinfo ne 'NULL' ) { + $qinfo = $qr->fingerprint($query->{'Info'}); + } + my $chksm = ''; + if ( $qinfo ne 'NULL' ) { + my $fp = $qr->fingerprint($query->{'Info'}); + # $chksm is used by query-id and json + $chksm = Transformers::make_checksum($fp); + } if ( $o->get('print') ) { - my $qinfo = ($query->{Info} || 'NULL' ); - if( $o->get('fingerprint') && $qinfo ne 'NULL' ) { - $qinfo = $qr->fingerprint($query->{'Info'}); + if ( $o->get('json') ) { + my $reasons = join "\n", map { + defined($_) ? $_ : "Unknown reason" + } @{ $pl->{_reasons_for_matching}->{$query} }; + my %jsonOutput = ( + Timestamp => ts(time), + Reason => $reasons, + Kill_Error => $EVAL_ERROR, + Id => $query->{Id}, + User => $query->{User}, + Host => $query->{Host}, + Db => $query->{db}, + Command => $query->{Command}, + Time => $query->{Time}, + State => $query->{State}, + Info => $qinfo, + Digest => $chksm + ); + if ( $o->get('json-fields') ) { + my @logFieldKVs = split(",", $o->get('json-fields')); + my %logFields = map { split(":", $_) } @logFieldKVs; + %jsonOutput = (%jsonOutput, %logFields); + } + printf "%s\n", Transformers::hash_to_json(\%jsonOutput); + } else { + printf "# %s %s %d (%s %d sec) %s\n", + ts(time), $o->get('kill-query') ? 'KILL QUERY' : 'KILL', + $query->{Id}, ($query->{Command} || 'NULL'), $query->{Time}, + $qinfo; } - - printf "# %s %s %d (%s %d sec) %s\n", - ts(time), $o->get('kill-query') ? 'KILL QUERY' : 'KILL', - $query->{Id}, ($query->{Command} || 'NULL'), $query->{Time}, - $qinfo; } if ( $o->get('query-id') ) { - my $fp = $qr->fingerprint($query->{'Info'}); - my $chksm = Transformers::make_checksum($fp); - print "Query ID: 0x$chksm\n"; + print "Query ID: 0x$chksm\n"; } if ( $o->get('execute-command') ) { exec_cmd($o->get('execute-command')); @@ -7484,7 +7513,7 @@ sub log_to_table { my $ts = Transformers::ts(time()); my $reasons = join "\n", map { - defined($_) ? $_ : "Unkown reason" + defined($_) ? $_ : "Unknown reason" } @{ $pl->{_reasons_for_matching}->{$query} }; $log->( $ts, $reasons, $args{eval_error}, @@ -7869,6 +7898,67 @@ MAGIC_create_log_table: PRIMARY KEY (kill_id) ) DEFAULT CHARSET=utf8 +=item --json + +Prints killed queries as JSON, must be used with L<"--print">. For example: + + --print --json + +The usual plain-text output from L<"--print"> will not be displayed. + +JSON output will be in the format of: + + { + "Command": "Query", + "Host": "10.0.0.1:9999", + "Id": 1234, + "Info": "SELECT SLEEP(5)", + "State": "User sleep", + "Time": 10, + "User": "my_user", + "Db": "my_db", + "Kill_Error": "", + "Digest": "58A43A7DA83F58C1", + "Reason": "Exceeds busy time\nQuery matches Command spec", + "Timestamp": "2022-01-01T00:00:00" + } + +=item --json-fields + +type: string + +Specify a list of additional key:value pairs to include in JSON output when +using L<"--json">, the value of this parameter must be specified in the +format of: + + --json-fields key1:value1,key2:value2 + +Any fields specified using L<"--json-fields"> will be included in the +L<"--json"> output. + +For example: + + --print --json --json-fields hostname:$(hostname),tag:my_tag + +Will result in JSON records being written to "kill_log.json" using this format: + + { + "Command": "Query", + "Host": "10.0.0.1:9999", + "Id": 1234, + "Info": "SELECT SLEEP(5)", + "State": "User sleep", + "Time": 10, + "User": "my_user", + "Db": "my_db", + "Kill_Error": "", + "Digest": "58A43A7DA83F58C1", + "Reason": "Exceeds busy time\nQuery matches Command spec", + "Timestamp": "2022-01-01T00:00:00", + "hostname": "my_host", + "tag": "my_tag" + } + =item --password short form: -p; type: string diff --git a/t/pt-kill/match.t b/t/pt-kill/match.t index 47be0382..f41a4fcb 100644 --- a/t/pt-kill/match.t +++ b/t/pt-kill/match.t @@ -9,7 +9,7 @@ BEGIN { use strict; use warnings FATAL => 'all'; use English qw(-no_match_vars); -use Test::More tests => 16; +use Test::More tests => 17; use PerconaTest; use Sandbox; @@ -147,6 +147,16 @@ like( '--query-id' ); +# --json option +$output = output( + sub { pt_kill::main(@args, "$trunk/t/lib/samples/pl/recset011.txt", qw(--match-all --print --json --json-fields key:value)); } +); +like( + $output, + qr/\{"Command"\:"Query","Db"\:"db","Digest"\:"69962191E64980E6","Host"\:"127\.0\.0\.1\:3306","Id"\:"4","Info"\:"\\\/\* fruit\=orange \*\\\/ select 1 from fuits;","Kill_Error"\:"","Reason"\:"","State"\:"statistics","Time"\:"6","Timestamp"\:".*","User"\:"foo","key"\:"value"\}/, + '--json' +); + # ############################################################################# # Live tests. # #############################################################################