From: Gilles Darold <gilles@darold.net>
Date: Sat, 8 Dec 2018 13:05:05 +0000 (+0100)
Subject: Fix pgbouncer parsing and request throughput reports. Thanks to Levente Birta for... 
X-Git-Tag: v10.2~12
X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=75b7e72d59a212e57a2c965a96694820ff9b0514;p=pgbadger

Fix pgbouncer parsing and request throughput reports. Thanks to Levente Birta for the report.
---

diff --git a/pgbadger b/pgbadger
index ddb5632..f58b89b 100755
--- a/pgbadger
+++ b/pgbadger
@@ -1988,34 +1988,30 @@ sub set_parser_regex
 	@prefix_q_params = ();
 
 	if ($fmt eq 'pgbouncer') {
-
 		$pgbouncer_log_format = qr/^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2})\.\d+(?: [A-Z\+\-\d]{3,6})? (\d+) ([^\s]+) (.\-0x[0-9a-f\.]*): ([0-9a-zA-Z\_\[\]\-\.]*)\/([0-9a-zA-Z\_\[\]\-\.]*)\@([a-zA-Z0-9\-\.]+|\[local\]|\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}|[0-9a-fA-F:]+)(?:\(\d+\))??[:\d]* (.*)/;
 		@pgb_prefix_params = ('t_timestamp', 't_pid', 't_loglevel', 't_session_id', 't_dbname', 't_dbuser', 't_client', 't_query');
-
-		$pgbouncer_log_parse1 = qr/^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2})\.\d+(?: [A-Z\+\-\d]{3,6})? (\d+) ([^\s]+) (.*)/;
-		@pgb_prefix_parse1 = ('t_timestamp', 't_pid', 't_loglevel', 't_query');
+		$pgbouncer_log_parse1 = qr/^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2})\.\d+(?: [A-Z\+\-\d]{3,6})? (\d+) ([^\s]+) (.\-0x[0-9a-f\.]+|Stats): (.*)/;
+		@pgb_prefix_parse1 = ('t_timestamp', 't_pid', 't_loglevel', 't_session_id', 't_query');
 		$pgbouncer_log_parse2 = qr/^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d+(?: [A-Z\+\-\d]{3,6})? \d+ [^\s]+ .\-0x[0-9a-f\.]*: ([0-9a-zA-Z\_\[\]\-\.]*)\/([0-9a-zA-Z\_\[\]\-\.]*)\@([a-zA-Z0-9\-\.]+|\[local\]|\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}|[0-9a-fA-F:]+)?(?:\(\d+\))?(?:\(\d+\))?[:\d]* (.*)/;
 		@pgb_prefix_parse2 = ('t_dbname', 't_dbuser', 't_client', 't_query');
 
 	} elsif ($fmt eq 'pgbouncer1') {
 
-		$fmt = 'pgbouncer';
 		$pgbouncer_log_format = qr/^(...)\s+(\d+)\s(\d+):(\d+):(\d+)(?:\s[^\s]+)?\s([^\s]+)\s([^\s\[]+)\[(\d+)\]: (.\-0x[0-9a-f\.]*): ([0-9a-zA-Z\_\[\]\-\.]*)\/([0-9a-zA-Z\_\[\]\-\.]*)\@([a-zA-Z0-9\-\.]+|\[local\]|\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}|[0-9a-fA-F:]+)?(?:\(\d+\))?[:\d]* (.*)/;
 		@pgb_prefix_params = ('t_year', 't_month', 't_day', 't_hour', 't_min', 't_sec', 't_host', 't_ident', 't_pid', 't_session_id', 't_dbname', 't_dbuser', 't_client', 't_query');
 
-		$pgbouncer_log_parse1 = qr/^(...)\s+(\d+)\s(\d+):(\d+):(\d+)(?:\s[^\s]+)?\s([^\s]+)\s([^\s\[]+)\[(\d+)\]: (.\-0x[0-9a-f\.]*): (.*)/;
-		@pgb_prefix_parse1 = ('t_month', 't_day', 't_hour', 't_min', 't_sec', 't_host', 't_ident', 't_pid', 't_query');
+		$pgbouncer_log_parse1 = qr/^(...)\s+(\d+)\s(\d+):(\d+):(\d+)(?:\s[^\s]+)?\s([^\s]+)\s([^\s\[]+)\[(\d+)\]: (.\-0x[0-9a-f\.]+|Stats): (.*)/;
+		@pgb_prefix_parse1 = ('t_month', 't_day', 't_hour', 't_min', 't_sec', 't_host', 't_ident', 't_pid', 't_session_id', 't_query');
 		$pgbouncer_log_parse2 = qr/^...\s+\d+\s\d+:\d+:\d+(?:\s[^\s]+)?\s[^\s]+\s[^\s\[]+\[\d+\]: .\-0x[0-9a-f\.]*: ([0-9a-zA-Z\_\[\]\-\.]*)\/([0-9a-zA-Z\_\[\]\-\.]*)\@([a-zA-Z0-9\-\.]+|\[local\]|\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}|[0-9a-fA-F:]+)?(?:\(\d+\))?[:\d]* (.*)/;
 		@pgb_prefix_parse2 = ('t_dbname', 't_dbuser', 't_client', 't_query');
 
 	} elsif ($fmt eq 'pgbouncer2') {
 
-		$fmt = 'pgbouncer';
 		$pgbouncer_log_format = qr/^(\d{4})-(\d{2})-(\d{2})T(\d{2}):(\d{2}):(\d{2})(?:.[^\s]+)?\s([^\s]+)\s(?:[^\s]+\s)?(?:[^\s]+\s)?([^\s\[]+)\[(\d+)\]: (.\-0x[0-9a-f\.]*): ([0-9a-zA-Z\_\[\]\-\.]*)\/([0-9a-zA-Z\_\[\]\-\.]*)\@([a-zA-Z0-9\-\.]+|\[local\]|\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}|[0-9a-fA-F:]+)?(?:\(\d+\))?[:\d]* (.*)/;
 		@pgb_prefix_params = ('t_year', 't_month', 't_day', 't_hour', 't_min', 't_sec', 't_host', 't_ident', 't_pid', 't_session_id', 't_dbname', 't_dbuser', 't_client', 't_query');
 
-		$pgbouncer_log_parse1 = qr/^(\d{4})-(\d{2})-(\d{2})T(\d{2}):(\d{2}):(\d{2})(?:.[^\s]+)?\s([^\s]+)\s(?:[^\s]+\s)?(?:[^\s]+\s)?([^\s\[]+)\[(\d+)\]: (.\-0x[0-9a-f\.]*): (.*)/;
-		@pgb_prefix_parse1 = ('t_year', 't_month', 't_day', 't_hour', 't_min', 't_sec', 't_host', 't_ident', 't_pid', 't_query');
+		$pgbouncer_log_parse1 = qr/^(\d{4})-(\d{2})-(\d{2})T(\d{2}):(\d{2}):(\d{2})(?:.[^\s]+)?\s([^\s]+)\s(?:[^\s]+\s)?(?:[^\s]+\s)?([^\s\[]+)\[(\d+)\]: (.\-0x[0-9a-f\.]+|Stats): (.*)/;
+		@pgb_prefix_parse1 = ('t_year', 't_month', 't_day', 't_hour', 't_min', 't_sec', 't_host', 't_ident', 't_pid', 't_session_id', 't_query');
 		$pgbouncer_log_parse2 = qr/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(?:.[^\s]+)?\s[^\s]+\s(?:[^\s]+\s)?(?:[^\s]+\s)?[^\s\[]+\[\d+\]: .\-0x[0-9a-f\.]*: ([0-9a-zA-Z\_\[\]\-\.]*)\/([0-9a-zA-Z\_\[\]\-\.]*)\@([a-zA-Z0-9\-\.]+|\[local\]|\d{1,3}\.\d{1,3}\.\d{1,3}\.\d{1,3}|[0-9a-fA-F:]+)?(?:\(\d+\))?[:\d]* (.*)/;
 		@pgb_prefix_parse2 = ('t_dbname', 't_dbuser', 't_client', 't_query');
 
@@ -2553,7 +2549,7 @@ sub process_file
 	# Check if the first date in the log are after the last date saved
 	if (($logfile ne '-') && ($fmt ne 'binary') && ($fmt ne 'csv') && !$http_download) {
 		if ($start_offset && !$chunk_pos) {
-			my ($retcode, $msg) = check_file_changed($logfile, $file_size{$logfile}, $fmt, ($fmt eq 'pgbouncer') ? $pgb_saved_last_line{datetime} : $saved_last_line{datetime}, $start_offset, 1);
+			my ($retcode, $msg) = check_file_changed($logfile, $file_size{$logfile}, $fmt, ($fmt =~ /pgbouncer/) ? $pgb_saved_last_line{datetime} : $saved_last_line{datetime}, $start_offset, 1);
 			if ($retcode) {
 				&logmsg('DEBUG', "This file should be parsed from the beginning: $logfile, $msg");
 				&logmsg('DEBUG', "Reverting start offset $start_offset to 0 for file $logfile, stoppping offset is " . ($stop_offset || $totalsize));
@@ -2587,7 +2583,7 @@ sub process_file
 	}
 
 	# Parse pgbouncer logfile
-	if ($fmt eq 'pgbouncer') {
+	if ($fmt =~ /pgbouncer/) {
 
 		my $time_pattern = qr/(\d{4})-(\d{2})-(\d{2}) (\d{2}):(\d{2}):(\d{2})/;
 		my $cur_pid = '';
@@ -2654,6 +2650,11 @@ sub process_file
 "$prefix_vars{'t_year'}-$prefix_vars{'t_month'}-$prefix_vars{'t_day'} $prefix_vars{'t_hour'}:$prefix_vars{'t_min'}:$prefix_vars{'t_sec'}";
 				}
 				$prefix_vars{'t_loglevel'} = 'LOG';
+				if ($prefix_vars{'t_session_id'} eq 'Stats') {
+					$prefix_vars{'t_loglevel'} = 'STATS';
+					$prefix_vars{'t_session_id'} = '';
+					$prefix_vars{'t_query'} = 'Stats: ' . $prefix_vars{'t_query'};
+				}
 
 				# Skip unwanted lines
 				my $res = &skip_unwanted_line();
@@ -3207,8 +3208,8 @@ sub process_file
 
 	%cur_info = ();
 	# In incremental mode data are saved to disk per day
-	if ($incremental && ($last_line{datetime} || (($fmt eq 'pgbouncer') && $pgb_last_line{datetime}))) {
-		$incr_date = ($fmt eq 'pgbouncer') ? $pgb_last_line{datetime} : $last_line{datetime};
+	if ($incremental && ($last_line{datetime} || (($fmt =~ /pgbouncer/) && $pgb_last_line{datetime}))) {
+		$incr_date = ($fmt =~ /pgbouncer/) ? $pgb_last_line{datetime} : $last_line{datetime};
 		$incr_date =~ s/\s.*$//;
 		# set path and create subdirectories
 		if ($incr_date =~ /^(\d+)-(\d+)-(\d+)/) {
@@ -3252,7 +3253,7 @@ sub process_file
 	if ($last_parsed && (scalar keys %last_line || scalar keys %pgb_last_line)) {
 		if (open(my $out, '>>', "$tmp_last_parsed")) {
 			flock($out, 2) || return $getout;
-			if ($fmt eq 'pgbouncer') {
+			if ($fmt =~ /pgbouncer/) {
 				$pgb_last_line{current_pos} ||= 0;
 				&logmsg('DEBUG', "Saving pgbouncer last parsed line into $tmp_last_parsed ($pgb_last_line{datetime}\t$pgb_last_line{current_pos})");
 				print $out "pgbouncer\t$pgb_last_line{datetime}\t$pgb_last_line{current_pos}\t$pgb_last_line{orig}\n";
@@ -3531,7 +3532,7 @@ sub check_file_changed
 				}
 			}
 
-		} elsif ($fmt eq 'pgbouncer') {
+		} elsif ($fmt =~ /pgbouncer/) {
 
 			my @matches = ($line =~ $pgbouncer_log_parse1);
 			if ($#matches >= 0) {
@@ -3572,7 +3573,7 @@ sub check_incremental_position
 {
 	my ($fmt, $cur_date, $line) = @_;
 
-	if ($last_parsed && ($fmt ne 'pgbouncer')) {
+	if ($last_parsed && ($fmt !~ /pgbouncer/)) {
 		if ($saved_last_line{datetime}) {
 			if ($cur_date lt $saved_last_line{datetime}) {
 				return 0;
@@ -13411,7 +13412,7 @@ sub parse_pgbouncer
 	my $fmt = shift;
 
 	my $t_pid = $prefix_vars{'t_pid'};
-	my $t_session_id = $prefix_vars{'t_session_id'} || $prefix_vars{'t_pid'};
+	my $t_session_id = $prefix_vars{'t_session_id'};
 
 	my $date_part = "$prefix_vars{'t_year'}$prefix_vars{'t_month'}$prefix_vars{'t_day'}";
 	my $cur_last_log_timestamp = "$prefix_vars{'t_year'}-$prefix_vars{'t_month'}-$prefix_vars{'t_day'} " .
@@ -13525,7 +13526,7 @@ sub parse_pgbouncer
 		}
 
 		# set current session workload
-		if ( !$disable_session ) {
+		if ( !$disable_session && $t_session_id) {
 			$pgb_current_sessions{$t_session_id} = $prefix_vars{'t_timestamp'};
 			my $sess_count = scalar keys %pgb_current_sessions;
 			$pgb_overall_stat{'peak'}{$cur_last_log_timestamp}{session} = $sess_count;
@@ -14260,7 +14261,7 @@ sub autodetect_format
 	}
 
 	# When --pgbouncer-only is used force the format
-	if (!$format && $pgbouncer_only) {
+	if (!$format && !$fmt && $pgbouncer_only) {
 		$pgbouncer_only = 1;
 		$fmt = 'pgbouncer';
 	} elsif (!$format) {
@@ -14287,7 +14288,7 @@ sub search_log_format
 
 	# Are pgbouncer syslog lines ?
 	if ($line =~
-/^[A-Z][a-z]{2}\s+\d+ \d+:\d+:\d+(?:\s[^\s]+)?\s[^\s]+\s([^\s\[]+)\[\d+\]: (.\-0x[0-9a-f\.]*|Stats):/
+/^[A-Z][a-z]{2}\s+\d+ \d+:\d+:\d+(?: [^\s]+)? [^\s]+ [^\s\[]+\[\d+\]: (.\-0x[0-9a-f\.]+|Stats):/
 	   )
 	{
 		$fmt = 'pgbouncer1';
@@ -14343,7 +14344,7 @@ sub search_log_format
 		$fmt = 'default';
 
 	# Are pgbouncer lines ?
-	} elsif ($line =~ /^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2})\.\d+(?: [A-Z\+\-\d]{3,6})? (\d+) (LOG|ERROR) (.\-0x[0-9a-f\.]*|Stats):/) {
+	} elsif ($line =~ /^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2})\.\d+(?: [A-Z\+\-\d]{3,6})? (\d+) (LOG|ERROR) (.\-0x[0-9a-f\.]+|Stats):/) {
 		$fmt = 'pgbouncer';
 		# If we just have one single pgbouncer file, force pgbouncer_only to 1
 		$pgbouncer_only = 1 if ($#log_files == 0);