Skip to content

Fix dropped queries when filtering by user (#886) #887

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
darold merged 1 commit into from
Sep 15, 2026
Merged

Fix dropped queries when filtering by user (#886) #887

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
43 changes: 43 additions & 0 deletions pgbadger
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4405,6 +4405,21 @@ sub process_file
&store_queries($cur_pid);
delete $cur_info{$cur_pid};
}

# A completed query may still be buffered for THIS backend when the
# lines that would normally flush it were dropped by --dbuser/--dbname/
# --dbclient/--exclude-* filtering. Flush it now: otherwise the pending
# entry stays in %cur_info and set_current_infos() refuses to overwrite
# its non-empty query slot, silently dropping this query.
if (exists $cur_info{$prefix_vars{'t_pid'}} && ($prefix_vars{'t_pid'} ne $cur_pid)
&& ($prefix_vars{'t_loglevel'} =~ /^(LOG|ERROR|FATAL|PANIC|WARNING)$/)
&& ($cur_info{$prefix_vars{'t_pid'}}{query} ne '')
&& (!$log_duration || ($cur_info{$prefix_vars{'t_pid'}}{duration} ne '')))
{
&store_queries($prefix_vars{'t_pid'});
delete $cur_info{$prefix_vars{'t_pid'}};
}

# Parse the query now
&parse_query($fmt);
}
Expand Down Expand Up @@ -4513,6 +4528,20 @@ sub process_file
delete $cur_info{$cur_pid} if (!$log_duration || ($cur_info{$cur_pid}{duration} ne '' && $cur_info{$cur_pid}{query} ne ''));
}

# A completed query may still be buffered for THIS backend when the
# lines that would normally flush it were dropped by --dbuser/--dbname/
# --dbclient/--exclude-* filtering. Flush it now: otherwise the pending
# entry stays in %cur_info and set_current_infos() refuses to overwrite
# its non-empty query slot, silently dropping this query.
if (exists $cur_info{$prefix_vars{'t_pid'}} && ($prefix_vars{'t_pid'} ne $cur_pid)
&& ($prefix_vars{'t_loglevel'} =~ /^(LOG|ERROR|FATAL|PANIC|WARNING)$/)
&& ($cur_info{$prefix_vars{'t_pid'}}{query} ne '')
&& (!$log_duration || ($cur_info{$prefix_vars{'t_pid'}}{duration} ne '')))
{
&store_queries($prefix_vars{'t_pid'});
delete $cur_info{$prefix_vars{'t_pid'}};
}

# Process the log line
&parse_query($fmt);

Expand Down Expand Up @@ -4700,6 +4729,20 @@ sub process_file
delete $cur_info{$cur_pid} if (!$log_duration || ($cur_info{$cur_pid}{duration} ne '' && $cur_info{$cur_pid}{query} ne ''));
}

# A completed query may still be buffered for THIS backend when the
# lines that would normally flush it were dropped by --dbuser/--dbname/
# --dbclient/--exclude-* filtering. Flush it now: otherwise the pending
# entry stays in %cur_info and set_current_infos() refuses to overwrite
# its non-empty query slot, silently dropping this query.
if (exists $cur_info{$prefix_vars{'t_pid'}} && ($prefix_vars{'t_pid'} ne $cur_pid)
&& ($prefix_vars{'t_loglevel'} =~ /^(LOG|ERROR|FATAL|PANIC|WARNING)$/)
&& ($cur_info{$prefix_vars{'t_pid'}}{query} ne '')
&& (!$log_duration || ($cur_info{$prefix_vars{'t_pid'}}{duration} ne '')))
{
&store_queries($prefix_vars{'t_pid'});
delete $cur_info{$prefix_vars{'t_pid'}};
}

# Process the log line
&parse_query($fmt);

Expand Down
61 changes: 61 additions & 0 deletions t/08_dbuser_filter.t
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,61 @@
use Test::More;

# Regression test: line filters such as --dbuser must not silently drop queries
# that belong to the requested user.
#
# On interleaved logs, a completed query can remain buffered in %cur_info for a
# backend after the line that would normally flush it has been removed by the
# filter. set_current_infos() then refuses to overwrite the still-occupied query
# slot, so the next query on that backend used to be dropped from the report.
#
# The fixture stages two concurrent "batch" backends (pids 100 and 200) plus one
# "webapp" line. With --dbuser=batch the webapp line is filtered out; that line is
# exactly the one that would have flushed pid 100's first query, so the following
# slow query on pid 100 (IMPORTANT_slow_batch_query) used to disappear.

plan tests => 8;

my $LOG = 't/fixtures/dbuser_filter.log';
my $PREFIX = '%t:%r:%u@%d:[%p]:';
my $FILT = 't/dbuser_filter_batch.html';
my $ALL = 't/dbuser_filter_all.html';

unlink $FILT, $ALL;

# --- Filtered run: only the "batch" user -----------------------------------
my $ret = `perl pgbadger -q -f rds -p '$PREFIX' --dbuser=batch -o $FILT $LOG 2>&1`;
is($?, 0, 'Generate rds report filtered by --dbuser=batch');
diag($ret) if $?;

my $filtered = slurp($FILT);

like($filtered, qr/IMPORTANT_slow_batch_query/,
'Slow batch query on a busy backend survives --dbuser filtering');
like($filtered, qr/stale_batch_query/,
'Earlier batch query on the same backend is still reported');
like($filtered, qr/other_batch_query/,
'Batch query on the second backend is reported');
unlike($filtered, qr/webapp/,
'Non-matching user (webapp) is excluded by --dbuser=batch');

# --- Baseline run: no filter -----------------------------------------------
$ret = `perl pgbadger -q -f rds -p '$PREFIX' -o $ALL $LOG 2>&1`;
is($?, 0, 'Generate rds report without filter');
diag($ret) if $?;

my $all = slurp($ALL);
like($all, qr/IMPORTANT_slow_batch_query/,
'Slow batch query is present in the unfiltered report');
like($all, qr/webapp/,
'webapp user is present in the unfiltered report');

unlink $FILT, $ALL;

sub slurp {
my ($file) = @_;
open(my $fh, '<', $file) or return '';
local $/;
my $data = <$fh>;
close($fh);
return $data;
}
6 changes: 6 additions & 0 deletions t/fixtures/dbuser_filter.log
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
2026-09-10 17:00:00 UTC:10.0.0.9(5001):batch@appdb:[200]:LOG: duration: 12.001 ms execute <unnamed>: /* other_batch_query */ select id from other_table where k = $1
2026-09-10 17:00:00 UTC:10.0.0.9(5000):batch@appdb:[100]:LOG: duration: 34.567 ms execute <unnamed>: /* stale_batch_query */ select name from accounts where id = $1
2026-09-10 17:00:01 UTC:10.0.0.7(6000):webapp@appdb:[300]:LOG: duration: 1.234 ms statement: SELECT now()
2026-09-10 17:00:01 UTC:10.0.0.9(5001):batch@appdb:[200]:DETAIL: parameters: $1 = '42'
2026-09-10 17:00:02 UTC:10.0.0.9(5000):batch@appdb:[100]:LOG: duration: 987654.321 ms execute <unnamed>: /* IMPORTANT_slow_batch_query */ select count(*) from huge_reporting_table where created > $1
2026-09-10 17:00:02 UTC:10.0.0.9(5000):batch@appdb:[100]:DETAIL: parameters: $1 = '2026-09-01 00:00:00'