1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
|
# Copyright (c) 2021-2023, PostgreSQL Global Development Group
use strict;
use warnings;
use PostgreSQL::Test::Cluster;
use PostgreSQL::Test::Utils;
use Test::More;
# Runs the specified query and returns the emitted server log.
# params is an optional hash mapping GUC names to values;
# any such settings are transmitted to the backend via PGOPTIONS.
sub query_log
{
my ($node, $sql, $params) = @_;
$params ||= {};
local $ENV{PGOPTIONS} = join " ",
map { "-c $_=$params->{$_}" } keys %$params;
my $log = $node->logfile();
my $offset = -s $log;
$node->safe_psql("postgres", $sql);
return slurp_file($log, $offset);
}
my $node = PostgreSQL::Test::Cluster->new('main');
$node->init('auth_extra' => [ '--create-role', 'regress_user1' ]);
$node->append_conf('postgresql.conf',
"session_preload_libraries = 'auto_explain'");
$node->append_conf('postgresql.conf', "auto_explain.log_min_duration = 0");
$node->append_conf('postgresql.conf', "auto_explain.log_analyze = on");
$node->start;
# Simple query.
my $log_contents = query_log($node, "SELECT * FROM pg_class;");
like(
$log_contents,
qr/Query Text: SELECT \* FROM pg_class;/,
"query text logged, text mode");
unlike(
$log_contents,
qr/Query Parameters:/,
"no query parameters logged when none, text mode");
like(
$log_contents,
qr/Seq Scan on pg_class/,
"sequential scan logged, text mode");
# Prepared query.
$log_contents = query_log($node,
q{PREPARE get_proc(name) AS SELECT * FROM pg_proc WHERE proname = $1; EXECUTE get_proc('int4pl');}
);
like(
$log_contents,
qr/Query Text: PREPARE get_proc\(name\) AS SELECT \* FROM pg_proc WHERE proname = \$1;/,
"prepared query text logged, text mode");
like(
$log_contents,
qr/Query Parameters: \$1 = 'int4pl'/,
"query parameters logged, text mode");
like(
$log_contents,
qr/Index Scan using pg_proc_proname_args_nsp_index on pg_proc/,
"index scan logged, text mode");
# Prepared query with truncated parameters.
$log_contents = query_log(
$node,
q{PREPARE get_type(name) AS SELECT * FROM pg_type WHERE typname = $1; EXECUTE get_type('float8');},
{ "auto_explain.log_parameter_max_length" => 3 });
like(
$log_contents,
qr/Query Text: PREPARE get_type\(name\) AS SELECT \* FROM pg_type WHERE typname = \$1;/,
"prepared query text logged, text mode");
like(
$log_contents,
qr/Query Parameters: \$1 = 'flo\.\.\.'/,
"query parameters truncated, text mode");
# Prepared query with parameter logging disabled.
$log_contents = query_log(
$node,
q{PREPARE get_type(name) AS SELECT * FROM pg_type WHERE typname = $1; EXECUTE get_type('float8');},
{ "auto_explain.log_parameter_max_length" => 0 });
like(
$log_contents,
qr/Query Text: PREPARE get_type\(name\) AS SELECT \* FROM pg_type WHERE typname = \$1;/,
"prepared query text logged, text mode");
unlike(
$log_contents,
qr/Query Parameters:/,
"query parameters not logged when disabled, text mode");
# Query Identifier.
# Logging enabled.
$log_contents = query_log(
$node,
"SELECT * FROM pg_class;",
{
"auto_explain.log_verbose" => "on",
"compute_query_id" => "on"
});
like(
$log_contents,
qr/Query Identifier:/,
"query identifier logged with compute_query_id=on, text mode");
# Logging disabled.
$log_contents = query_log(
$node,
"SELECT * FROM pg_class;",
{
"auto_explain.log_verbose" => "on",
"compute_query_id" => "regress"
});
unlike(
$log_contents,
qr/Query Identifier:/,
"query identifier not logged with compute_query_id=regress, text mode");
# JSON format.
$log_contents = query_log(
$node,
"SELECT * FROM pg_class;",
{ "auto_explain.log_format" => "json" });
like(
$log_contents,
qr/"Query Text": "SELECT \* FROM pg_class;"/,
"query text logged, json mode");
unlike(
$log_contents,
qr/"Query Parameters":/,
"query parameters not logged when none, json mode");
like(
$log_contents,
qr/"Node Type": "Seq Scan"[^}]*"Relation Name": "pg_class"/s,
"sequential scan logged, json mode");
# Prepared query in JSON format.
$log_contents = query_log(
$node,
q{PREPARE get_class(name) AS SELECT * FROM pg_class WHERE relname = $1; EXECUTE get_class('pg_class');},
{ "auto_explain.log_format" => "json" });
like(
$log_contents,
qr/"Query Text": "PREPARE get_class\(name\) AS SELECT \* FROM pg_class WHERE relname = \$1;"/,
"prepared query text logged, json mode");
like(
$log_contents,
qr/"Node Type": "Index Scan"[^}]*"Index Name": "pg_class_relname_nsp_index"/s,
"index scan logged, json mode");
# Check that PGC_SUSET parameters can be set by non-superuser if granted,
# otherwise not
$node->safe_psql(
"postgres", q{
CREATE USER regress_user1;
GRANT SET ON PARAMETER auto_explain.log_format TO regress_user1;
});
{
local $ENV{PGUSER} = "regress_user1";
$log_contents = query_log(
$node,
"SELECT * FROM pg_database;",
{ "auto_explain.log_format" => "json" });
like(
$log_contents,
qr/"Query Text": "SELECT \* FROM pg_database;"/,
"query text logged, json mode selected by non-superuser");
$log_contents = query_log(
$node,
"SELECT * FROM pg_database;",
{ "auto_explain.log_level" => "log" });
like(
$log_contents,
qr/WARNING: ( 42501:)? permission denied to set parameter "auto_explain\.log_level"/,
"permission failure logged");
} # end queries run as regress_user1
$node->safe_psql(
"postgres", q{
REVOKE SET ON PARAMETER auto_explain.log_format FROM regress_user1;
DROP USER regress_user1;
});
done_testing();
|
