Thanks for the continued review!
Attached v11 has a test added (passes locally but fails in CI, so I
have to fix that).
I still need to do some more manual testing and validation.
On Thu, Mar 6, 2025 at 9:56 AM Bertrand Drouvot
<bertranddrouvot...@gmail.com> wrote:
>
<-- snip -->
> what do you think about also doing?
>
> static const struct config_enum_entry compat_options[] = {
> - {"off", 0},
> - {"false", 0},
> - {"no", 0},
> - {"0", 0},
> + {"off", LOG_CONNECTION_OFF},
> + {"false", LOG_CONNECTION_OFF},
> + {"no", LOG_CONNECTION_OFF},
> + {"0", LOG_CONNECTION_OFF},
>
> and
>
> typedef enum LogConnectionOption
> {
> + LOG_CONNECTION_OFF = 0,
> LOG_CONNECTION_RECEIVED = (1 << 0),
> and
>
> /* If an empty string was passed, we're done. */
> if (list_length(elemlist) == 0)
> return LOG_CONNECTION_OFF;
Yes, I do notice that most GUCs with enums that have an "off" switch
also have a "NONE" or "OFF" enumeration value. This is to contrast it
with a GUC that doesn't have an "off" switch (like wal_level). So, I
think you're right that we should have something to indicate you can
turn off log_connections.
However, I was a bit torn about LOG_CONNECTION_OFF vs
LOG_CONNECTION_NONE. We have LOG_CONNECTION_ON because it is a
legitimately distinct alias for the log messages emitted by < pg 18
when log_connections == on. However, LOG_CONNECTION_NONE and
LOG_CONNECTION_OFF would be the same. As such, I prefer
LOG_CONNECTION_NONE because it makes more sense in the context of
where the enumeration is defined. I've added this and used it in the
compat_options array. What do you think? Is it too confusing?
> - if (Log_connections && status == STATUS_OK &&
> + if (log_connections & LOG_CONNECTION_AUTHENTICATED &&
> + status == STATUS_OK &&
>
> Worth to add extra parentheses around (log_connections &
> LOG_CONNECTION_AUTHENTICATED)?
>
> Not necessary as bitwise AND has higher precedence than logical AND but I
> think
> it makes the code more readable.
Done in all places (I think).
> + /* If an empty string was passed, we're done. */
> + if (list_length(elemlist) == 0)
> + return 0;
> +
< -- snip -->
> what about storing the list_length(elemlist) at the start to avoid the
> multiple
> list_length(elemlist) calls?
Since it would only be called twice and it has the length stored in
the List struct, I prefer it as is -- without an extra local variable.
> + /* If an empty string was passed, we're done. */
>
> s/done./done/? (Looking at the one line comments around)
I've addressed all of these comment punctuations you've mentioned. Thanks!
> === 6
>
> + /* For backwards compatability, we accept these tokens by themselves
> */
>
> Typo: compatability/compatibility
Whoops! Thanks. I forgot to spell check my commit message. Done that now too.
How do you find spelling mistakes in patches usually? I tried `git
show | aspell list` -- but of course that includes lots of variables
and such that aren't actually spelling mistakes.
> + /* Time for cleanup and allocating `extra` if we succeeded */
> + pfree(rawstring);
> + list_free(elemlist);
> +
> + /* We didn't succeed */
> + if (flags == -1)
> + return false;
>
> I feel the first comment is confusing, maybe the "allocating `extra` if we
> succeeded"
> should be put after the "if (flags == -1)" part?
Fixed.
> > In 0002, because we take the timings for all wal sender and client
> > connection backends, now the new log message emitted in 0002 is more
> > like a stage, so I've named that option "ready_for_query". As such, I
> > wonder if I should change the output message to reflect that. What do
> > you think?
>
> hmm, I'm tempted to vote for "timings". I understand your point but "timings"
> more directly communicates that this option enables timing measurements,
> whereas "ready_for_query" describes just one particular state.
Well, I actually didn't want to call it "timings" because it implies
that we only measure the timings when it is specified. But we actually
get the timings unconditionally for client backends and wal sender.
Don't you think it is more confusing for the user if we call it
timings and users think if they don't include that timings aren't
measured?
I didn't change it in the attached version 11. I wanted to discuss
more before making that decision.
Also, I thought changing the message output to say "ready for query"
somewhere in it makes it more clear when that message is actually
emitted in a connection's lifetime. What do you think?
> I think I could vote for "ready_for_query" should the GUC be
> log_connection_stages
> (and not log_connections).
All the existing connection messages are at certain stages and fall in
this category. However, were we to add more that don't fall in that
category, we'd have to think about how to modularize them. I'm not
sure if we could mix connection stages and other assorted message
types easily without the groupings you've mentioned in the past. What
we don't want to do is make a change that makes that harder to do in
the future.
- Melanie
From f0040ff957176a3dec61cacc7771945e6e2ccf8d Mon Sep 17 00:00:00 2001
From: Melanie Plageman <melanieplage...@gmail.com>
Date: Wed, 5 Mar 2025 18:05:19 -0500
Subject: [PATCH v11 2/3] Add connection establishment duration logging
Add log_connections option 'ready_for_query' which logs durations of
several key parts of connection establishment and setup the first time
the backend is ready for query.
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 initialization time.
To make this portable, the timings captured in the postmaster (socket
creation time, fork initiation time) are passed through the
BackendStartupData instead of simply saved in backend local memory.
Author: Melanie Plageman <melanieplage...@gmail.com>
Reviewed-by: Bertrand Drouvot <bertranddrouvot...@gmail.com>
Reviewed-by: Fujii Masao <masao.fu...@oss.nttdata.com>
Reviewed-by: Jelte Fennema-Nio <postg...@jeltef.nl>
Reviewed-by: Jacob Champion <jacob.champ...@enterprisedb.com>
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 | 9 ++++
src/backend/postmaster/launch_backend.c | 39 ++++++++++++++++
src/backend/postmaster/postmaster.c | 6 +++
src/backend/tcop/backend_startup.c | 1 +
src/backend/tcop/postgres.c | 22 +++++++++
src/backend/utils/init/globals.c | 3 ++
src/backend/utils/init/postinit.c | 8 ++++
src/include/miscadmin.h | 9 ++++
src/include/portability/instr_time.h | 9 ++++
src/include/tcop/backend_startup.h | 45 +++++++++++++++++--
.../postmaster/t/002_connection_limits.pl | 8 +++-
src/tools/pgindent/typedefs.list | 1 +
12 files changed, 156 insertions(+), 4 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index b97707a7ec2..f424b3f215b 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7362,6 +7362,15 @@ local0.* /var/log/postgresql
</entry>
</row>
+ <row>
+ <entry><literal>ready_for_query</literal></entry>
+ <entry>
+ Logs the duration of connection establishment and setup as well as
+ several establishment component durations. At this point, the
+ backend is ready for query.
+ </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..097605b4070 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 fork for logging */
+ if (IsConnectionBackend(child_type))
+ INSTR_TIME_SET_CURRENT(((BackendStartupData *) startup_data)->fork_started);
+
#ifdef EXEC_BACKEND
pid = internal_forkexec(child_process_kinds[child_type].name, child_slot,
startup_data, startup_data_len, client_sock);
@@ -240,6 +244,21 @@ postmaster_child_launch(BackendType child_type, int child_slot,
pid = fork_process();
if (pid == 0) /* child */
{
+ /*
+ * Transfer over any timing data captured by postmaster that may be
+ * needed for log_connections.
+ */
+ if (IsConnectionBackend(child_type))
+ {
+ BackendStartupData *data = (BackendStartupData *) startup_data;
+
+ /* Calculate fork duration since we have start and end times */
+ conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(data->fork_started);
+
+ /* Will be used to calculate total connection setup duration */
+ conn_timing.creation_time = data->socket_created;
+ }
+
/* Close the postmaster's sockets */
ClosePostmasterPorts(child_type == B_LOGGER);
@@ -586,6 +605,7 @@ SubPostmasterMain(int argc, char *argv[])
char *child_kind;
BackendType child_type;
bool found = false;
+ instr_time fork_ended;
/* In EXEC_BACKEND case we will not have inherited these settings */
IsPostmasterEnvironment = true;
@@ -615,6 +635,9 @@ SubPostmasterMain(int argc, char *argv[])
if (!found)
elog(ERROR, "unknown child kind %s", child_kind);
+ if (IsConnectionBackend(child_type))
+ INSTR_TIME_SET_CURRENT(fork_ended);
+
/* Read in the variables file */
read_backend_variables(argv[2], &startup_data, &startup_data_len);
@@ -648,6 +671,22 @@ SubPostmasterMain(int argc, char *argv[])
/* Read in remaining GUC variables */
read_nondefault_variables();
+ /*
+ * Transfer over any timing data captured by postmaster that may be needed
+ * for log_connections.
+ */
+ if (IsConnectionBackend(child_type))
+ {
+ BackendStartupData *data = (BackendStartupData *) startup_data;
+
+ /* Calculate fork duration since we have start and end times */
+ conn_timing.fork_duration = fork_ended;
+ INSTR_TIME_SUBTRACT(conn_timing.fork_duration, data->fork_started);
+
+ /* Will be used to calculate total connection setup duration */
+ conn_timing.creation_time = data->socket_created;
+ }
+
/*
* 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..d46ffa34151 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).
+ */
+ INSTR_TIME_SET_CURRENT(startup_data.socket_created);
+
/*
* 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 84db47231f6..399562bb599 100644
--- a/src/backend/tcop/backend_startup.c
+++ b/src/backend/tcop/backend_startup.c
@@ -997,6 +997,7 @@ validate_log_connections_options(List *elemlist)
{"received", LOG_CONNECTION_RECEIVED},
{"authenticated", LOG_CONNECTION_AUTHENTICATED},
{"authorized", LOG_CONNECTION_AUTHORIZED},
+ {"ready_for_query", LOG_CONNECTION_READY_FOR_QUERY},
{"all", LOG_CONNECTION_ALL},
};
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 947ffb40421..4e74f309c47 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"
@@ -4153,6 +4154,7 @@ PostgresMain(const char *dbname, const char *username)
volatile bool send_ready_for_query = true;
volatile bool idle_in_transaction_timeout_enabled = false;
volatile bool idle_session_timeout_enabled = false;
+ bool reported_first_ready_for_query = false;
Assert(dbname != NULL);
Assert(username != NULL);
@@ -4607,6 +4609,26 @@ 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.
+ */
+ if (!reported_first_ready_for_query &&
+ (log_connections & LOG_CONNECTION_READY_FOR_QUERY) &&
+ IsConnectionBackend(MyBackendType))
+ {
+ instr_time total_duration =
+ INSTR_TIME_GET_DURATION_SINCE(conn_timing.creation_time);
+
+ ereport(LOG,
+ errmsg("connection ready for query. durations (ms): total: %.3f, fork: %.3f, authentication: %.3f",
+ (double) INSTR_TIME_GET_NANOSEC(total_duration) / NS_PER_MS,
+ (double) INSTR_TIME_GET_NANOSEC(conn_timing.fork_duration) / NS_PER_MS,
+ (double) INSTR_TIME_GET_NANOSEC(conn_timing.auth_duration) / NS_PER_MS));
+
+ reported_first_ready_for_query = true;
+ }
ReadyForQuery(whereToSendOutput);
send_ready_for_query = false;
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index b844f9fdaef..9c59f31fc84 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -24,6 +24,7 @@
#include "miscadmin.h"
#include "postmaster/postmaster.h"
#include "storage/procnumber.h"
+#include "tcop/backend_startup.h"
ProtocolVersion FrontendProtocol;
@@ -43,6 +44,8 @@ volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
+ConnectionTiming conn_timing = {0};
+
int MyProcPid;
pg_time_t MyStartTime;
TimestampTz MyStartTimestamp;
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index dc6484bb092..7c1ab501395 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -192,9 +192,14 @@ GetDatabaseTupleByOid(Oid dboid)
static void
PerformAuthentication(Port *port)
{
+ instr_time auth_start_time;
+
/* This should be set already, but let's make sure */
ClientAuthInProgress = true; /* limit visibility of log messages */
+ /* Capture authentication start time for logging */
+ INSTR_TIME_SET_CURRENT(auth_start_time);
+
/*
* In EXEC_BACKEND case, we didn't inherit the contents of pg_hba.conf
* etcetera from the postmaster, and have to load them ourselves.
@@ -253,6 +258,9 @@ PerformAuthentication(Port *port)
*/
disable_timeout(STATEMENT_TIMEOUT, false);
+ /* Calculate authentication duration for logging */
+ conn_timing.auth_duration = INSTR_TIME_GET_DURATION_SINCE(auth_start_time);
+
if (log_connections & LOG_CONNECTION_AUTHORIZED)
{
StringInfoData logmsg;
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index a2b63495eec..ec5ed2235e6 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -178,6 +178,8 @@ extern PGDLLIMPORT int MaxConnections;
extern PGDLLIMPORT int max_worker_processes;
extern PGDLLIMPORT int max_parallel_workers;
+extern PGDLLIMPORT struct ConnectionTiming conn_timing;
+
extern PGDLLIMPORT int commit_timestamp_buffers;
extern PGDLLIMPORT int multixact_member_buffers;
extern PGDLLIMPORT int multixact_offset_buffers;
@@ -394,6 +396,13 @@ extern PGDLLIMPORT BackendType MyBackendType;
(AmAutoVacuumLauncherProcess() || \
AmLogicalSlotSyncWorkerProcess())
+/*
+ * Backend types that are spawned by the postmaster to serve a client
+ * 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/portability/instr_time.h b/src/include/portability/instr_time.h
index f71a851b18d..48d7ff1bfad 100644
--- a/src/include/portability/instr_time.h
+++ b/src/include/portability/instr_time.h
@@ -184,6 +184,15 @@ GetTimerFrequency(void)
#define INSTR_TIME_ACCUM_DIFF(x,y,z) \
((x).ticks += (y).ticks - (z).ticks)
+static inline instr_time
+INSTR_TIME_GET_DURATION_SINCE(instr_time start_time)
+{
+ instr_time now;
+
+ INSTR_TIME_SET_CURRENT(now);
+ INSTR_TIME_SUBTRACT(now, start_time);
+ return now;
+}
#define INSTR_TIME_GET_DOUBLE(t) \
((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S)
diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h
index 66d370c1e00..d4ad9f69086 100644
--- a/src/include/tcop/backend_startup.h
+++ b/src/include/tcop/backend_startup.h
@@ -14,6 +14,8 @@
#ifndef BACKEND_STARTUP_H
#define BACKEND_STARTUP_H
+#include "portability/instr_time.h"
+
/* GUCs */
extern PGDLLIMPORT bool Trace_connection_negotiation;
extern PGDLLIMPORT int log_connections;
@@ -39,13 +41,25 @@ typedef enum CAC_state
typedef struct BackendStartupData
{
CAC_state canAcceptConnections;
+
+ /*
+ * Time at which the postmaster initiates a fork of a backend process.
+ * Only used for client and wal sender connections.
+ */
+ instr_time fork_started;
+
+ /*
+ * Time at which the connection client socket is created. Only used for
+ * client and wal sender connections.
+ */
+ instr_time socket_created;
} BackendStartupData;
/*
* Granular control over which messages to log for the log_connections GUC.
*
- * RECEIVED, AUTHENTICATED, and AUTHORIZED are different stages of connection
- * establishment and setup where we may emit a log message.
+ * RECEIVED, AUTHENTICATED, AUTHORIZED, and READY_FOR_QUERY are different
+ * stages of connection establishment and setup where we may emit a log message.
*
* ALL is a convenience alias for when all stages should be logged.
*
@@ -60,14 +74,39 @@ typedef enum LogConnectionOption
LOG_CONNECTION_RECEIVED = (1 << 0),
LOG_CONNECTION_AUTHENTICATED = (1 << 1),
LOG_CONNECTION_AUTHORIZED = (1 << 2),
+ LOG_CONNECTION_READY_FOR_QUERY = (1 << 3),
LOG_CONNECTION_ON =
LOG_CONNECTION_RECEIVED |
LOG_CONNECTION_AUTHENTICATED |
LOG_CONNECTION_AUTHORIZED,
LOG_CONNECTION_ALL =
- LOG_CONNECTION_ON,
+ LOG_CONNECTION_ON |
+ LOG_CONNECTION_READY_FOR_QUERY,
} LogConnectionOption;
+/*
+ * A collection of timings and durations of various stages of connection
+ * establishment and setup for client backends and WAL senders.
+ *
+ * Used to emit log messages according to the options specified in the
+ * log_connections GUC.
+ */
+typedef struct ConnectionTiming
+{
+ /*
+ * The time at which the client socket is created. This is used to log the
+ * total connection establishment and setup time from accept() to first
+ * being ready for query.
+ */
+ instr_time creation_time;
+
+ /* How long it took the backend to be forked */
+ instr_time fork_duration;
+
+ /* How long authentication took */
+ instr_time auth_duration;
+} ConnectionTiming;
+
extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn();
#endif /* BACKEND_STARTUP_H */
diff --git a/src/test/postmaster/t/002_connection_limits.pl b/src/test/postmaster/t/002_connection_limits.pl
index f19d6e73ac9..de35d85e23e 100644
--- a/src/test/postmaster/t/002_connection_limits.pl
+++ b/src/test/postmaster/t/002_connection_limits.pl
@@ -29,11 +29,12 @@ $node->connect_ok("",
qr/connection received/,
qr/connection authenticated/,
qr/connection authorized/,
+ qr/connection ready for query/,
],);
$node->safe_psql(
'postgres',
- q[ALTER SYSTEM SET log_connections = received,authorized;
+ q[ALTER SYSTEM SET log_connections = received,authorized,ready_for_query;
SELECT pg_reload_conf();]);
$node->connect_ok("",
@@ -41,6 +42,7 @@ $node->connect_ok("",
log_like => [
qr/connection received/,
qr/connection authorized/,
+ qr/connection ready for query/,
],
log_unlike => [
qr/connection authenticated/,
@@ -56,6 +58,9 @@ $node->connect_ok("",
qr/connection received/,
qr/connection authenticated/,
qr/connection authorized/,
+ ],
+ log_unlike => [
+ qr/connection ready for query/,
],);
$node->safe_psql(
@@ -68,6 +73,7 @@ $node->connect_ok("",
qr/connection received/,
qr/connection authenticated/,
qr/connection authorized/,
+ qr/connection ready for query/,
],);
$node->safe_psql(
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 29e52b64994..3da74999634 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
From 2fb563dc2f95ff50bf492340cd1e1d10aa45eb94 Mon Sep 17 00:00:00 2001
From: Melanie Plageman <melanieplage...@gmail.com>
Date: Wed, 5 Mar 2025 18:02:45 -0500
Subject: [PATCH v11 1/3] Modularize log_connections output
Convert the boolean log_connections GUC into a list GUC of the
connection stages to log.
The current log_connections options are 'received', 'authenticated', and
'authorized'. The empty string disables all connection logging. 'all'
enables all available connection logging.
This gives users more control over the volume of connection logging.
For backwards compatibility, the most common values for the
log_connections boolean are still supported ('on', 'off', 1, 0, true,
false).
This patch has much of the same behavior as [1] but was developed
independently.
[1] https://postgr.es/m/flat/CAA8Fd-qCB96uwfgMKrzfNs32mqqysi53yZFNVaRNJ6xDthZEgA%40mail.gmail.com
Author: Melanie Plageman <melanieplage...@gmail.com>
Reviewed-by: Bertrand Drouvot <bertranddrouvot...@gmail.com>
Reviewed-by: Fujii Masao <masao.fu...@oss.nttdata.com>
Discussion: https://postgr.es/m/flat/CAAKRu_b_smAHK0ZjrnL5GRxnAVWujEXQWpLXYzGbmpcZd3nLYw%40mail.gmail.com
---
doc/src/sgml/config.sgml | 71 +++++++-
src/backend/libpq/auth.c | 9 +-
src/backend/postmaster/postmaster.c | 1 -
src/backend/tcop/backend_startup.c | 152 +++++++++++++++++-
src/backend/utils/init/postinit.c | 3 +-
src/backend/utils/misc/guc_tables.c | 21 +--
src/backend/utils/misc/postgresql.conf.sample | 4 +-
src/include/postmaster/postmaster.h | 1 -
src/include/tcop/backend_startup.h | 29 ++++
src/include/utils/guc_hooks.h | 2 +
.../postmaster/t/002_connection_limits.pl | 50 +++++-
src/tools/pgindent/typedefs.list | 1 +
12 files changed, 319 insertions(+), 25 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index d2fa5f7d1a9..b97707a7ec2 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7315,20 +7315,81 @@ 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 the specified stages 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 are the options
+ that may be specified:
+ </para>
+
+ <table id="log-connections-stages">
+ <title>Log Connection Stages</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>received</literal></entry>
+ <entry>Logs receipt of a connection.</entry>
+ </row>
+
+ <row>
+ <entry><literal>authenticated</literal></entry>
+ <entry>
+ Logs the original identity used by an authentication method to
+ identify a user. Failed authentication is always logged regardless
+ of the value of this setting.
+ </entry>
+ </row>
+
+ <row>
+ <entry><literal>authorized</literal></entry>
+ <entry>
+ Logs successful completion of authorization. At this point the
+ connection has been fully established.
+ </entry>
+ </row>
+
+ <row>
+ <entry><literal>all</literal></entry>
+ <entry>
+ A convenience alias. If specified, <literal>all</literal> must be
+ quoted because it is a <productname>PostgreSQL</productname>
+ keyword. If <literal>all</literal> is specified in a list of other
+ options, all connection logging will be enabled.
+ </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 emit logs for the
+ <literal>received</literal>, <literal>authenticated</literal>, and
+ <literal>authorized</literal> stages.
+ </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..066bc5254ee 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
+ * 'authenticated' 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_AUTHENTICATED)
{
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_AUTHENTICATED) &&
+ 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..84db47231f6 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;
+int 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 int validate_log_connections_options(List *elemlist);
/*
* 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_RECEIVED)
{
if (remote_port[0])
ereport(LOG,
@@ -924,3 +929,146 @@ StartupPacketTimeoutHandler(void)
{
_exit(1);
}
+
+/*
+ * Helper for the log_connections GUC check hook.
+ *
+ * `elemlist` is the listified string input passed to check_log_connections().
+ * check_log_connections() is responsible for cleaning up `elemlist`.
+ *
+ * validate_log_connections_options() returns the flags that should be stored
+ * in the log_connections GUC by the assign_hook or -1 if the input is not
+ * valid and we should error out.
+ */
+static int
+validate_log_connections_options(List *elemlist)
+{
+ int flags = 0;
+ ListCell *l;
+ char *item;
+
+ /* For backwards compatibility, we accept these tokens by themselves */
+ static const struct config_enum_entry compat_options[] = {
+ {"off", LOG_CONNECTION_NONE},
+ {"false", LOG_CONNECTION_NONE},
+ {"no", LOG_CONNECTION_NONE},
+ {"0", LOG_CONNECTION_NONE},
+ {"on", LOG_CONNECTION_ON},
+ {"true", LOG_CONNECTION_ON},
+ {"yes", LOG_CONNECTION_ON},
+ {"1", LOG_CONNECTION_ON},
+ };
+
+ /* If an empty string was passed, we're done */
+ if (list_length(elemlist) == 0)
+ return 0;
+
+ /*
+ * 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 -1;
+ }
+
+ return option.val;
+ }
+
+ /*
+ * Now check the stage-specific options. The empty string was already
+ * handled.
+ */
+ foreach(l, elemlist)
+ {
+ static const struct config_enum_entry options[] = {
+ {"received", LOG_CONNECTION_RECEIVED},
+ {"authenticated", LOG_CONNECTION_AUTHENTICATED},
+ {"authorized", LOG_CONNECTION_AUTHORIZED},
+ {"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 -1;
+
+next: ;
+ }
+
+ return flags;
+}
+
+
+/*
+ * GUC check hook for log_connections
+ */
+bool
+check_log_connections(char **newval, void **extra, GucSource source)
+{
+ int flags;
+ char *rawstring;
+ List *elemlist;
+
+ /* 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 */
+ flags = validate_log_connections_options(elemlist);
+
+ /* Time for cleanup */
+ pfree(rawstring);
+ list_free(elemlist);
+
+ /* We didn't succeed */
+ if (flags == -1)
+ 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..dc6484bb092 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_AUTHORIZED)
{
StringInfoData logmsg;
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index ad25cbb39c5..71070465379 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 information about events during 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..aca610f4fad 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,7 +578,7 @@
# actions running at least this number
# of milliseconds.
#log_checkpoints = on
-#log_connections = off
+#log_connections = ''
#log_disconnections = off
#log_duration = off
#log_error_verbosity = default # terse, default, or verbose messages
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..66d370c1e00 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 int 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.
+ *
+ * RECEIVED, AUTHENTICATED, and AUTHORIZED are different stages of connection
+ * establishment and setup where we may emit a log message.
+ *
+ * ALL is a convenience alias for when all stages should be logged.
+ *
+ * NONE is an alias for when no connection logging should be done.
+ *
+ * ON is backwards compatibility alias for the connection events that were
+ * logged in Postgres versions < 18.
+ */
+typedef enum LogConnectionOption
+{
+ LOG_CONNECTION_NONE = 0,
+ LOG_CONNECTION_RECEIVED = (1 << 0),
+ LOG_CONNECTION_AUTHENTICATED = (1 << 1),
+ LOG_CONNECTION_AUTHORIZED = (1 << 2),
+ LOG_CONNECTION_ON =
+ LOG_CONNECTION_RECEIVED |
+ LOG_CONNECTION_AUTHENTICATED |
+ LOG_CONNECTION_AUTHORIZED,
+ LOG_CONNECTION_ALL =
+ LOG_CONNECTION_ON,
+} 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/postmaster/t/002_connection_limits.pl b/src/test/postmaster/t/002_connection_limits.pl
index 8cfa6e0ced5..f19d6e73ac9 100644
--- a/src/test/postmaster/t/002_connection_limits.pl
+++ b/src/test/postmaster/t/002_connection_limits.pl
@@ -19,9 +19,57 @@ $node->init(
$node->append_conf('postgresql.conf', "max_connections = 6");
$node->append_conf('postgresql.conf', "reserved_connections = 2");
$node->append_conf('postgresql.conf', "superuser_reserved_connections = 1");
-$node->append_conf('postgresql.conf', "log_connections = on");
$node->start;
+# Before testing connection limits, test the behavior of log_connections
+
+$node->connect_ok("",
+ "no connection logging emitted when log_connections is the default (off)",
+ log_unlike => [
+ qr/connection received/,
+ qr/connection authenticated/,
+ qr/connection authorized/,
+ ],);
+
+$node->safe_psql(
+ 'postgres',
+ q[ALTER SYSTEM SET log_connections = received,authorized;
+ SELECT pg_reload_conf();]);
+
+$node->connect_ok("",
+ "log_connections with subset of specified stages logs only those stages",
+ log_like => [
+ qr/connection received/,
+ qr/connection authorized/,
+ ],
+ log_unlike => [
+ qr/connection authenticated/,
+ ],);
+
+$node->safe_psql(
+ 'postgres',
+ q[ALTER SYSTEM SET log_connections = on; SELECT pg_reload_conf();]);
+
+$node->connect_ok("",
+ "log_connections 'on' works as expected for backwards compatibility",
+ log_like => [
+ qr/connection received/,
+ qr/connection authenticated/,
+ qr/connection authorized/,
+ ],);
+
+$node->safe_psql(
+ 'postgres',
+ q[ALTER SYSTEM SET log_connections = 'all'; SELECT pg_reload_conf();]);
+
+$node->connect_ok("",
+ "all log connections messages printed when 'all' specified",
+ log_like => [
+ qr/connection received/,
+ qr/connection authenticated/,
+ qr/connection authorized/,
+ ],);
+
$node->safe_psql(
'postgres', qq{
CREATE USER regress_regular LOGIN;
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 9840060997f..29e52b64994 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -1555,6 +1555,7 @@ LockTupleMode
LockViewRecurse_context
LockWaitPolicy
LockingClause
+LogConnectionOption
LogOpts
LogStmtLevel
LogicalDecodeBeginCB
--
2.34.1
