Skip to content

Commit dc11f31

Browse files
sfrostsfrost
committed
Add GSS information to connection authorized log message
GSS information (if used) such as if the connection was authorized using GSS or if it was encrypted using GSS, and perhaps most importantly, what the GSS principal used for the authentication was, is extremely useful but wasn't being included in the connection authorized log message. Therefore, add to the connection authorized log message that information, in a similar manner to how we log SSL information when SSL is used for a connection. Author: Vignesh C Reviewed-by: Bharath Rupireddy Discussion: https://www.postgresql.org/message-id/CALDaNm2N1385_Ltoo%3DS7VGT-ESu_bRQa-sC1wg6ikrM2L2Z49w%40mail.gmail.com
1 parent 0146924 commit dc11f31

File tree

2 files changed

+114
-86
lines changed

2 files changed

+114
-86
lines changed

‎src/backend/utils/init/postinit.c‎

Lines changed: 30 additions & 52 deletions
Original file line numberDiff line numberDiff line change
@@ -245,62 +245,40 @@ PerformAuthentication(Port *port)
245245

246246
if (Log_connections)
247247
{
248+
StringInfoData logmsg;
249+
250+
initStringInfo(&logmsg);
248251
if (am_walsender)
249-
{
250-
#ifdef USE_SSL
251-
if (port->ssl_in_use)
252-
ereport(LOG,
253-
(port->application_name != NULL
254-
? errmsg("replication connection authorized: user=%s application_name=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
255-
port->user_name,
256-
port->application_name,
257-
be_tls_get_version(port),
258-
be_tls_get_cipher(port),
259-
be_tls_get_cipher_bits(port),
260-
be_tls_get_compression(port) ? _("on") : _("off"))
261-
: errmsg("replication connection authorized: user=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
262-
port->user_name,
263-
be_tls_get_version(port),
264-
be_tls_get_cipher(port),
265-
be_tls_get_cipher_bits(port),
266-
be_tls_get_compression(port) ? _("on") : _("off"))));
267-
else
268-
#endif
269-
ereport(LOG,
270-
(port->application_name != NULL
271-
? errmsg("replication connection authorized: user=%s application_name=%s",
272-
port->user_name,
273-
port->application_name)
274-
: errmsg("replication connection authorized: user=%s",
275-
port->user_name)));
276-
}
252+
appendStringInfo(&logmsg, _("replication connection authorized: user=%s"),
253+
port->user_name);
277254
else
278-
{
255+
appendStringInfo(&logmsg, _("connection authorized: user=%s"),
256+
port->user_name);
257+
if (!am_walsender)
258+
appendStringInfo(&logmsg, _(" database=%s"), port->database_name);
259+
260+
if (port->application_name != NULL)
261+
appendStringInfo(&logmsg, _(" application_name=%s"),
262+
port->application_name);
263+
279264
#ifdef USE_SSL
280-
if (port->ssl_in_use)
281-
ereport(LOG,
282-
(port->application_name != NULL
283-
? errmsg("connection authorized: user=%s database=%s application_name=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
284-
port->user_name, port->database_name, port->application_name,
285-
be_tls_get_version(port),
286-
be_tls_get_cipher(port),
287-
be_tls_get_cipher_bits(port),
288-
be_tls_get_compression(port) ? _("on") : _("off"))
289-
: errmsg("connection authorized: user=%s database=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
290-
port->user_name, port->database_name,
291-
be_tls_get_version(port),
292-
be_tls_get_cipher(port),
293-
be_tls_get_cipher_bits(port),
294-
be_tls_get_compression(port) ? _("on") : _("off"))));
295-
else
265+
if (port->ssl_in_use)
266+
appendStringInfo(&logmsg, _(" SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)"),
267+
be_tls_get_version(port),
268+
be_tls_get_cipher(port),
269+
be_tls_get_cipher_bits(port),
270+
be_tls_get_compression(port) ? _("on") : _("off"));
296271
#endif
297-
ereport(LOG,
298-
(port->application_name != NULL
299-
? errmsg("connection authorized: user=%s database=%s application_name=%s",
300-
port->user_name, port->database_name, port->application_name)
301-
: errmsg("connection authorized: user=%s database=%s",
302-
port->user_name, port->database_name)));
303-
}
272+
#ifdef ENABLE_GSS
273+
if (be_gssapi_get_princ(port))
274+
appendStringInfo(&logmsg, _(" GSS (authenticated=%s, encrypted=%s, principal=%s)"),
275+
be_gssapi_get_auth(port) ? _("yes") : _("no"),
276+
be_gssapi_get_enc(port) ? _("yes") : _("no"),
277+
be_gssapi_get_princ(port));
278+
#endif
279+
280+
ereport(LOG, errmsg_internal("%s", logmsg.data));
281+
pfree(logmsg.data);
304282
}
305283

306284
set_ps_display("startup");

‎src/test/kerberos/t/001_auth.pl‎

Lines changed: 84 additions & 34 deletions
Original file line numberDiff line numberDiff line change
@@ -16,10 +16,11 @@
1616
use TestLib;
1717
use PostgresNode;
1818
use Test::More;
19+
use Time::HiRes qw(usleep);
1920

2021
if ($ENV{with_gssapi} eq 'yes')
2122
{
22-
plan tests => 18;
23+
plan tests => 34;
2324
}
2425
else
2526
{
@@ -74,6 +75,10 @@
7475
my $kdc_pidfile = "${TestLib::tmp_check}/krb5kdc.pid";
7576
my $keytab = "${TestLib::tmp_check}/krb5.keytab";
7677

78+
my $dbname = 'postgres';
79+
my $username = 'test1';
80+
my $application = '001_auth.pl';
81+
7782
note "setting up Kerberos";
7883

7984
my ($stdout, $krb5_version);
@@ -160,6 +165,8 @@ END
160165
$node->init;
161166
$node->append_conf('postgresql.conf', "listen_addresses = '$hostaddr'");
162167
$node->append_conf('postgresql.conf', "krb_server_keyfile = '$keytab'");
168+
$node->append_conf('postgresql.conf', "logging_collector = on");
169+
$node->append_conf('postgresql.conf', "log_connections = on");
163170
$node->start;
164171

165172
$node->safe_psql('postgres', 'CREATE USER test1;');
@@ -169,7 +176,7 @@ END
169176
# Test connection success or failure, and if success, that query returns true.
170177
sub test_access
171178
{
172-
my ($node, $role, $query, $expected_res, $gssencmode, $test_name) = @_;
179+
my ($node, $role, $query, $expected_res, $gssencmode, $test_name, $expect_log_msg) = @_;
173180

174181
# need to connect over TCP/IP for Kerberos
175182
my ($res, $stdoutres, $stderrres) = $node->psql(
@@ -192,6 +199,33 @@ sub test_access
192199
{
193200
is($res, $expected_res, $test_name);
194201
}
202+
203+
# Verify specified log message is logged in the log file.
204+
if ($expect_log_msg ne '')
205+
{
206+
my $current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
207+
note "current_logfiles = $current_logfiles";
208+
like($current_logfiles, qr|^stderr log/postgresql-.*log$|,
209+
'current_logfiles is sane');
210+
211+
my $lfname = $current_logfiles;
212+
$lfname =~ s/^stderr //;
213+
chomp $lfname;
214+
215+
# might need to retry if logging collector process is slow...
216+
my $max_attempts = 180 * 10;
217+
my $first_logfile;
218+
for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
219+
{
220+
$first_logfile = slurp_file($node->data_dir . '/' . $lfname);
221+
last if $first_logfile =~ m/\Q$expect_log_msg\E/;
222+
usleep(100_000);
223+
}
224+
225+
like($first_logfile, qr/\Q$expect_log_msg\E/,
226+
'found expected log file content');
227+
}
228+
195229
return;
196230
}
197231

@@ -223,11 +257,11 @@ sub test_query
223257
qq{host all all $hostaddr/32 gss map=mymap});
224258
$node->restart;
225259

226-
test_access($node, 'test1', 'SELECT true', 2, '', 'fails without ticket');
260+
test_access($node, 'test1', 'SELECT true', 2, '', 'fails without ticket', '');
227261

228262
run_log [ $kinit, 'test1' ], \$test1_password or BAIL_OUT($?);
229263

230-
test_access($node, 'test1', 'SELECT true', 2, '', 'fails without mapping');
264+
test_access($node, 'test1', 'SELECT true', 2, '', 'fails without mapping', '');
231265

232266
$node->append_conf('pg_ident.conf', qq{mymap /^(.*)\@$realm\$ \\1});
233267
$node->restart;
@@ -238,42 +272,49 @@ sub test_query
238272
'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
239273
0,
240274
'',
241-
'succeeds with mapping with default gssencmode and host hba');
275+
'succeeds with mapping with default gssencmode and host hba',
276+
"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
277+
);
278+
242279
test_access(
243280
$node,
244-
"test1",
281+
'test1',
245282
'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
246283
0,
247-
"gssencmode=prefer",
248-
"succeeds with GSS-encrypted access preferred with host hba");
284+
'gssencmode=prefer',
285+
'succeeds with GSS-encrypted access preferred with host hba',
286+
"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
287+
);
249288
test_access(
250289
$node,
251-
"test1",
290+
'test1',
252291
'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
253292
0,
254-
"gssencmode=require",
255-
"succeeds with GSS-encrypted access required with host hba");
293+
'gssencmode=require',
294+
'succeeds with GSS-encrypted access required with host hba',
295+
"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
296+
);
256297

257298
# Test that we can transport a reasonable amount of data.
258299
test_query(
259300
$node,
260-
"test1",
301+
'test1',
261302
'SELECT * FROM generate_series(1, 100000);',
262303
qr/^1\n.*\n1024\n.*\n9999\n.*\n100000$/s,
263-
"gssencmode=require",
264-
"receiving 100K lines works");
304+
'gssencmode=require',
305+
'receiving 100K lines works');
265306

266307
test_query(
267308
$node,
268-
"test1",
309+
'test1',
269310
"CREATE TABLE mytab (f1 int primary key);\n"
270311
. "COPY mytab FROM STDIN;\n"
271312
. join("\n", (1 .. 100000))
272313
. "\n\\.\n"
273314
. "SELECT COUNT(*) FROM mytab;",
274315
qr/^100000$/s,
275-
"gssencmode=require",
276-
"sending 100K lines works");
316+
'gssencmode=require',
317+
'sending 100K lines works');
277318

278319
unlink($node->data_dir . '/pg_hba.conf');
279320
$node->append_conf('pg_hba.conf',
@@ -282,20 +323,24 @@ sub test_query
282323

283324
test_access(
284325
$node,
285-
"test1",
326+
'test1',
286327
'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
287328
0,
288-
"gssencmode=prefer",
289-
"succeeds with GSS-encrypted access preferred and hostgssenc hba");
329+
'gssencmode=prefer',
330+
'succeeds with GSS-encrypted access preferred and hostgssenc hba',
331+
"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
332+
);
290333
test_access(
291334
$node,
292-
"test1",
335+
'test1',
293336
'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
294337
0,
295-
"gssencmode=require",
296-
"succeeds with GSS-encrypted access required and hostgssenc hba");
297-
test_access($node, "test1", 'SELECT true', 2, "gssencmode=disable",
298-
"fails with GSS encryption disabled and hostgssenc hba");
338+
'gssencmode=require',
339+
'succeeds with GSS-encrypted access required and hostgssenc hba',
340+
"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
341+
);
342+
test_access($node, 'test1', 'SELECT true', 2, 'gssencmode=disable',
343+
'fails with GSS encryption disabled and hostgssenc hba', '');
299344

300345
unlink($node->data_dir . '/pg_hba.conf');
301346
$node->append_conf('pg_hba.conf',
@@ -304,21 +349,24 @@ sub test_query
304349

305350
test_access(
306351
$node,
307-
"test1",
352+
'test1',
308353
'SELECT gss_authenticated and not encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
309354
0,
310-
"gssencmode=prefer",
311-
"succeeds with GSS-encrypted access preferred and hostnogssenc hba, but no encryption"
355+
'gssencmode=prefer',
356+
'succeeds with GSS-encrypted access preferred and hostnogssenc hba, but no encryption',
357+
"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=no, principal=test1\@$realm)"
312358
);
313-
test_access($node, "test1", 'SELECT true', 2, "gssencmode=require",
314-
"fails with GSS-encrypted access required and hostnogssenc hba");
359+
test_access($node, 'test1', 'SELECT true', 2, 'gssencmode=require',
360+
'fails with GSS-encrypted access required and hostnogssenc hba', '');
315361
test_access(
316362
$node,
317-
"test1",
363+
'test1',
318364
'SELECT gss_authenticated and not encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
319365
0,
320-
"gssencmode=disable",
321-
"succeeds with GSS encryption disabled and hostnogssenc hba");
366+
'gssencmode=disable',
367+
'succeeds with GSS encryption disabled and hostnogssenc hba',
368+
"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=no, principal=test1\@$realm)"
369+
);
322370

323371
truncate($node->data_dir . '/pg_ident.conf', 0);
324372
unlink($node->data_dir . '/pg_hba.conf');
@@ -332,4 +380,6 @@ sub test_query
332380
'SELECT gss_authenticated AND encrypted from pg_stat_gssapi where pid = pg_backend_pid();',
333381
0,
334382
'',
335-
'succeeds with include_realm=0 and defaults');
383+
'succeeds with include_realm=0 and defaults',
384+
"connection authorized: user=$username database=$dbname application_name=$application GSS (authenticated=yes, encrypted=yes, principal=test1\@$realm)"
385+
);

0 commit comments

Comments
 (0)