On Mon, Mar 10, 2025 at 5:03 PM Daniel Gustafsson <dan...@yesql.se> wrote:
>
> > On 7 Mar 2025, at 23:08, Melanie Plageman <melanieplage...@gmail.com> wrote:
>
> Sorry for being late to the party. I like this functionality and would
> definitely like to see it in v18.
Thanks so much for the review!
> + /* For backwards compatibility, we accept these tokens by themselves */
> + static const struct config_enum_entry compat_options[] = {
> + {"off", 0},
> + {"false", 0},
> + {"no", 0},
> + {"0", 0},
> + {"on", LOG_CONNECTION_ON},
> + {"true", LOG_CONNECTION_ON},
> + {"yes", LOG_CONNECTION_ON},
> + {"1", LOG_CONNECTION_ON},
> + };
> It's not documented here that the backwards compatibility will turn the
> LOG_CONNECTION_ON value into a set of the new fine-grained value. A brief
> mention would be good for future code reading (or a hint to look for details
> in
> src/include/tcop/backend_startup.h).
I've added a comment about this in attached v14.
> + LOG_CONNECTION_ON =
> + LOG_CONNECTION_RECEIPT |
> + LOG_CONNECTION_AUTHENTICATION |
> + LOG_CONNECTION_AUTHORIZATION,
> + LOG_CONNECTION_ALL =
> + LOG_CONNECTION_ON,
> Nitpick I know, but reusing the backwards compatible _ON for _ALL makes it
> seem
> like they are the other way around (_ALL being for backwards compat). 0002
> makes it less so but I would prefer to spend the extra lines of code and spell
> out both.
Done.
> +#define IsConnectionBackend(backend_type) \
> This feels like a slightly too generic name to fully convey what it does. I
> don't have a better one off the cuff but I had to refer back multiple times to
> remind myself what it did.
Is `IsClientBackend()` better? It doesn't sound immediately like it
includes WAL sender backends (replication connections), but those are
initiated by clients too, right?
I didn't change it in v14 because I wasn't sure it was better and
wanted to hear what you thought.
> + backend at the time the connection is ready for use. The log
> I'm not sure if "ready for use" will be clear for all readers? The other
> options are using a bit more precise language.
I've tried to clear this up.
> + {"durations", LOG_CONNECTION_DURATIONS},
> I think "durations" is a good name for this, but we risk causing some
> confusion
> in postgresql.conf when set, as it will end up like this:
>
> log_connections = durations
> #log_disconnections = off
> #log_duration = off
>
> How log_connections=durations and log_duration=off are related might not be
> immediately obvious to new users. Can we avoid confusion by adding comments
> on
> these log entries perhaps?
I forgot about log_duration and that log_disconnections prints the
connection duration. Thinking about it more and taking into account
something Bertrand suggested upthread, I decided to rename the option
"setup_durations". It's a bit long, but it does convey that these
durations are only about connection setup.
I also added more details about what this is both to docs and
postgresql.conf.sample. Thanks!
> + errmsg("connection ready: total=%.3f ms, fork=%.3f ms,
> authentication=%.3f ms",
> The use of "total" here makes it seem like (fork+authentication)=total. Not
> sure if we can do better and still be descriptive. Maybe it's a case of
> documenting it if there are questions or complaints?
I've changed it to "setup total=xxx ms, fork=xxx...". I also added
details about the component durations to the docs.
> > I'm a bit torn about having the tests in authentication/001_password.
>
> Agreed, they're not a great fit and it's not where I would look for them.
> That
> being said, paying for spinning up a new cluster for just this also doesn't
> seem great. Maybe adding a comment in the test file explaining why they are
> in
> there could help readers.
Yep, added the comment.
I did more manual testing of my patches, and I think they are mostly
ready for commit except for the IsConnectionBackend() macro (if we
have something to change it to).
I did notice one other thing, though. Because
process_startup_options() is called after all the existing
log_connections messages are emitted, setup_durations behaves a bit
differently than the other options. I actually think the other
log_connections options are not quite right, so perhaps it is okay
that the new option is different if it is more compliant.
For example, if you start from a freshly initdb'd cluster and do ALTER
SYSTEM SET log_connections='all', then restart or reload the conf file
and reconnect, you'll see the receipt, authentication, authorization,
and setup_durations messages. If you then `export PGOPTIONS="-c
log_connections="` and reconnect again, you'll see the receipt,
authentication, and authorization messages but not the setup_durations
message. The setup_durations message is emitted after we process
PGOPTIONS and set log_connections = ''. I think this behavior is okay,
though I'm not sure if/where it should be documented
- Melanie
From 46d416c95943ff79762c551443e6de1f64f771e0 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <melanieplage...@gmail.com>
Date: Wed, 5 Mar 2025 18:02:45 -0500
Subject: [PATCH v14 1/2] Modularize log_connections output
Convert the boolean log_connections GUC into a list GUC comprised of the
connection aspects to log.
This gives users more control over the volume and kind of connection
logging.
The current log_connections options are 'receipt', 'authentication', and
'authorization'. The empty string disables all connection logging. 'all'
enables all available connection logging.
For backwards compatibility, the most common values for the
log_connections boolean are still supported (on, off, 1, 0, true,
false, yes, no).
Author: Melanie Plageman <melanieplage...@gmail.com>
Reviewed-by: Bertrand Drouvot <bertranddrouvot...@gmail.com>
Reviewed-by: Fujii Masao <masao.fu...@oss.nttdata.com>
Reviewed-by: Daniel Gustafsson <dan...@yesql.se>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
doc/src/sgml/config.sgml | 77 ++++++++-
src/backend/libpq/auth.c | 9 +-
src/backend/postmaster/postmaster.c | 1 -
src/backend/tcop/backend_startup.c | 161 +++++++++++++++++-
src/backend/utils/init/postinit.c | 3 +-
src/backend/utils/misc/guc_tables.c | 21 ++-
src/backend/utils/misc/postgresql.conf.sample | 8 +-
src/include/postmaster/postmaster.h | 1 -
src/include/tcop/backend_startup.h | 29 ++++
src/include/utils/guc_hooks.h | 2 +
src/test/authentication/t/001_password.pl | 38 +++++
src/tools/pgindent/typedefs.list | 1 +
12 files changed, 326 insertions(+), 25 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index d2fa5f7d1a9..d939d99d6e8 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7315,20 +7315,87 @@ local0.* /var/log/postgresql
</varlistentry>
<varlistentry id="guc-log-connections" xreflabel="log_connections">
- <term><varname>log_connections</varname> (<type>boolean</type>)
+ <term><varname>log_connections</varname> (<type>string</type>)
<indexterm>
<primary><varname>log_connections</varname> configuration parameter</primary>
</indexterm>
</term>
<listitem>
<para>
- Causes each attempted connection to the server to be logged,
- as well as successful completion of both client authentication (if
- necessary) and authorization.
+ Causes aspects of each connection attempt to the server to be
+ logged. The default is the empty string, <literal>''</literal>,
+ which disables all connection logging. The following options may
+ be specified alone or in a comma-separated list:
+ </para>
+
+ <table id="log-connections-options">
+ <title>Log Connection Options</title>
+ <tgroup cols="2">
+ <colspec colname="col1" colwidth="1*"/>
+ <colspec colname="col2" colwidth="2*"/>
+ <thead>
+ <row>
+ <entry>Name</entry>
+ <entry>Description</entry>
+ </row>
+ </thead>
+ <tbody>
+ <row>
+ <entry><literal>receipt</literal></entry>
+ <entry>Logs receipt of a connection.</entry>
+ </row>
+
+ <row>
+ <entry><literal>authentication</literal></entry>
+ <entry>
+ Logs the original identity used by an authentication method
+ to identify a user. In most cases, the identity string
+ matches the PostgreSQL username, but some third-party
+ authentication methods may alter the original user
+ identifier before the server stores it. Failed
+ authentication is always logged regardless of the value of
+ this setting.
+ </entry>
+ </row>
+
+ <row>
+ <entry><literal>authorization</literal></entry>
+ <entry>
+ Logs successful completion of authorization. At this point
+ the connection has been established but the backend is not
+ yet fully set up. The log message includes the authorized
+ username as well as the database name and application name,
+ if applicable.
+ </entry>
+ </row>
+
+ <row>
+ <entry><literal>all</literal></entry>
+ <entry>
+ A convenience alias equivalent to specifying all options. If
+ <literal>all</literal> is specified in a list of other
+ options, all connection aspects will be logged.
+ </entry>
+ </row>
+
+ </tbody>
+ </tgroup>
+ </table>
+
+ <para>
+ For the purposes of backwards compatibility, <literal>on</literal>,
+ <literal>off</literal>, <literal>true</literal>,
+ <literal>false</literal>, <literal>yes</literal>,
+ <literal>no</literal>, <literal>1</literal>, and <literal>0</literal>
+ are still supported. The positive values are equivalent to specifying
+ the <literal>receipt</literal>, <literal>authentication</literal>, and
+ <literal>authorization</literal> options.
+ </para>
+
+ <para>
Only superusers and users with the appropriate <literal>SET</literal>
privilege can change this parameter at session start,
and it cannot be changed at all within a session.
- The default is <literal>off</literal>.
</para>
<note>
diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index 81e2f8184e3..e18683c47e7 100644
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -38,6 +38,7 @@
#include "postmaster/postmaster.h"
#include "replication/walsender.h"
#include "storage/ipc.h"
+#include "tcop/backend_startup.h"
#include "utils/memutils.h"
/*----------------------------------------------------------------
@@ -317,7 +318,8 @@ auth_failed(Port *port, int status, const char *logdetail)
/*
* Sets the authenticated identity for the current user. The provided string
* will be stored into MyClientConnectionInfo, alongside the current HBA
- * method in use. The ID will be logged if log_connections is enabled.
+ * method in use. The ID will be logged if log_connections has the
+ * 'authentication' option specified.
*
* Auth methods should call this routine exactly once, as soon as the user is
* successfully authenticated, even if they have reasons to know that
@@ -349,7 +351,7 @@ set_authn_id(Port *port, const char *id)
MyClientConnectionInfo.authn_id = MemoryContextStrdup(TopMemoryContext, id);
MyClientConnectionInfo.auth_method = port->hba->auth_method;
- if (Log_connections)
+ if (log_connections & LOG_CONNECTION_AUTHENTICATION)
{
ereport(LOG,
errmsg("connection authenticated: identity=\"%s\" method=%s "
@@ -633,7 +635,8 @@ ClientAuthentication(Port *port)
#endif
}
- if (Log_connections && status == STATUS_OK &&
+ if ((log_connections & LOG_CONNECTION_AUTHENTICATION) &&
+ status == STATUS_OK &&
!MyClientConnectionInfo.authn_id)
{
/*
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index d2a7a7add6f..b4f34c57a1b 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -237,7 +237,6 @@ int PreAuthDelay = 0;
int AuthenticationTimeout = 60;
bool log_hostname; /* for ps display and logging */
-bool Log_connections = false;
bool enable_bonjour = false;
char *bonjour_name;
diff --git a/src/backend/tcop/backend_startup.c b/src/backend/tcop/backend_startup.c
index c70746fa562..962b6e60002 100644
--- a/src/backend/tcop/backend_startup.c
+++ b/src/backend/tcop/backend_startup.c
@@ -34,13 +34,17 @@
#include "tcop/backend_startup.h"
#include "tcop/tcopprot.h"
#include "utils/builtins.h"
+#include "utils/guc_hooks.h"
#include "utils/injection_point.h"
#include "utils/memutils.h"
#include "utils/ps_status.h"
#include "utils/timeout.h"
+#include "utils/varlena.h"
/* GUCs */
bool Trace_connection_negotiation = false;
+uint32 log_connections = 0;
+char *log_connections_string = NULL;
static void BackendInitialize(ClientSocket *client_sock, CAC_state cac);
static int ProcessSSLStartup(Port *port);
@@ -48,6 +52,7 @@ static int ProcessStartupPacket(Port *port, bool ssl_done, bool gss_done);
static void SendNegotiateProtocolVersion(List *unrecognized_protocol_options);
static void process_startup_packet_die(SIGNAL_ARGS);
static void StartupPacketTimeoutHandler(void);
+static bool validate_log_connections_options(List *elemlist, uint32 *flags);
/*
* Entry point for a new backend process.
@@ -201,8 +206,8 @@ BackendInitialize(ClientSocket *client_sock, CAC_state cac)
port->remote_host = MemoryContextStrdup(TopMemoryContext, remote_host);
port->remote_port = MemoryContextStrdup(TopMemoryContext, remote_port);
- /* And now we can issue the Log_connections message, if wanted */
- if (Log_connections)
+ /* And now we can log that the connection was received, if enabled */
+ if (log_connections & LOG_CONNECTION_RECEIPT)
{
if (remote_port[0])
ereport(LOG,
@@ -924,3 +929,155 @@ StartupPacketTimeoutHandler(void)
{
_exit(1);
}
+
+/*
+ * Helper for the log_connections GUC check hook.
+ *
+ * `elemlist` is a listified version of the string input passed to the
+ * log_connections GUC check hook, check_log_connections().
+ * check_log_connections() is responsible for cleaning up `elemlist`.
+ *
+ * validate_log_connections_options() returns false if an error was
+ * encountered and the GUC input could not be validated and true otherwise.
+ *
+ * `flags` returns the flags that should be stored in the log_connections GUC
+ * by its assign hook.
+ */
+static bool
+validate_log_connections_options(List *elemlist, uint32 *flags)
+{
+ ListCell *l;
+ char *item;
+
+ /*
+ * For backwards compatibility, we accept these tokens by themselves.
+ *
+ * Prior to PostgreSQL 18, log_connections was a boolean GUC that accepted
+ * any unambiguous substring of 'true', 'false', 'yes', 'no', 'on', and
+ * 'off'. Since log_connections became a list of strings in 18, we only
+ * accept complete option strings.
+ */
+ static const struct config_enum_entry compat_options[] = {
+ {"off", 0},
+ {"false", 0},
+ {"no", 0},
+ {"0", 0},
+ {"on", LOG_CONNECTION_ON},
+ {"true", LOG_CONNECTION_ON},
+ {"yes", LOG_CONNECTION_ON},
+ {"1", LOG_CONNECTION_ON},
+ };
+
+ *flags = 0;
+
+ /* If an empty string was passed, we're done */
+ if (list_length(elemlist) == 0)
+ return true;
+
+ /*
+ * Now check for the backwards compatibility options. They must always be
+ * specified on their own, so we error out if the first option is a
+ * backwards compatibility option and other options are also specified.
+ */
+ item = linitial(elemlist);
+
+ for (size_t i = 0; i < lengthof(compat_options); i++)
+ {
+ struct config_enum_entry option = compat_options[i];
+
+ if (pg_strcasecmp(item, option.name) != 0)
+ continue;
+
+ if (list_length(elemlist) > 1)
+ {
+ GUC_check_errdetail("Cannot specify log_connections option \"%s\" in a list with other options.",
+ item);
+ return false;
+ }
+
+ *flags = option.val;
+ return true;
+ }
+
+ /* Now check the aspect options. The empty string was already handled */
+ foreach(l, elemlist)
+ {
+ static const struct config_enum_entry options[] = {
+ {"receipt", LOG_CONNECTION_RECEIPT},
+ {"authentication", LOG_CONNECTION_AUTHENTICATION},
+ {"authorization", LOG_CONNECTION_AUTHORIZATION},
+ {"all", LOG_CONNECTION_ALL},
+ };
+
+ item = lfirst(l);
+ for (size_t i = 0; i < lengthof(options); i++)
+ {
+ struct config_enum_entry option = options[i];
+
+ if (pg_strcasecmp(item, option.name) == 0)
+ {
+ *flags |= option.val;
+ goto next;
+ }
+ }
+
+ GUC_check_errdetail("Invalid option \"%s\".", item);
+ return false;
+
+next: ;
+ }
+
+ return true;
+}
+
+
+/*
+ * GUC check hook for log_connections
+ */
+bool
+check_log_connections(char **newval, void **extra, GucSource source)
+{
+ uint32 flags;
+ char *rawstring;
+ List *elemlist;
+ bool success;
+
+ /* Need a modifiable copy of string */
+ rawstring = pstrdup(*newval);
+
+ if (!SplitIdentifierString(rawstring, ',', &elemlist))
+ {
+ GUC_check_errdetail("Invalid list syntax in parameter \"log_connections\".");
+ pfree(rawstring);
+ list_free(elemlist);
+ return false;
+ }
+
+ /* Validation logic is all in the helper */
+ success = validate_log_connections_options(elemlist, &flags);
+
+ /* Time for cleanup */
+ pfree(rawstring);
+ list_free(elemlist);
+
+ if (!success)
+ return false;
+
+ /*
+ * We succeeded, so allocate `extra` and save the flags there for use by
+ * assign_log_connections().
+ */
+ *extra = guc_malloc(ERROR, sizeof(int));
+ *((int *) *extra) = flags;
+
+ return true;
+}
+
+/*
+ * GUC assign hook for log_connections
+ */
+void
+assign_log_connections(const char *newval, void *extra)
+{
+ log_connections = *((int *) extra);
+}
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index ee1a9d5d98b..6c207e17768 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -54,6 +54,7 @@
#include "storage/sinvaladt.h"
#include "storage/smgr.h"
#include "storage/sync.h"
+#include "tcop/backend_startup.h"
#include "tcop/tcopprot.h"
#include "utils/acl.h"
#include "utils/builtins.h"
@@ -252,7 +253,7 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
- if (Log_connections)
+ if (log_connections & LOG_CONNECTION_AUTHORIZATION)
{
StringInfoData logmsg;
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index ad25cbb39c5..d95e6bb9e4b 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -1219,15 +1219,6 @@ struct config_bool ConfigureNamesBool[] =
true,
NULL, NULL, NULL
},
- {
- {"log_connections", PGC_SU_BACKEND, LOGGING_WHAT,
- gettext_noop("Logs each successful connection."),
- NULL
- },
- &Log_connections,
- false,
- NULL, NULL, NULL
- },
{
{"trace_connection_negotiation", PGC_POSTMASTER, DEVELOPER_OPTIONS,
gettext_noop("Logs details of pre-authentication connection handshake."),
@@ -4886,6 +4877,18 @@ struct config_string ConfigureNamesString[] =
NULL, NULL, NULL
},
+ {
+ {"log_connections", PGC_SU_BACKEND, LOGGING_WHAT,
+ gettext_noop("Logs specified aspects of connection establishment."),
+ NULL,
+ GUC_LIST_INPUT
+ },
+ &log_connections_string,
+ "",
+ check_log_connections, assign_log_connections, NULL
+ },
+
+
/* End-of-list marker */
{
{NULL, 0, 0, NULL, NULL}, NULL, NULL, NULL, NULL, NULL
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 2d1de9c37bd..c291c05d181 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -21,7 +21,7 @@
# require a server shutdown and restart to take effect.
#
# Any parameter can also be given as a command-line option to the server, e.g.,
-# "postgres -c log_connections=on". Some parameters can be changed at run time
+# "postgres -c log_connections=all". Some parameters can be changed at run time
# with the "SET" SQL command.
#
# Memory units: B = bytes Time units: us = microseconds
@@ -578,9 +578,11 @@
# actions running at least this number
# of milliseconds.
#log_checkpoints = on
-#log_connections = off
+#log_connections = '' # log aspects of connection setup
+ # options include receipt, authentication, authorization,
+ # and all to log all of these aspects
#log_disconnections = off
-#log_duration = off
+#log_duration = off # log statement duration
#log_error_verbosity = default # terse, default, or verbose messages
#log_hostname = off
#log_line_prefix = '%m [%p] ' # special values:
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index b6a3f275a1b..aa786bfacf3 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -63,7 +63,6 @@ extern PGDLLIMPORT char *ListenAddresses;
extern PGDLLIMPORT bool ClientAuthInProgress;
extern PGDLLIMPORT int PreAuthDelay;
extern PGDLLIMPORT int AuthenticationTimeout;
-extern PGDLLIMPORT bool Log_connections;
extern PGDLLIMPORT bool log_hostname;
extern PGDLLIMPORT bool enable_bonjour;
extern PGDLLIMPORT char *bonjour_name;
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 73285611203..e00851a004e 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -16,6 +16,8 @@
/* GUCs */
extern PGDLLIMPORT bool Trace_connection_negotiation;
+extern PGDLLIMPORT uint32 log_connections;
+extern PGDLLIMPORT char *log_connections_string;
/*
* CAC_state is passed from postmaster to the backend process, to indicate
@@ -39,6 +41,33 @@ typedef struct BackendStartupData
CAC_state canAcceptConnections;
} BackendStartupData;
+/*
+ * Granular control over which messages to log for the log_connections GUC.
+ *
+ * RECEIPT, AUTHENTICATION, and AUTHORIZATION are different aspects of
+ * connection establishment and backend setup for which we may emit a log
+ * message.
+ *
+ * ALL is a convenience alias equivalent to all of the above aspects.
+ *
+ * ON is backwards compatibility alias for the connection aspects that were
+ * logged in Postgres versions < 18.
+ */
+typedef enum LogConnectionOption
+{
+ LOG_CONNECTION_RECEIPT = (1 << 0),
+ LOG_CONNECTION_AUTHENTICATION = (1 << 1),
+ LOG_CONNECTION_AUTHORIZATION = (1 << 2),
+ LOG_CONNECTION_ON =
+ LOG_CONNECTION_RECEIPT |
+ LOG_CONNECTION_AUTHENTICATION |
+ LOG_CONNECTION_AUTHORIZATION,
+ LOG_CONNECTION_ALL =
+ LOG_CONNECTION_RECEIPT |
+ LOG_CONNECTION_AUTHENTICATION |
+ LOG_CONNECTION_AUTHORIZATION,
+} LogConnectionOption;
+
extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
#endif /* BACKEND_STARTUP_H */
diff --git a/src/include/utils/guc_hooks.h b/src/include/utils/guc_hooks.h
index 951451a9765..9a0d8ec85c7 100644
--- a/src/include/utils/guc_hooks.h
+++ b/src/include/utils/guc_hooks.h
@@ -51,6 +51,8 @@ extern bool check_datestyle(char **newval, void **extra, GucSource source);
extern void assign_datestyle(const char *newval, void *extra);
extern bool check_debug_io_direct(char **newval, void **extra, GucSource source);
extern void assign_debug_io_direct(const char *newval, void *extra);
+extern bool check_log_connections(char **newval, void **extra, GucSource source);
+extern void assign_log_connections(const char *newval, void *extra);
extern bool check_default_table_access_method(char **newval, void **extra,
GucSource source);
extern bool check_default_tablespace(char **newval, void **extra,
diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl
index 4ce22ccbdf2..e307dee5c48 100644
--- a/src/test/authentication/t/001_password.pl
+++ b/src/test/authentication/t/001_password.pl
@@ -7,6 +7,8 @@
# - MD5-encrypted
# - SCRAM-encrypted
# This test can only run with Unix-domain sockets.
+#
+# There's also a few tests of the log_connections GUC here.
use strict;
use warnings FATAL => 'all';
@@ -66,6 +68,42 @@ $node->init;
$node->append_conf('postgresql.conf', "log_connections = on\n");
$node->start;
+# Test behavior of log_connections GUC
+#
+# There wasn't another test file where these tests obviously fit, and we don't
+# want to incur the cost of spinning up a new cluster just to test one GUC.
+
+# Make a database for the log_connections tests to avoid test fragility if
+# other tests are added to this file in the future
+$node->safe_psql('postgres', "CREATE DATABASE test_log_connections");
+
+$node->safe_psql('test_log_connections',
+ q[ALTER SYSTEM SET log_connections = receipt,authorization;
+ SELECT pg_reload_conf();]);
+
+$node->connect_ok('test_log_connections',
+ q(log_connections with subset of specified options logs only those aspects),
+ log_like => [
+ qr/connection received/,
+ qr/connection authorized: user=\S+ database=test_log_connections/,
+ ],
+ log_unlike => [
+ qr/connection authenticated/,
+ ],);
+
+$node->safe_psql('test_log_connections',
+ qq(ALTER SYSTEM SET log_connections = 'all'; SELECT pg_reload_conf();));
+
+$node->connect_ok('test_log_connections',
+ qq(log_connections 'all' logs all available connection aspects),
+ log_like => [
+ qr/connection received/,
+ qr/connection authenticated/,
+ qr/connection authorized: user=\S+ database=test_log_connections/,
+ ],);
+
+# Authentication tests
+
# could fail in FIPS mode
my $md5_works = ($node->psql('postgres', "select md5('')") == 0);
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index dfe2690bdd3..9e7f58adb18 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -1556,6 +1556,7 @@ LockTupleMode
LockViewRecurse_context
LockWaitPolicy
LockingClause
+LogConnectionOption
LogOpts
LogStmtLevel
LogicalDecodeBeginCB
--
2.34.1
From f307fb571230e8aa452a19d68a25933f500df4f4 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <melanieplage...@gmail.com>
Date: Wed, 5 Mar 2025 18:05:19 -0500
Subject: [PATCH v14 2/2] Add connection establishment duration logging
Add log_connections option 'setup_durations' which logs durations of
several key parts of connection establishment and backend setup.
For an incoming connection, starting from when the postmaster gets a
socket from accept() and ending when the forked child backend is first
ready for query, there are multiple steps that could each take longer
than expected due to external factors. This logging provides visibility
into authentication and fork duration as well as the end-to-end
connection establishment and backend initialization time.
To make this portable, the timings captured in the postmaster (socket
creation time, fork initiation time) are passed through the
BackendStartupData.
Author: Melanie Plageman <melanieplage...@gmail.com>
Reviewed-by: Bertrand Drouvot <bertranddrouvot...@gmail.com>
Reviewed-by: Fujii Masao <masao.fu...@oss.nttdata.com>
Reviewed-by: Daniel Gustafsson <dan...@yesql.se>
Reviewed-by: Jacob Champion <jacob.champ...@enterprisedb.com>
Reviewed-by: Jelte Fennema-Nio <postg...@jeltef.nl>
Reviewed-by: Guillaume Lelarge <guillaume.lela...@dalibo.com>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
doc/src/sgml/config.sgml | 13 +++++
src/backend/postmaster/launch_backend.c | 31 ++++++++++
src/backend/postmaster/postmaster.c | 6 ++
src/backend/tcop/backend_startup.c | 11 ++++
src/backend/tcop/postgres.c | 33 +++++++++++
src/backend/utils/init/postinit.c | 6 ++
src/backend/utils/misc/postgresql.conf.sample | 2 +-
src/include/miscadmin.h | 7 +++
src/include/tcop/backend_startup.h | 57 +++++++++++++++++--
src/include/utils/timestamp.h | 9 +++
src/test/authentication/t/001_password.pl | 18 +++++-
src/tools/pgindent/typedefs.list | 1 +
12 files changed, 188 insertions(+), 6 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index d939d99d6e8..403d959ab30 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7369,6 +7369,19 @@ local0.* /var/log/postgresql
</entry>
</row>
+ <row>
+ <entry><literal>setup_durations</literal></entry>
+ <entry>
+ Logs the time spent establishing the connection and setting up the
+ backend at the time the connection is ready to execute its first
+ query. The log message includes the total setup duration, starting
+ from the postmaster accepting the incoming connection and ending
+ when the connection is ready for query. It also includes the time
+ it took to fork the new backend and the time it took to
+ authenticate the user.
+ </entry>
+ </row>
+
<row>
<entry><literal>all</literal></entry>
<entry>
diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c
index 47375e5bfaa..74b0c33adaa 100644
--- a/src/backend/postmaster/launch_backend.c
+++ b/src/backend/postmaster/launch_backend.c
@@ -232,6 +232,10 @@ postmaster_child_launch(BackendType child_type, int child_slot,
Assert(IsPostmasterEnvironment && !IsUnderPostmaster);
+ /* Capture time Postmaster initiates process creation for logging */
+ if (IsConnectionBackend(child_type))
+ ((BackendStartupData *) startup_data)->fork_started = GetCurrentTimestamp();
+
#ifdef EXEC_BACKEND
pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
startup_data, startup_data_len, client_sock);
@@ -240,6 +244,16 @@ postmaster_child_launch(BackendType child_type, int child_slot,
pid = fork_process();
if (pid == 0) /* child */
{
+ /* Capture and transfer timings that may be needed for logging */
+ if (IsConnectionBackend(child_type))
+ {
+ conn_timing.socket_create =
+ ((BackendStartupData *) startup_data)->socket_created;
+ conn_timing.fork_start =
+ ((BackendStartupData *) startup_data)->fork_started;
+ conn_timing.fork_end = GetCurrentTimestamp();
+ }
+
/* Close the postmaster's sockets */
ClosePostmasterPorts(child_type == B_LOGGER);
@@ -586,11 +600,18 @@ SubPostmasterMain(int argc, char *argv[])
char *child_kind;
BackendType child_type;
bool found = false;
+ TimestampTz fork_end;
/* In EXEC_BACKEND case we will not have inherited these settings */
IsPostmasterEnvironment = true;
whereToSendOutput = DestNone;
+ /*
+ * Capture the end of process creation for logging. We don't include the
+ * time spent copying data from shared memory and setting up the backend.
+ */
+ fork_end = GetCurrentTimestamp();
+
/* Setup essential subsystems (to ensure elog() behaves sanely) */
InitializeGUCOptions();
@@ -648,6 +669,16 @@ SubPostmasterMain(int argc, char *argv[])
/* Read in remaining GUC variables */
read_nondefault_variables();
+ /* Capture and transfer timings that may be needed for log_connections */
+ if (IsConnectionBackend(child_type))
+ {
+ conn_timing.socket_create =
+ ((BackendStartupData *) startup_data)->socket_created;
+ conn_timing.fork_start =
+ ((BackendStartupData *) startup_data)->fork_started;
+ conn_timing.fork_end = fork_end;
+ }
+
/*
* Check that the data directory looks valid, which will also check the
* privileges on the data directory and update our umask and file/group
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index b4f34c57a1b..57155c00e01 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -3477,6 +3477,12 @@ BackendStartup(ClientSocket *client_sock)
BackendStartupData startup_data;
CAC_state cac;
+ /*
+ * Capture time that Postmaster got a socket from accept (for logging
+ * connection establishment and setup total duration).
+ */
+ startup_data.socket_created = GetCurrentTimestamp();
+
/*
* Allocate and assign the child slot. Note we must do this before
* forking, so that we can handle failures (out of memory or child-process
diff --git a/src/backend/tcop/backend_startup.c b/src/backend/tcop/backend_startup.c
index 962b6e60002..27c0b3c2b04 100644
--- a/src/backend/tcop/backend_startup.c
+++ b/src/backend/tcop/backend_startup.c
@@ -46,6 +46,16 @@ bool Trace_connection_negotiation = false;
uint32 log_connections = 0;
char *log_connections_string = NULL;
+/* Other globals */
+
+/*
+ * ConnectionTiming stores timestamps of various points in connection
+ * establishment and setup.
+ * ready_for_use is initialized to a special value here so we can check if
+ * we've already set it before doing so in PostgresMain().
+ */
+ConnectionTiming conn_timing = {.ready_for_use = TIMESTAMP_MINUS_INFINITY};
+
static void BackendInitialize(ClientSocket *client_sock, CAC_state cac);
static int ProcessSSLStartup(Port *port);
static int ProcessStartupPacket(Port *port, bool ssl_done, bool gss_done);
@@ -1006,6 +1016,7 @@ validate_log_connections_options(List *elemlist, uint32 *flags)
{"receipt", LOG_CONNECTION_RECEIPT},
{"authentication", LOG_CONNECTION_AUTHENTICATION},
{"authorization", LOG_CONNECTION_AUTHORIZATION},
+ {"setup_durations", LOG_CONNECTION_SETUP_DURATIONS},
{"all", LOG_CONNECTION_ALL},
};
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 947ffb40421..f2cae40b53d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -66,6 +66,7 @@
#include "storage/proc.h"
#include "storage/procsignal.h"
#include "storage/sinval.h"
+#include "tcop/backend_startup.h"
#include "tcop/fastpath.h"
#include "tcop/pquery.h"
#include "tcop/tcopprot.h"
@@ -4607,6 +4608,38 @@ PostgresMain(const char *dbname, const char *username)
/* Report any recently-changed GUC options */
ReportChangedGUCOptions();
+ /*
+ * The first time this backend is ready for query, log the
+ * durations of the different components of connection
+ * establishment and setup.
+ */
+ if (conn_timing.ready_for_use == TIMESTAMP_MINUS_INFINITY &&
+ (log_connections & LOG_CONNECTION_SETUP_DURATIONS) &&
+ IsConnectionBackend(MyBackendType))
+ {
+ uint64 total_duration,
+ fork_duration,
+ auth_duration;
+
+ conn_timing.ready_for_use = GetCurrentTimestamp();
+
+ total_duration =
+ TimestampDifferenceMicroseconds(conn_timing.socket_create,
+ conn_timing.ready_for_use);
+ fork_duration =
+ TimestampDifferenceMicroseconds(conn_timing.fork_start,
+ conn_timing.fork_end);
+ auth_duration =
+ TimestampDifferenceMicroseconds(conn_timing.auth_start,
+ conn_timing.auth_end);
+
+ ereport(LOG,
+ errmsg("connection ready: setup total=%.3f ms, fork=%.3f ms, authentication=%.3f ms",
+ (double) total_duration / NS_PER_US,
+ (double) fork_duration / NS_PER_US,
+ (double) auth_duration / NS_PER_US));
+ }
+
ReadyForQuery(whereToSendOutput);
send_ready_for_query = false;
}
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 6c207e17768..4b2faf1ba9d 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -235,6 +235,9 @@ PerformAuthentication(Port *port)
}
#endif
+ /* Capture authentication start time for logging */
+ conn_timing.auth_start = GetCurrentTimestamp();
+
/*
* Set up a timeout in case a buggy or malicious client fails to respond
* during authentication. Since we're inside a transaction and might do
@@ -253,6 +256,9 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Capture authentication end time for logging */
+ conn_timing.auth_end = GetCurrentTimestamp();
+
if (log_connections & LOG_CONNECTION_AUTHORIZATION)
{
StringInfoData logmsg;
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index c291c05d181..d2bd329a587 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -580,7 +580,7 @@
#log_checkpoints = on
#log_connections = '' # log aspects of connection setup
# options include receipt, authentication, authorization,
- # and all to log all of these aspects
+ # setup_durations, and all to log all of these aspects
#log_disconnections = off
#log_duration = off # log statement duration
#log_error_verbosity = default # terse, default, or verbose messages
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..312eb3f9529 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -394,6 +394,13 @@ extern PGDLLIMPORT BackendType MyBackendType;
(AmAutoVacuumLauncherProcess() || \
AmLogicalSlotSyncWorkerProcess())
+/*
+ * Backend types that are spawned by the postmaster to serve a client
+ * or replication connection.
+ */
+#define IsConnectionBackend(backend_type) \
+ (backend_type == B_BACKEND || backend_type == B_WAL_SENDER)
+
extern const char *GetBackendTypeDesc(BackendType backendType);
extern void SetDatabasePath(const char *path);
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index e00851a004e..2912ef80288 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -14,11 +14,16 @@
#ifndef BACKEND_STARTUP_H
#define BACKEND_STARTUP_H
+#include "utils/timestamp.h"
+
/* GUCs */
extern PGDLLIMPORT bool Trace_connection_negotiation;
extern PGDLLIMPORT uint32 log_connections;
extern PGDLLIMPORT char *log_connections_string;
+/* Other globals */
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
/*
* CAC_state is passed from postmaster to the backend process, to indicate
* whether the connection should be accepted, or if the process should just
@@ -39,14 +44,27 @@ typedef enum CAC_state
typedef struct BackendStartupData
{
CAC_state canAcceptConnections;
+
+ /*
+ * Time at which the connection client socket is created. Only used for
+ * client and wal sender connections.
+ */
+ TimestampTz socket_created;
+
+ /*
+ * Time at which the postmaster initiates process creation -- either
+ * through fork or otherwise. Only used for client and wal sender
+ * connections.
+ */
+ TimestampTz fork_started;
} BackendStartupData;
/*
* Granular control over which messages to log for the log_connections GUC.
*
- * RECEIPT, AUTHENTICATION, and AUTHORIZATION are different aspects of
- * connection establishment and backend setup for which we may emit a log
- * message.
+ * RECEIPT, AUTHENTICATION, AUTHORIZATION, and SETUP_DURATIONS are different
+ * aspects of connection establishment and backend setup for which we may emit
+ * a log message.
*
* ALL is a convenience alias equivalent to all of the above aspects.
*
@@ -58,6 +76,7 @@ typedef enum LogConnectionOption
LOG_CONNECTION_RECEIPT = (1 << 0),
LOG_CONNECTION_AUTHENTICATION = (1 << 1),
LOG_CONNECTION_AUTHORIZATION = (1 << 2),
+ LOG_CONNECTION_SETUP_DURATIONS = (1 << 3),
LOG_CONNECTION_ON =
LOG_CONNECTION_RECEIPT |
LOG_CONNECTION_AUTHENTICATION |
@@ -65,9 +84,39 @@ typedef enum LogConnectionOption
LOG_CONNECTION_ALL =
LOG_CONNECTION_RECEIPT |
LOG_CONNECTION_AUTHENTICATION |
- LOG_CONNECTION_AUTHORIZATION,
+ LOG_CONNECTION_AUTHORIZATION |
+ LOG_CONNECTION_SETUP_DURATIONS,
} LogConnectionOption;
+/*
+ * A collection of timings of various stages of connection establishment and
+ * setup for client backends and WAL senders.
+ *
+ * Used to emit the setup_durations log message for the log_connections GUC.
+ */
+typedef struct ConnectionTiming
+{
+ /*
+ * The time at which the client socket is created and the time at which
+ * the connection is fully set up and first ready for query. Together
+ * these represent the total connection establishment and setup time.
+ */
+ TimestampTz socket_create;
+ TimestampTz ready_for_use;
+
+ /* Time at which process creation was initiated */
+ TimestampTz fork_start;
+
+ /* Time at which process creation was completed */
+ TimestampTz fork_end;
+
+ /* Time at which authentication started */
+ TimestampTz auth_start;
+
+ /* Time at which authentication was finished */
+ TimestampTz auth_end;
+} ConnectionTiming;
+
extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
#endif /* BACKEND_STARTUP_H */
diff --git a/src/include/utils/timestamp.h b/src/include/utils/timestamp.h
index 9963bddc0ec..8c205859c3b 100644
--- a/src/include/utils/timestamp.h
+++ b/src/include/utils/timestamp.h
@@ -85,6 +85,15 @@ IntervalPGetDatum(const Interval *X)
#define TimestampTzPlusMilliseconds(tz,ms) ((tz) + ((ms) * (int64) 1000))
#define TimestampTzPlusSeconds(tz,s) ((tz) + ((s) * (int64) 1000000))
+/* Helper for simple subtraction between two timestamps */
+static inline uint64
+TimestampDifferenceMicroseconds(TimestampTz start_time,
+ TimestampTz stop_time)
+{
+ if (start_time >= stop_time)
+ return 0;
+ return (uint64) stop_time - start_time;
+}
/* Set at postmaster start */
extern PGDLLIMPORT TimestampTz PgStartTime;
diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl
index e307dee5c48..8269c470b59 100644
--- a/src/test/authentication/t/001_password.pl
+++ b/src/test/authentication/t/001_password.pl
@@ -77,8 +77,22 @@ $node->start;
# other tests are added to this file in the future
$node->safe_psql('postgres', "CREATE DATABASE test_log_connections");
+my $log_connections = $node->safe_psql('test_log_connections', q(SHOW log_connections;));
+is($log_connections, 'on', qq(check log connections has expected value 'on'));
+
+$node->connect_ok('test_log_connections',
+ qq(log_connections 'on' works as expected for backwards compatibility),
+ log_like => [
+ qr/connection received/,
+ qr/connection authenticated/,
+ qr/connection authorized: user=\S+ database=test_log_connections/,
+ ],
+ log_unlike => [
+ qr/connection ready/,
+ ],);
+
$node->safe_psql('test_log_connections',
- q[ALTER SYSTEM SET log_connections = receipt,authorization;
+ q[ALTER SYSTEM SET log_connections = receipt,authorization,setup_durations;
SELECT pg_reload_conf();]);
$node->connect_ok('test_log_connections',
@@ -86,6 +100,7 @@ $node->connect_ok('test_log_connections',
log_like => [
qr/connection received/,
qr/connection authorized: user=\S+ database=test_log_connections/,
+ qr/connection ready/,
],
log_unlike => [
qr/connection authenticated/,
@@ -100,6 +115,7 @@ $node->connect_ok('test_log_connections',
qr/connection received/,
qr/connection authenticated/,
qr/connection authorized: user=\S+ database=test_log_connections/,
+ qr/connection ready/,
],);
# Authentication tests
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 9e7f58adb18..a2e592dbbbb 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -484,6 +484,7 @@ ConnParams
ConnStatusType
ConnType
ConnectionStateEnum
+ConnectionTiming
ConsiderSplitContext
Const
ConstrCheck
--
2.34.1
