On Fri, Feb 28, 2025 at 12:54 AM Bertrand Drouvot <bertranddrouvot...@gmail.com> wrote: > > On Thu, Feb 27, 2025 at 05:55:19PM -0500, Melanie Plageman wrote: > > It still needs polishing (e.g. I need to figure out where to put the new > > guc hook > > functions and enums and such) > > yeah, I wonder if it would make sense to create new dedicated > "connection_logging" > file(s).
I think for now there isn't enough for a new file. I think these are probably okay in postmaster.c since this has to do with postmaster starting new connections. > > I'm worried the list of possible connection log messages could get > > unwieldy if we add many more. > > Thinking out loud, I'm not sure we'd add "many more" but maybe what we could > do > is to introduce some predefined groups like: > > 'basic' (that would be equivalent to 'received, + timings introduced in 0002') > 'security' (equivalent to 'authenticated,authorized') > > Not saying we need to create this kind of predefined groups now, just an idea > in case we'd add many more: that could "help" the user experience, or are you > more concerned about the code maintenance? I was more worried about the user having to provide very long lists. But groupings could be a sensible solution in the future. > Just did a quick test, (did not look closely at the code), and it looks like > that: > > 'all': does not report the "received" (but does report authenticated and > authorized) > 'received': does not work? > 'authenticated': works > 'authorized': works Thanks for testing! Ouch, there were many bugs in that prototype. My enums were broken and a few other things. I found some bugs in 0002 as well. Attached v8 fixes the issues I found so far. We have to be really careful about when log_connections is actually set before we use it -- I fixed some issues with that. I decided to move the creation_time out of ClientSocket and into BackendStartupData, but that meant I had to save it in the ConnectionTiming because we don't have access to the BackendStartupData anymore in PostgresMain(). That means ConnectionTiming is now a mixture of times and durations. I think that should be okay (i.e. not too confusing and gross), but I'm not sure. It is called ConnectionTiming and not ConnectionDuration, after all. - Melanie
From 0ee1cd306a4c27e5ec0d1860ce7cd219bb761fed Mon Sep 17 00:00:00 2001 From: Melanie Plageman <melanieplage...@gmail.com> Date: Thu, 27 Feb 2025 17:32:17 -0500 Subject: [PATCH v8 1/2] Modularize log_connections output Convert the boolean log_connections GUC into a list GUC of the connection stages to log. This obsoletes log_disconnections, as 'disconnected' is now a log_connections option. The current log_connections options are 'received', 'authenticated', 'authorized', and 'disconnected'. The empty string disables all connection logging. 'all' enables all available connection logging. This gives users more control over the volume of connection logging. This patch has the same behavior as [1] but was developed independently. The idea to replace log_disconnections with a log_connections option does, however, come from that thread. [1] https://www.postgresql.org/message-id/flat/CAA8Fd-qCB96uwfgMKrzfNs32mqqysi53yZFNVaRNJ6xDthZEgA%40mail.gmail.com Discussion: https://postgr.es/m/flat/Z8FPpJPDLHWNuV2c%40ip-10-97-1-34.eu-west-3.compute.internal#35525b4425c5f8ecfe52ec6ad859ef9a --- doc/src/sgml/config.sgml | 48 +++++------- src/backend/libpq/auth.c | 8 +- src/backend/postmaster/postmaster.c | 77 ++++++++++++++++++- src/backend/tcop/backend_startup.c | 4 +- src/backend/tcop/postgres.c | 13 +--- src/backend/utils/init/postinit.c | 2 +- src/backend/utils/misc/guc_tables.c | 29 +++---- src/backend/utils/misc/postgresql.conf.sample | 5 +- src/include/postmaster/postmaster.h | 16 +++- src/include/tcop/tcopprot.h | 1 - src/include/utils/guc_hooks.h | 2 + .../libpq/t/005_negotiate_encryption.pl | 3 +- src/test/authentication/t/001_password.pl | 2 +- src/test/authentication/t/003_peer.pl | 2 +- src/test/authentication/t/005_sspi.pl | 2 +- src/test/kerberos/t/001_auth.pl | 2 +- src/test/ldap/t/001_auth.pl | 2 +- src/test/ldap/t/002_bindpasswd.pl | 2 +- .../t/001_mutated_bindpasswd.pl | 2 +- .../modules/oauth_validator/t/001_server.pl | 2 +- .../modules/oauth_validator/t/002_client.pl | 2 +- .../postmaster/t/002_connection_limits.pl | 2 +- src/test/postmaster/t/003_start_stop.pl | 2 +- src/test/recovery/t/013_crash_restart.pl | 2 +- src/test/recovery/t/022_crash_temp_files.pl | 2 +- src/test/recovery/t/032_relfilenode_reuse.pl | 2 +- src/test/recovery/t/037_invalid_database.pl | 3 +- src/test/ssl/t/SSL/Server.pm | 2 +- src/tools/ci/pg_ci_base.conf | 3 +- src/tools/pgindent/typedefs.list | 1 + 30 files changed, 155 insertions(+), 90 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index e55700f35b8..4d2bbb3f720 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -140,7 +140,7 @@ An example of what this file might look like is: <programlisting> # This is a comment -log_connections = yes +log_connections = 'all' log_destination = 'syslog' search_path = '"$user", public' shared_buffers = 128MB @@ -337,7 +337,7 @@ UPDATE pg_settings SET setting = reset_val WHERE name = 'configuration_parameter <option>-c name=value</option> command-line parameter, or its equivalent <option>--name=value</option> variation. For example, <programlisting> -postgres -c log_connections=yes --log-destination='syslog' +postgres -c log_connections='all' --log-destination='syslog' </programlisting> Settings provided in this way override those set via <filename>postgresql.conf</filename> or <command>ALTER SYSTEM</command>, @@ -7315,20 +7315,28 @@ 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. - 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>. + Causes the specified stages of each connection attempt to the server to + be logged. 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>''</literal> which causes no connection logging messages to be + emitted. + </para> + + <para> + May be set to <literal>''</literal> to disable connection logging, + <literal>'all'</literal> to log all available connection stages, or a + comma-separated list of specific connection stages to log. The valid + options are <literal>received</literal>, + <literal>authenticated</literal>, <literal>authorized</literal>, and + <literal>disconnected</literal>. </para> <note> @@ -7342,26 +7350,6 @@ local0.* /var/log/postgresql </listitem> </varlistentry> - <varlistentry id="guc-log-disconnections" xreflabel="log_disconnections"> - <term><varname>log_disconnections</varname> (<type>boolean</type>) - <indexterm> - <primary><varname>log_disconnections</varname> configuration parameter</primary> - </indexterm> - </term> - <listitem> - <para> - Causes session terminations to be logged. The log output - provides information similar to <varname>log_connections</varname>, - plus the duration of the session. - 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> - </listitem> - </varlistentry> - - <varlistentry id="guc-log-duration" xreflabel="log_duration"> <term><varname>log_duration</varname> (<type>boolean</type>) <indexterm> diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c index 81e2f8184e3..da7b46720d4 100644 --- a/src/backend/libpq/auth.c +++ b/src/backend/libpq/auth.c @@ -317,7 +317,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 +350,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 +634,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 5dd3b6a4fd4..315f5a55a34 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -118,6 +118,7 @@ #include "utils/pidfile.h" #include "utils/timestamp.h" #include "utils/varlena.h" +#include "utils/guc_hooks.h" #ifdef EXEC_BACKEND #include "common/file_utils.h" @@ -237,7 +238,8 @@ int PreAuthDelay = 0; int AuthenticationTimeout = 60; bool log_hostname; /* for ps display and logging */ -bool Log_connections = false; +char *log_connections_string = NULL; +int log_connections = 0; bool enable_bonjour = false; char *bonjour_name; @@ -1517,6 +1519,79 @@ checkControlFile(void) FreeFile(fp); } +/* + * Validate the input for the log_connections GUC. + */ +bool +check_log_connections(char **newval, void **extra, GucSource source) +{ + int flags = 0; + char *rawstring = NULL; + List *elemlist; + ListCell *l; + + char *effval = *newval; + + /* + * log_connections can be 'all', '', or a list of comma-separated options. + */ + if (pg_strcasecmp(*newval, "all") == 0) + effval = "received, authenticated, authorized, disconnected"; + + /* Need a modifiable copy of string */ + rawstring = pstrdup(effval); + + if (!SplitGUCList(rawstring, ',', &elemlist)) + { + GUC_check_errdetail("Invalid list syntax in parameter \"log_connections\"."); + goto log_connections_error; + } + + foreach(l, elemlist) + { + char *item = (char *) lfirst(l); + + if (pg_strcasecmp(item, "received") == 0) + flags |= LOG_CONNECTION_RECEIVED; + else if (pg_strcasecmp(item, "authenticated") == 0) + flags |= LOG_CONNECTION_AUTHENTICATED; + else if (pg_strcasecmp(item, "authorized") == 0) + flags |= LOG_CONNECTION_AUTHORIZED; + else if (pg_strcasecmp(item, "disconnected") == 0) + flags |= LOG_CONNECTION_DISCONNECTED; + else if (pg_strcasecmp(item, "all") == 0) + { + GUC_check_errdetail("Must specify \"all\" alone with no additional options, whitespace, or characters."); + goto log_connections_error; + } + else + { + GUC_check_errdetail("Invalid option \"%s\".", item); + goto log_connections_error; + } + } + + pfree(rawstring); + list_free(elemlist); + + /* Save the flags in *extra, for use by assign_log_connections */ + *extra = guc_malloc(ERROR, sizeof(int)); + *((int *) *extra) = flags; + + return true; + +log_connections_error: + pfree(rawstring); + list_free(elemlist); + return false; +} + +void +assign_log_connections(const char *newval, void *extra) +{ + log_connections = *((int *) extra); +} + /* * Determine how long should we let ServerLoop sleep, in milliseconds. * diff --git a/src/backend/tcop/backend_startup.c b/src/backend/tcop/backend_startup.c index c70746fa562..887c2f177ef 100644 --- a/src/backend/tcop/backend_startup.c +++ b/src/backend/tcop/backend_startup.c @@ -201,8 +201,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, diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index f2f75aa0f88..8b403a6cc3d 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -89,9 +89,6 @@ const char *debug_query_string; /* client-supplied query string */ /* Note: whereToSendOutput is initialized for the bootstrap/standalone case */ CommandDest whereToSendOutput = DestDebug; -/* flag for logging end of session */ -bool Log_disconnections = false; - int log_statement = LOGSTMT_NONE; /* wait N seconds to allow attach from a debugger */ @@ -3653,10 +3650,7 @@ set_debug_options(int debug_flag, GucContext context, GucSource source) SetConfigOption("log_min_messages", "notice", context, source); if (debug_flag >= 1 && context == PGC_POSTMASTER) - { - SetConfigOption("log_connections", "true", context, source); - SetConfigOption("log_disconnections", "true", context, source); - } + SetConfigOption("log_connections", "all", context, source); if (debug_flag >= 2) SetConfigOption("log_statement", "all", context, source); if (debug_flag >= 3) @@ -4271,9 +4265,10 @@ PostgresMain(const char *dbname, const char *username) /* * Also set up handler to log session end; we have to wait till now to be - * sure Log_disconnections has its final value. + * sure log_connections has its final value. */ - if (IsUnderPostmaster && Log_disconnections) + if (IsUnderPostmaster && + (log_connections & LOG_CONNECTION_DISCONNECTED)) on_proc_exit(log_disconnections, 0); pgstat_report_connect(MyDatabaseId); diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c index 318600d6d02..8811f2ba3e6 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -251,7 +251,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..5b73270c8a9 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."), @@ -1238,15 +1229,6 @@ struct config_bool ConfigureNamesBool[] = false, NULL, NULL, NULL }, - { - {"log_disconnections", PGC_SU_BACKEND, LOGGING_WHAT, - gettext_noop("Logs end of a session, including duration."), - NULL - }, - &Log_disconnections, - false, - NULL, NULL, NULL - }, { {"log_replication_commands", PGC_SUSET, LOGGING_WHAT, gettext_noop("Logs each replication command."), @@ -4850,6 +4832,17 @@ struct config_string ConfigureNamesString[] = check_debug_io_direct, assign_debug_io_direct, 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 + }, + { {"synchronized_standby_slots", PGC_SIGHUP, REPLICATION_PRIMARY, gettext_noop("Lists streaming replication standby server replication slot " diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index 5362ff80519..bf611317b3f 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,8 +578,7 @@ # actions running at least this number # of milliseconds. #log_checkpoints = on -#log_connections = off -#log_disconnections = off +#log_connections = '' #log_duration = off #log_error_verbosity = default # terse, default, or verbose messages #log_hostname = off diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h index b6a3f275a1b..ffa30e94aff 100644 --- a/src/include/postmaster/postmaster.h +++ b/src/include/postmaster/postmaster.h @@ -63,7 +63,8 @@ extern PGDLLIMPORT char *ListenAddresses; extern PGDLLIMPORT bool ClientAuthInProgress; extern PGDLLIMPORT int PreAuthDelay; extern PGDLLIMPORT int AuthenticationTimeout; -extern PGDLLIMPORT bool Log_connections; +extern PGDLLIMPORT int log_connections; +extern PGDLLIMPORT char *log_connections_string; extern PGDLLIMPORT bool log_hostname; extern PGDLLIMPORT bool enable_bonjour; extern PGDLLIMPORT char *bonjour_name; @@ -143,4 +144,17 @@ typedef enum DispatchOption extern DispatchOption parse_dispatch_option(const char *name); +/* + * These flags correspond to the various stages of connection establishment + * which may be logged. check_log_connections() converts the options specified + * in the log_connections GUC to some combination of these values. + */ +typedef enum ConnectionLogOption +{ + LOG_CONNECTION_RECEIVED = (1 << 0), + LOG_CONNECTION_AUTHENTICATED = (1 << 1), + LOG_CONNECTION_AUTHORIZED = (1 << 2), + LOG_CONNECTION_DISCONNECTED = (1 << 3), +} ConnectionLogOption; + #endif /* _POSTMASTER_H */ diff --git a/src/include/tcop/tcopprot.h b/src/include/tcop/tcopprot.h index a62367f7793..dde9b7e9b59 100644 --- a/src/include/tcop/tcopprot.h +++ b/src/include/tcop/tcopprot.h @@ -36,7 +36,6 @@ typedef enum LOGSTMT_ALL, /* log all statements */ } LogStmtLevel; -extern PGDLLIMPORT bool Log_disconnections; extern PGDLLIMPORT int log_statement; /* Flags for restrict_nonsystem_relation_kind value */ 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/interfaces/libpq/t/005_negotiate_encryption.pl b/src/interfaces/libpq/t/005_negotiate_encryption.pl index c834fa5149a..d488aa1f1e2 100644 --- a/src/interfaces/libpq/t/005_negotiate_encryption.pl +++ b/src/interfaces/libpq/t/005_negotiate_encryption.pl @@ -107,8 +107,7 @@ $node->append_conf( listen_addresses = '$hostaddr' # Capturing the EVENTS that occur during tests requires these settings -log_connections = on -log_disconnections = on +log_connections = 'all' trace_connection_negotiation = on lc_messages = 'C' }); diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl index 4ce22ccbdf2..72c187fbdc0 100644 --- a/src/test/authentication/t/001_password.pl +++ b/src/test/authentication/t/001_password.pl @@ -63,7 +63,7 @@ sub test_conn # Initialize primary node my $node = PostgreSQL::Test::Cluster->new('primary'); $node->init; -$node->append_conf('postgresql.conf', "log_connections = on\n"); +$node->append_conf('postgresql.conf', "log_connections = 'all'\n"); $node->start; # could fail in FIPS mode diff --git a/src/test/authentication/t/003_peer.pl b/src/test/authentication/t/003_peer.pl index 69ba73bd2b9..8e1b0477d6b 100644 --- a/src/test/authentication/t/003_peer.pl +++ b/src/test/authentication/t/003_peer.pl @@ -71,7 +71,7 @@ sub test_role my $node = PostgreSQL::Test::Cluster->new('node'); $node->init; -$node->append_conf('postgresql.conf', "log_connections = on\n"); +$node->append_conf('postgresql.conf', "log_connections = 'all'\n"); $node->start; # Set pg_hba.conf with the peer authentication. diff --git a/src/test/authentication/t/005_sspi.pl b/src/test/authentication/t/005_sspi.pl index b480b702590..f9b61babcd7 100644 --- a/src/test/authentication/t/005_sspi.pl +++ b/src/test/authentication/t/005_sspi.pl @@ -18,7 +18,7 @@ if (!$windows_os || $use_unix_sockets) # Initialize primary node my $node = PostgreSQL::Test::Cluster->new('primary'); $node->init; -$node->append_conf('postgresql.conf', "log_connections = on\n"); +$node->append_conf('postgresql.conf', "log_connections = 'all'\n"); $node->start; my $huge_pages_status = diff --git a/src/test/kerberos/t/001_auth.pl b/src/test/kerberos/t/001_auth.pl index 6748b109dec..afc3130e720 100644 --- a/src/test/kerberos/t/001_auth.pl +++ b/src/test/kerberos/t/001_auth.pl @@ -65,7 +65,7 @@ $node->append_conf( 'postgresql.conf', qq{ listen_addresses = '$hostaddr' krb_server_keyfile = '$krb->{keytab}' -log_connections = on +log_connections = 'all' lc_messages = 'C' }); $node->start; diff --git a/src/test/ldap/t/001_auth.pl b/src/test/ldap/t/001_auth.pl index 352b0fc1fa7..b6ee386679d 100644 --- a/src/test/ldap/t/001_auth.pl +++ b/src/test/ldap/t/001_auth.pl @@ -47,7 +47,7 @@ note "setting up PostgreSQL instance"; my $node = PostgreSQL::Test::Cluster->new('node'); $node->init; -$node->append_conf('postgresql.conf', "log_connections = on\n"); +$node->append_conf('postgresql.conf', "log_connections = 'all'\n"); $node->start; $node->safe_psql('postgres', 'CREATE USER test0;'); diff --git a/src/test/ldap/t/002_bindpasswd.pl b/src/test/ldap/t/002_bindpasswd.pl index f8beba2b279..2acf96aeb6d 100644 --- a/src/test/ldap/t/002_bindpasswd.pl +++ b/src/test/ldap/t/002_bindpasswd.pl @@ -43,7 +43,7 @@ note "setting up PostgreSQL instance"; my $node = PostgreSQL::Test::Cluster->new('node'); $node->init; -$node->append_conf('postgresql.conf', "log_connections = on\n"); +$node->append_conf('postgresql.conf', "log_connections = 'all'\n"); $node->start; $node->safe_psql('postgres', 'CREATE USER test0;'); diff --git a/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl b/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl index 9b062e1c800..4591b5568a8 100644 --- a/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl +++ b/src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl @@ -42,7 +42,7 @@ note "setting up PostgreSQL instance"; my $node = PostgreSQL::Test::Cluster->new('node'); $node->init; -$node->append_conf('postgresql.conf', "log_connections = on\n"); +$node->append_conf('postgresql.conf', "log_connections = 'all'\n"); $node->append_conf('postgresql.conf', "shared_preload_libraries = 'ldap_password_func'"); $node->start; diff --git a/src/test/modules/oauth_validator/t/001_server.pl b/src/test/modules/oauth_validator/t/001_server.pl index 6fa59fbeb25..27829680439 100644 --- a/src/test/modules/oauth_validator/t/001_server.pl +++ b/src/test/modules/oauth_validator/t/001_server.pl @@ -43,7 +43,7 @@ if ($ENV{with_python} ne 'yes') my $node = PostgreSQL::Test::Cluster->new('primary'); $node->init; -$node->append_conf('postgresql.conf', "log_connections = on\n"); +$node->append_conf('postgresql.conf', "log_connections = 'all'\n"); $node->append_conf('postgresql.conf', "oauth_validator_libraries = 'validator'\n"); $node->start; diff --git a/src/test/modules/oauth_validator/t/002_client.pl b/src/test/modules/oauth_validator/t/002_client.pl index ab83258d736..aa944ba5f2f 100644 --- a/src/test/modules/oauth_validator/t/002_client.pl +++ b/src/test/modules/oauth_validator/t/002_client.pl @@ -26,7 +26,7 @@ if (!$ENV{PG_TEST_EXTRA} || $ENV{PG_TEST_EXTRA} !~ /\boauth\b/) my $node = PostgreSQL::Test::Cluster->new('primary'); $node->init; -$node->append_conf('postgresql.conf', "log_connections = on\n"); +$node->append_conf('postgresql.conf', "log_connections = 'all'\n"); $node->append_conf('postgresql.conf', "oauth_validator_libraries = 'validator'\n"); $node->start; diff --git a/src/test/postmaster/t/002_connection_limits.pl b/src/test/postmaster/t/002_connection_limits.pl index 8cfa6e0ced5..a221501c206 100644 --- a/src/test/postmaster/t/002_connection_limits.pl +++ b/src/test/postmaster/t/002_connection_limits.pl @@ -19,7 +19,7 @@ $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->append_conf('postgresql.conf', "log_connections = 'all'"); $node->start; $node->safe_psql( diff --git a/src/test/postmaster/t/003_start_stop.pl b/src/test/postmaster/t/003_start_stop.pl index 036b296f72b..08cd7a4857e 100644 --- a/src/test/postmaster/t/003_start_stop.pl +++ b/src/test/postmaster/t/003_start_stop.pl @@ -29,7 +29,7 @@ $node->append_conf('postgresql.conf', "max_connections = 5"); $node->append_conf('postgresql.conf', "max_wal_senders = 0"); $node->append_conf('postgresql.conf', "autovacuum_max_workers = 1"); $node->append_conf('postgresql.conf', "max_worker_processes = 1"); -$node->append_conf('postgresql.conf', "log_connections = on"); +$node->append_conf('postgresql.conf', "log_connections = 'all'"); $node->append_conf('postgresql.conf', "log_min_messages = debug2"); $node->append_conf('postgresql.conf', "authentication_timeout = '$authentication_timeout s'"); diff --git a/src/test/recovery/t/013_crash_restart.pl b/src/test/recovery/t/013_crash_restart.pl index cd848918d00..2b6ec94cd75 100644 --- a/src/test/recovery/t/013_crash_restart.pl +++ b/src/test/recovery/t/013_crash_restart.pl @@ -27,7 +27,7 @@ $node->start(); $node->safe_psql( 'postgres', q[ALTER SYSTEM SET restart_after_crash = 1; - ALTER SYSTEM SET log_connections = 1; + ALTER SYSTEM SET log_connections = 'all'; SELECT pg_reload_conf();]); # Run psql, keeping session alive, so we have an alive backend to kill. diff --git a/src/test/recovery/t/022_crash_temp_files.pl b/src/test/recovery/t/022_crash_temp_files.pl index 483a416723f..5d4b695c193 100644 --- a/src/test/recovery/t/022_crash_temp_files.pl +++ b/src/test/recovery/t/022_crash_temp_files.pl @@ -26,7 +26,7 @@ $node->start(); $node->safe_psql( 'postgres', q[ALTER SYSTEM SET remove_temp_files_after_crash = on; - ALTER SYSTEM SET log_connections = 1; + ALTER SYSTEM SET log_connections = 'all'; ALTER SYSTEM SET work_mem = '64kB'; ALTER SYSTEM SET restart_after_crash = on; SELECT pg_reload_conf();]); diff --git a/src/test/recovery/t/032_relfilenode_reuse.pl b/src/test/recovery/t/032_relfilenode_reuse.pl index ddb7223b337..388a50add7a 100644 --- a/src/test/recovery/t/032_relfilenode_reuse.pl +++ b/src/test/recovery/t/032_relfilenode_reuse.pl @@ -14,7 +14,7 @@ $node_primary->init(allows_streaming => 1); $node_primary->append_conf( 'postgresql.conf', q[ allow_in_place_tablespaces = true -log_connections=on +log_connections='all' # to avoid "repairing" corruption full_page_writes=off log_min_messages=debug2 diff --git a/src/test/recovery/t/037_invalid_database.pl b/src/test/recovery/t/037_invalid_database.pl index bdf39397397..e03b963f917 100644 --- a/src/test/recovery/t/037_invalid_database.pl +++ b/src/test/recovery/t/037_invalid_database.pl @@ -15,8 +15,7 @@ $node->append_conf( autovacuum = off max_prepared_transactions=5 log_min_duration_statement=0 -log_connections=on -log_disconnections=on +log_connections='all' )); $node->start; diff --git a/src/test/ssl/t/SSL/Server.pm b/src/test/ssl/t/SSL/Server.pm index 447469d8937..7bc45ee7611 100644 --- a/src/test/ssl/t/SSL/Server.pm +++ b/src/test/ssl/t/SSL/Server.pm @@ -200,7 +200,7 @@ sub configure_test_server_for_ssl $node->append_conf( 'postgresql.conf', <<EOF fsync=off -log_connections=on +log_connections='all' log_hostname=on listen_addresses='$serverhost' log_statement=all diff --git a/src/tools/ci/pg_ci_base.conf b/src/tools/ci/pg_ci_base.conf index d8faa9c26c1..b05a4844b26 100644 --- a/src/tools/ci/pg_ci_base.conf +++ b/src/tools/ci/pg_ci_base.conf @@ -8,7 +8,6 @@ max_prepared_transactions = 10 # Settings that make logs more useful log_autovacuum_min_duration = 0 log_checkpoints = true -log_connections = true -log_disconnections = true +log_connections = 'all' log_line_prefix = '%m [%p][%b] %q[%a][%v:%x] ' log_lock_waits = true diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list index 56989aa0b84..d155dcff036 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -483,6 +483,7 @@ ConnCacheKey ConnParams ConnStatusType ConnType +ConnectionLogOption ConnectionStateEnum ConsiderSplitContext Const -- 2.34.1
From 22584b57cda98058d2a1d714cc8d45c676935d9d Mon Sep 17 00:00:00 2001 From: Melanie Plageman <melanieplage...@gmail.com> Date: Thu, 27 Feb 2025 17:33:38 -0500 Subject: [PATCH v8 2/2] Add connection establishment duration logging Add log_connections option 'timings' which logs durations for several key parts of connection establishment when specified. For a new 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. Provide visibility into authentication and fork duration as well as the end-to-end connection establishment and initialization time with logging. To make this portable, the timings captured in the postmaster (socket creation time, fork initiation time) are passed through the ClientSocket and BackendStartupData structures instead of simply saved in backend local memory inherited by the child process. 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 | 15 +++++---- src/backend/postmaster/launch_backend.c | 45 +++++++++++++++++++++++++ src/backend/postmaster/postmaster.c | 10 +++++- src/backend/tcop/postgres.c | 21 ++++++++++++ src/backend/utils/init/globals.c | 2 ++ src/backend/utils/init/postinit.c | 10 ++++++ src/include/libpq/libpq-be.h | 1 + src/include/miscadmin.h | 2 ++ src/include/portability/instr_time.h | 9 +++++ src/include/postmaster/postmaster.h | 23 +++++++++++++ src/include/tcop/backend_startup.h | 14 ++++++++ src/tools/pgindent/typedefs.list | 1 + 12 files changed, 146 insertions(+), 7 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 4d2bbb3f720..b1f38b99ee0 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7331,12 +7331,15 @@ local0.* /var/log/postgresql </para> <para> - May be set to <literal>''</literal> to disable connection logging, - <literal>'all'</literal> to log all available connection stages, or a - comma-separated list of specific connection stages to log. The valid - options are <literal>received</literal>, - <literal>authenticated</literal>, <literal>authorized</literal>, and - <literal>disconnected</literal>. + May be set to <literal>''</literal> to disable this logging, + <literal>'all'</literal> to enable all connection log message types, or + a comma-separated list of the specific connection log message types to + emit. The valid options are <literal>received</literal>, + <literal>authenticated</literal>, <literal>authorized</literal>, + <literal>disconnected</literal>, and <literal>timings</literal>. When + <literal>timings</literal> is specified, a message is logged the first + time the connection is ready for query containing connection + establishment durations. </para> <note> diff --git a/src/backend/postmaster/launch_backend.c b/src/backend/postmaster/launch_backend.c index 47375e5bfaa..67fdad55414 100644 --- a/src/backend/postmaster/launch_backend.c +++ b/src/backend/postmaster/launch_backend.c @@ -232,6 +232,11 @@ postmaster_child_launch(BackendType child_type, int child_slot, Assert(IsPostmasterEnvironment && !IsUnderPostmaster); + /* Capture time Postmaster initiates fork for logging */ + if ((log_connections & LOG_CONNECTION_TIMINGS) && + (child_type == B_BACKEND || child_type == B_WAL_SENDER)) + 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 +245,22 @@ postmaster_child_launch(BackendType child_type, int child_slot, pid = fork_process(); if (pid == 0) /* child */ { + /* + * Transfer over any log_connections 'timings' data we need that was + * collected by the postmaster. We save the time the socket was + * created to later log the total connection establishment and setup + * time. Calculate the total fork duration now since we have the start + * and end times. + */ + if ((log_connections & LOG_CONNECTION_TIMINGS) && + (child_type == B_BACKEND || child_type == B_WAL_SENDER)) + { + BackendStartupData *data = (BackendStartupData *) startup_data; + + conn_timing.fork_duration = INSTR_TIME_GET_DURATION_SINCE(data->fork_started); + conn_timing.creation_time = data->socket_created; + } + /* Close the postmaster's sockets */ ClosePostmasterPorts(child_type == B_LOGGER); @@ -586,6 +607,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; @@ -598,6 +620,13 @@ SubPostmasterMain(int argc, char *argv[]) if (argc != 3) elog(FATAL, "invalid subpostmaster invocation"); + /* + * Set the fork end time. We haven't read the GUC file yet, so we don't + * know if we will use this value for logging, but getting the time is + * relatively little overhead. + */ + INSTR_TIME_SET_CURRENT(fork_ended); + /* Find the entry in child_process_kinds */ if (strncmp(argv[1], "--forkchild=", 12) != 0) elog(FATAL, "invalid subpostmaster invocation (--forkchild argument missing)"); @@ -648,6 +677,22 @@ SubPostmasterMain(int argc, char *argv[]) /* Read in remaining GUC variables */ read_nondefault_variables(); + /* + * Transfer over any log_connections 'timings' data we need that was + * collected by the postmaster. We save the time the socket was created to + * later log the total connection establishment and setup time. Calculate + * the total fork duration now since we have the start and end times. + */ + if ((log_connections & LOG_CONNECTION_TIMINGS) && + (child_type == B_BACKEND || child_type == B_WAL_SENDER)) + { + BackendStartupData *data = (BackendStartupData *) startup_data; + + conn_timing.fork_duration = fork_ended; + INSTR_TIME_SUBTRACT(conn_timing.fork_duration, data->fork_started); + 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 315f5a55a34..67d388ff2d5 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -1536,7 +1536,7 @@ check_log_connections(char **newval, void **extra, GucSource source) * log_connections can be 'all', '', or a list of comma-separated options. */ if (pg_strcasecmp(*newval, "all") == 0) - effval = "received, authenticated, authorized, disconnected"; + effval = "received, authenticated, authorized, disconnected, timings"; /* Need a modifiable copy of string */ rawstring = pstrdup(effval); @@ -1559,6 +1559,8 @@ check_log_connections(char **newval, void **extra, GucSource source) flags |= LOG_CONNECTION_AUTHORIZED; else if (pg_strcasecmp(item, "disconnected") == 0) flags |= LOG_CONNECTION_DISCONNECTED; + else if (pg_strcasecmp(item, "timings") == 0) + flags |= LOG_CONNECTION_TIMINGS; else if (pg_strcasecmp(item, "all") == 0) { GUC_check_errdetail("Must specify \"all\" alone with no additional options, whitespace, or characters."); @@ -3553,6 +3555,12 @@ BackendStartup(ClientSocket *client_sock) BackendStartupData startup_data; CAC_state cac; + /* + * Capture time that Postmaster got a socket from accept (for logging + * connection establishment 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/postgres.c b/src/backend/tcop/postgres.c index 8b403a6cc3d..8c6fdf4bc9d 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -4147,6 +4147,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); @@ -4602,6 +4603,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_TIMINGS) && + (AmRegularBackendProcess() || AmWalSenderProcess())) + { + instr_time total_duration = + INSTR_TIME_GET_DURATION_SINCE(conn_timing.creation_time); + + ereport(LOG, + errmsg("connection establishment times (ms): total: %ld, fork: %ld, authentication: %ld", + (long int) INSTR_TIME_GET_MILLISEC(total_duration), + (long int) INSTR_TIME_GET_MILLISEC(conn_timing.fork_duration), + (long int) INSTR_TIME_GET_MILLISEC(conn_timing.auth_duration))); + + 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..3c7b14dd57d 100644 --- a/src/backend/utils/init/globals.c +++ b/src/backend/utils/init/globals.c @@ -43,6 +43,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 8811f2ba3e6..6d39acffb27 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -190,9 +190,15 @@ 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 */ + if (log_connections & LOG_CONNECTION_TIMINGS) + 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. @@ -251,6 +257,10 @@ PerformAuthentication(Port *port) */ disable_timeout(STATEMENT_TIMEOUT, false); + /* Calculate authentication duration for logging */ + if (log_connections & LOG_CONNECTION_TIMINGS) + 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/libpq/libpq-be.h b/src/include/libpq/libpq-be.h index 7fe92b15477..7579d96563e 100644 --- a/src/include/libpq/libpq-be.h +++ b/src/include/libpq/libpq-be.h @@ -58,6 +58,7 @@ typedef struct #include "datatype/timestamp.h" #include "libpq/hba.h" #include "libpq/pqcomm.h" +#include "portability/instr_time.h" /* diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h index a2b63495eec..9dd18a2c74f 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; 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/postmaster/postmaster.h b/src/include/postmaster/postmaster.h index ffa30e94aff..70818e70d2a 100644 --- a/src/include/postmaster/postmaster.h +++ b/src/include/postmaster/postmaster.h @@ -15,6 +15,7 @@ #include "lib/ilist.h" #include "miscadmin.h" +#include "portability/instr_time.h" /* * A struct representing an active postmaster child process. This is used @@ -127,6 +128,27 @@ extern PMChild *AllocDeadEndChild(void); extern bool ReleasePostmasterChildSlot(PMChild *pmchild); extern PMChild *FindPostmasterChildByPid(int pid); +/* + * A collection of timings and durations of various stages of connection + * establishment and setup for client backends and WAL senders. Used for + * log_connections 'timings' option. + */ +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; + /* * These values correspond to the special must-be-first options for dispatching * to various subprograms. parse_dispatch_option() can be used to convert an @@ -155,6 +177,7 @@ typedef enum ConnectionLogOption LOG_CONNECTION_AUTHENTICATED = (1 << 1), LOG_CONNECTION_AUTHORIZED = (1 << 2), LOG_CONNECTION_DISCONNECTED = (1 << 3), + LOG_CONNECTION_TIMINGS = (1 << 4), } ConnectionLogOption; #endif /* _POSTMASTER_H */ diff --git a/src/include/tcop/backend_startup.h b/src/include/tcop/backend_startup.h index 73285611203..03192e21387 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; @@ -37,6 +39,18 @@ 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; extern void BackendMain(const void *startup_data, size_t startup_data_len) pg_attribute_noreturn(); diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list index d155dcff036..c030047a107 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -485,6 +485,7 @@ ConnStatusType ConnType ConnectionLogOption ConnectionStateEnum +ConnectionTiming ConsiderSplitContext Const ConstrCheck -- 2.34.1
