Thread: Introduce "log_connection_stages" setting.

Hello,

The problem we face is excessive logging of connection information
that clutters the logs and in corner cases with many short-lived
connections leads to disk space exhaustion.

Current connection log lines share significant parts of the
information - host, port, very close timestamps etc. - in the common
case of a successful connection:

2022-07-12 12:17:39.369
UTC,,,12875,"10.2.101.63:35616",62cd6663.324b,1,"",2022-07-12 12:17:39
UTC,,0,LOG,00000,"connection received: host=10.2.101.63
port=35616",,,,,,,,,"","not initialized"
2022-07-12 12:17:39.374
UTC,"some_user","postgres",12875,"10.2.101.63:35616",62cd6663.324b,2,"authentication",2022-07-12
12:17:39 UTC,18/4571,0,LOG,00000,"connection authorized:
user=some_user database=postgres SSL enabled (protocol=, cipher=,
compression=)",,,,,,,,,"","client backend"
2022-07-12 12:17:39.430
UTC,"some_user","postgres",12875,"10.2.101.63:35616",62cd6663.324b,3,"idle",2022-07-12
12:17:39 UTC,,0,LOG,00000,"disconnection: session time: 0:00:00.060
user=some_user database=postgres host=10.2.101.63
port=35616",,,,,,,,,"","client backend"

Removing some of the lines should not harm log-based investigations in
most cases, but will shrink the logs improving readability and space
consumption.

I would like to get feedback on the following idea:

Add the `log_connection_stages` setting of type “string” with possible
values "received", "authorized", "authenticated", "disconnected", and
"all", with "all" being the default.
The setting would have effect only when `log_connections` is on.
Example: log_connection_stages=’authorized,disconnected’.
That also implies there would be no need for a separate
"log_disconnection" setting.

For the sake of completeness I have to mention omitting ‘received’
from `log_connection_stages` would lead to absence in logs info about
connections that do not complete initialization: for them only the
“connection received” line is currently logged. The attachment
contains a log excerpt to clarify the situation I am talking about.

Regards,
Sergey.

The problem we face is excessive logging of connection information

that clutters the logs and in corner cases with many short-lived

connections leads to disk space exhaustion.

I would like to get feedback on the following idea:

Add the `log_connection_stages` setting of type “string” with possible

values "received", "authorized", "authenticated", "disconnected", and

"all", with "all" being the default.

The setting would have effect only when `log_connections` is on.

Example: log_connection_stages=’authorized,disconnected’.

That also implies there would be no need for a separate

"log_disconnection" setting.

Hello,

Thank you for the constructive feedback.

> Your proposal will add more confusion to the already-confused logging-related GUCs.
> I wouldn't introduce a new GUC that depends on the stage of other GUC as you proposed.

Agreed, coupling a new GUC with "log_connections" is likely to lead to
extra confusion.

> There are 3 stages: connect (received), authorized (authenticated), disconnect.

I've taken connection stages and terminology from the existing log messages.
The reason I have separated "authorized" and "authenticated" are [1]
and [2] usages of "log_connections";
"received" is mentioned at [3].

>> Example: log_connection_stages=’authorized,disconnected’.
> would turn the boolean value into an enum value

I have thought about enums too, but we need to cover arbitrary
combinations of message types, for example log only "received" and
"disconnected".
Hence the proposed type "string" with individual values within the
string really drawn from an enum.

> merge log_connections and log_disconnections into a new GUC (?) and deprecate them.

Are there any specific deprecation guidelines ? I have not found any
after a quick search for GUC deprecation in Google and commit history.
A deprecation scheme could look like that:
1. Mention in the docs "log_(dis)connections" are deprecated in favor
of "log_connection_stages"
2. Map "log_(dis)connections" to relevant values of
"log_connection_stages" in code if the latter is unset.
3. Complain in the logs if a conflict arises between the old params
and "log_connection_stages", with "log_connection_stages"
taking the precedence.

Regards,
Sergey

[1]
https://github.com/postgres/postgres/blob/3f8148c256e067dc2e8929ed174671ba7dc3339c/src/backend/utils/init/postinit.c#L257-L262
[2] https://github.com/postgres/postgres/blob/02c408e21a6e78ff246ea7a1beb4669634fa9c4c/src/backend/libpq/auth.c#L372
[3] https://github.com/postgres/postgres/blob/master/src/backend/postmaster/postmaster.c#L4393

I've taken connection stages and terminology from the existing log messages.

The reason I have separated "authorized" and "authenticated" are [1]

and [2] usages of "log_connections";

"received" is mentioned at [3].

I have thought about enums too, but we need to cover arbitrary

combinations of message types, for example log only "received" and

"disconnected".

Hence the proposed type "string" with individual values within the

string really drawn from an enum.

Are there any specific deprecation guidelines ? I have not found any

after a quick search for GUC deprecation in Google and commit history.

A deprecation scheme could look like that:

1. Mention in the docs "log_(dis)connections" are deprecated in favor

of "log_connection_stages"

2. Map "log_(dis)connections" to relevant values of

"log_connection_stages" in code if the latter is unset.

3. Complain in the logs if a conflict arises between the old params

and "log_connection_stages", with "log_connection_stages"

taking the precedence.

Hi hackers,

I've sketched an initial patch version; feedback is welcome.

Regards,
Sergey Dudoladov

On Tue, Nov 08, 2022 at 07:30:38PM +0100, Sergey Dudoladov wrote:
> +        <entry>Logs reception of a connection. At this point a connection has been received, but no further work has
beendone:
 

receipt

> +        <entry>Logs the original identity that an authentication method employs to identify a user. In most cases,
theidentity string equals the PostgreSQL username,
 

s/equals/matches

> +/* check_hook: validate new log_connection_messages value */
> +bool
> +check_log_connection_messages(char **newval, void **extra, GucSource source)
> +{
> +    char        *rawname;
> +    List        *namelist;
> +    ListCell    *l;
> +    char        *log_connection_messages = *newval;
> +    bool        *myextra;
> +
> +    /*
> +     * Set up the "extra" struct actually used by assign_log_connection_messages.
> +     */
> +    myextra = (bool *) guc_malloc(LOG, 4 * sizeof(bool));

This function hardcodes each of the 4 connections:

> +        if (pg_strcasecmp(stage, "received") == 0)
> +            myextra[0] = true;

It'd be better to use #defines or enums for these.

> --- a/src/backend/tcop/postgres.c
> +++ b/src/backend/tcop/postgres.c
> @@ -84,8 +84,11 @@ 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;
> +/* flags for logging information about session state */
> +bool        Log_disconnected = false;
> +bool        Log_authenticated = false;
> +bool        Log_authorized = false;
> +bool        Log_received = false;

I think this ought to be an integer with flag bits, rather than 4
booleans (I don't know, but there might be more later?).  Then, the
implementation follows the user-facing GUC and also follows
log_destination.

-- 
Justin

On Thu, Nov 17, 2022 at 09:36:29AM -0600, Justin Pryzby wrote:
> On Tue, Nov 08, 2022 at 07:30:38PM +0100, Sergey Dudoladov wrote:
...

Also (I didn't realize there was a CF entry), this is failing tests.
http://cfbot.cputube.org/sergey-dudoladov.html

-- 
Justin

Hi,

+1 for the idea!

> +        <entry><literal>authenticated</literal></entry>
> +        <entry>Logs the original identity that an authentication method employs to identify a user. In most cases,
theidentity string equals 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>
 

I think the documentation needs to be rewrapped; those are very long lines.

On 11/17/22 07:36, Justin Pryzby wrote:
> This function hardcodes each of the 4 connections:
> 
>> +        if (pg_strcasecmp(stage, "received") == 0)
>> +            myextra[0] = true;
> 
> It'd be better to use #defines or enums for these.

Hardcoding seems reasonable to me, if this is the only place we're doing
string comparison.

>> --- a/src/backend/tcop/postgres.c
>> +++ b/src/backend/tcop/postgres.c
>> @@ -84,8 +84,11 @@ 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;
>> +/* flags for logging information about session state */
>> +bool        Log_disconnected = false;
>> +bool        Log_authenticated = false;
>> +bool        Log_authorized = false;
>> +bool        Log_received = false;
> 
> I think this ought to be an integer with flag bits, rather than 4
> booleans (I don't know, but there might be more later?).  Then, the
> implementation follows the user-facing GUC and also follows
> log_destination.

Agreed. Or at the very least, follow what's done with
wal_consistency_checking? But I think flag bits would be better.

The tests should be expanded for cases other than 'all'.

As to the failing test cases: it looks like there's a keyword issue with
ALTER SYSTEM and 'all', but trying to fix it by quoting also fails. I
think it's because of GUC_LIST_QUOTE -- is there a reason that's used
here? I don't think we'd need any special characters in future option
names. wal_consistency_checking is very similar, and it just uses
GUC_LIST_INPUT.

Thanks,
--Jacob

Hello, hackers

Thank you for the reviews. I've modified the patch to incorporate your
suggestions:
+ flag bits are now used to encode different connection stages
+ failing tests are now fixed. It was not a keyword issue but rather
"check_log_connection_messages" not allocating memory properly
   in the special case log_connection_messages =  'all'
+ the GUC option is now only GUC_LIST_INPUT
+ typo fixes and line rewrapping in the docs

Regards,
Sergey

Thanks for updating the patch.  It's currently failing check-world, due
to a test that was added on January 23 (a9dc7f941):

http://cfbot.cputube.org/sergey-dudoladov.html
[19:15:57.101] Summary of Failures:
[19:15:57.101] [19:15:57.101] 250/251 postgresql:ldap / ldap/002_bindpasswd ERROR          1.38s

2023-01-30 19:15:52.427 GMT [56038] LOG:  unrecognized configuration parameter "log_connections" in file
"/tmp/cirrus-ci-build/build/testrun/ldap/002_bindpasswd/data/t_002_bindpasswd_node_data/pgdata/postgresql.conf"line
839

> +        received, but no further work has been done: Postgres is about to start

say "PostgreSQL" to match the rest of the docs.

> +                       GUC_check_errmsg("Invalid value '%s'", stage);

This message shouldn't be uppercased.

> +            GUC_check_errdetail("Valid values to use in the list are 'received', 'authenticated', 'authorized',
'disconnected',and 'all'."
 
> +            "If 'all' is present, it must be the only value in the list.");

Maybe "all" should be first ?

There's no spaces before "If":

| 2023-01-31 00:17:48.906 GMT [5676] DETALLE:  Valid values to use in the list are 'received', 'authenticated',
'authorized','disconnected', and 'all'.If 'all' is present, it must be the only value in the list.
 

> +/* flags for logging information about session state */
> +int            Log_connection_messages = LOG_CONNECTION_ALL;

The initial value here is overwritten by the GUC default during startup.
For consistency, the integer should be initialized to 0.

> +extern PGDLLIMPORT int    Log_connection_messages;
> +
> +/* Bitmap for logging connection messages */
> +#define LOG_CONNECTION_RECEIVED         1
> +#define LOG_CONNECTION_AUTHENTICATED 2
> +#define LOG_CONNECTION_AUTHORIZED     4
> +#define LOG_CONNECTION_DISCONNECTED  8
> +#define LOG_CONNECTION_ALL             15

Maybe the integers should be written like (1<<0)..
And maybe ALL should be 0xffff ?

More nitpicks:

> +        Causes stages of each attempted connection to the server to be logged. Example:
<literal>authorized,disconnected</literal>.

"Causes the specified stages of each connection attempt .."

> +        The default is the empty string meaning nothing is logged.

".. string, which means that nothing is logged"

> +        <entry>Logs the original identity that an authentication method employs
> +        to identify a user. In most cases, the identity string matches the

".. original identity used by an authentication method ..'

-- 
Justin

Hi again,

Justin, thank you for the fast review. The new version is attached.

Regards,
Sergey Dudoladov

On 2/1/23 11:59, Sergey Dudoladov wrote:
> Justin, thank you for the fast review. The new version is attached.

This is looking very good. One bigger comment:

> +    myextra = (int *) guc_malloc(ERROR, sizeof(int));
> +    *myextra = newlogconnect;

If I've understood Tom correctly in [1], both of these guc_mallocs
should be using a loglevel less than ERROR, to avoid forcing a
postmaster exit when out of memory. (I used WARNING in that thread
instead, which seemed to be acceptable.)

And a couple of nitpicks:

> +        Causes the specified stages of each connection attempt to the server to be logged. Example:
<literal>authorized,disconnected</literal>.

Long line; should be rewrapped.

> +       else {                                                                   
> +           GUC_check_errcode(ERRCODE_INVALID_PARAMETER_VALUE);                  
> +           GUC_check_errmsg("invalid value '%s'", stage);                       
> +           GUC_check_errdetail("Valid values to use in the list are 'all', 'received', 'authenticate
> +           " If 'all' is present, it must be the only value in the list."); 

I think the errmsg here should reuse the standard message format
    invalid value for parameter "%s": "%s"
both for consistency and ease of translation.

Thanks!
--Jacob

[1] https://www.postgresql.org/message-id/2012342.1658356951%40sss.pgh.pa.us

Jacob Champion <jchampion@timescale.com> writes:
> This is looking very good. One bigger comment:

>> +    myextra = (int *) guc_malloc(ERROR, sizeof(int));
>> +    *myextra = newlogconnect;

> If I've understood Tom correctly in [1], both of these guc_mallocs
> should be using a loglevel less than ERROR, to avoid forcing a
> postmaster exit when out of memory. (I used WARNING in that thread
> instead, which seemed to be acceptable.)

Actually, preferred practice is as seen in e.g. check_datestyle:

    myextra = (int *) guc_malloc(LOG, 2 * sizeof(int));
    if (!myextra)
        return false;
    myextra[0] = newDateStyle;
    myextra[1] = newDateOrder;
    *extra = (void *) myextra;

which gives the guc.c functions an opportunity to manage the
failure.

A quick grep shows that there are existing check functions that
did not get that memo, e.g. check_recovery_target_lsn.
We ought to clean them up.

This is, of course, not super important unless you're allocating
something quite large; the odds of going OOM in the postmaster
should be pretty small.

            regards, tom lane

On 3/2/23 14:56, Tom Lane wrote:
> Jacob Champion <jchampion@timescale.com> writes:
>> If I've understood Tom correctly in [1], both of these guc_mallocs
>> should be using a loglevel less than ERROR, to avoid forcing a
>> postmaster exit when out of memory. (I used WARNING in that thread
>> instead, which seemed to be acceptable.)
> 
> Actually, preferred practice is as seen in e.g. check_datestyle:
> 
>     myextra = (int *) guc_malloc(LOG, 2 * sizeof(int));
>     if (!myextra)
>         return false;
>     myextra[0] = newDateStyle;
>     myextra[1] = newDateOrder;
>     *extra = (void *) myextra;
> 
> which gives the guc.c functions an opportunity to manage the
> failure.

Ah, thanks for the correction. (My guc_strdup(WARNING, ...) calls may
need to be cleaned up too, then.)

--Jacob

Hello,

I have attached the fourth version of the patch.

Regards,
Sergey.

> On 16 May 2023, at 20:51, Sergey Dudoladov <sergey.dudoladov@gmail.com> wrote:

> I have attached the fourth version of the patch.

This version fails the ldap_password test on all platforms on pg_ctl failing to start:

[14:48:10.544] --- stdout ---
[14:48:10.544] # executing test in /tmp/cirrus-ci-build/build/testrun/ldap_password_func/001_mutated_bindpasswd group
ldap_password_functest 001_mutated_bindpasswd 
[14:48:10.544] # waiting for slapd to accept requests...
[14:48:10.544] # setting up PostgreSQL instance
[14:48:10.544] Bail out! pg_ctl start failed
[14:48:10.544] # test failed

Updating src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl with
the new GUC might solve the problem from skimming this.

Please send a fixed version, I'm marking the patch Waiting on Author in the
meantime.

--
Daniel Gustafsson

> On 3 Jul 2023, at 15:57, Daniel Gustafsson <daniel@yesql.se> wrote:
>
>> On 16 May 2023, at 20:51, Sergey Dudoladov <sergey.dudoladov@gmail.com> wrote:
>
>> I have attached the fourth version of the patch.
>
> This version fails the ldap_password test on all platforms on pg_ctl failing to start:
>
> [14:48:10.544] --- stdout ---
> [14:48:10.544] # executing test in /tmp/cirrus-ci-build/build/testrun/ldap_password_func/001_mutated_bindpasswd group
ldap_password_functest 001_mutated_bindpasswd 
> [14:48:10.544] # waiting for slapd to accept requests...
> [14:48:10.544] # setting up PostgreSQL instance
> [14:48:10.544] Bail out! pg_ctl start failed
> [14:48:10.544] # test failed
>
> Updating src/test/modules/ldap_password_func/t/001_mutated_bindpasswd.pl with
> the new GUC might solve the problem from skimming this.
>
> Please send a fixed version, I'm marking the patch Waiting on Author in the
> meantime.

With the patch failing tests and the thread stalled with no update I am marking
this returned with feedback. Please feel free to resubmit to a future CF.

--
Daniel Gustafsson

Hi,

On Fri, Feb 28, 2025 at 10:40:37AM +0100, Sergey Dudoladov wrote:
> Hello hackers,
> 
> here is the new rebased version of the patch.
> 

Thanks for the patch!

Did not realized that before but FWIW, it looks "very close" to what Melanie is
doing in [1] (0001 patch). Idea looks similar excepts, among other things, that
log_connections is kept.

[1]: https://www.postgresql.org/message-id/CAAKRu_asMtUpxDjts1J60batVqLsSGRodMOq4E9ryg1XdO8EZw%40mail.gmail.com

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

On Fri, Feb 28, 2025 at 5:04 AM Bertrand Drouvot
<bertranddrouvot.pg@gmail.com> wrote:
>
> Did not realized that before but FWIW, it looks "very close" to what Melanie is
> doing in [1] (0001 patch). Idea looks similar excepts, among other things, that
> log_connections is kept.

Oh wow, yes, I never saw this thread. I prefer keeping the original
guc name log_connections. I think it makes sense to also include
disconnected as an option in the list and remove that separate guc
log_disconnections. I was thinking, it should be okay to include "all"
in the list with other values and it just sets the value to all.

- Melanie

On Mon, Mar 3, 2025 at 5:43 AM Sergey Dudoladov
<sergey.dudoladov@gmail.com> wrote:
>
> I must admit I haven't seen the [1] either. Thank you for pointing that out, Bertrand.
> I agree the patch from Melanie is very close to this patch.
>
> Melanie, do you think it is realistic to merge the v8-0001-Modularize-log_connections-output.patch from [1] during
thecurrent commitfest ? 

I'd certainly like to merge it in 18. The patch itself needs more
work, which I'm planning on doing this week. I think we have a
reasonable amount of consensus on using GUC_LIST_INPUT.

I am less sure about merging log_disconnections into log_connections.
I think it makes sense in principle. But, in 18, when people satisfied
with existing behavior change log_connections from 'on' to 'all' to
comply with the new format, they will get the disconnections messages.

I am still somewhat nervous about merging the patch in general and
people being surprised because they didn't pay attention to the
discussion and now log_connections is different and they would have
-1'd if they'd been paying attention.

- Melanie

On Mon, Mar 3, 2025 at 9:40 AM Melanie Plageman
<melanieplageman@gmail.com> wrote:
>
> I'd certainly like to merge it in 18. The patch itself needs more
> work, which I'm planning on doing this week. I think we have a
> reasonable amount of consensus on using GUC_LIST_INPUT.
>
> I am less sure about merging log_disconnections into log_connections.
> I think it makes sense in principle. But, in 18, when people satisfied
> with existing behavior change log_connections from 'on' to 'all' to
> comply with the new format, they will get the disconnections messages.
>
> I am still somewhat nervous about merging the patch in general and
> people being surprised because they didn't pay attention to the
> discussion and now log_connections is different and they would have
> -1'd if they'd been paying attention.

Okay, I got cold feet today working on this. I actually think we
probably want some kind of guc set (set like union/intersection/etc
not set like assign a value) infrastructure for gucs that can be equal
to any combination of predetermined values. See my musings on this
here [1].

It is too late in the cycle for me to get something like that done,
but I am interested in working on it next release. IIRC you did not
deprecate log_connections in your patch, but adding another guc that
is a staged version of it seems not as good as turning log_connections
into a more modular GUC. But I just don't think we want to move
log_connections/disconnections toward a string/list.

- Melanie

[1] https://www.postgresql.org/message-id/CAAKRu_a5-7sUP%2BQ6YD5emQYS1w7ffBDUNf-NMbcxR-dpOdGehw%40mail.gmail.com

On Mon, Mar 3, 2025 at 6:43 PM Melanie Plageman
<melanieplageman@gmail.com> wrote:
>
> Okay, I got cold feet today working on this. I actually think we
> probably want some kind of guc set (set like union/intersection/etc
> not set like assign a value) infrastructure for gucs that can be equal
> to any combination of predetermined values.

I ended up with a patch set that I was happy with which used the list
of string GUCs. I committed it in 9219093cab26. It changes
log_connections to a list of strings for the different aspects of
connection setup and supports the most common inputs for the boolean
version of log_connections for backwards compatibility. I did not end
up deprecating log_disconnections since it is rather late in the cycle
and that change could use more visibility. I suggest proposing that at
the beginning of the next release.

Thanks for your interest in this topic.

- Melanie