Re: Log connection establishment timings

Hi,

On Fri, Feb 28, 2025 at 05:52:35PM -0500, Melanie Plageman wrote:
> On Fri, Feb 28, 2025 at 12:54 AM Bertrand Drouvot
> <bertranddrouvot(dot)pg(at)gmail(dot)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.

Agree.

> > > 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.

Okay, yeah most probably.

> > 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.

Thanks for the updated version!

> We have to be really careful about when log_connections is actually
> set before we use it -- I fixed some issues with that.

Good catch! Yeah for the EXEC_BACKEND case we need to wait that read_nondefault_variables()
in SubPostmasterMain() is executed.

Looking at 0001, a few random comments:

=== 1

#include "utils/varlena.h"
+#include "utils/guc_hooks.h"

wrong ordering?

=== 2

+/*
+ * Validate the input for the log_connections GUC.
+ */
+bool
+check_log_connections(char **newval, void **extra, GucSource source)
+{

This function is pretty close to check_debug_io_direct() for example and its
overall content, memory management, looks good to me. I just have a few
following comments about it.

I was just wondering why:

"
+ 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;
+ }
"

but yeah that probably makes more sense that way.

=== 3

+ if (pg_strcasecmp(*newval, "all") == 0)
+ effval = "received, authenticated, authorized, disconnected";

Not sure this one is needed, see comment "=== 5".

=== 4

+void
+assign_log_connections(const char *newval, void *extra)
+{
+ log_connections = *((int *) extra);
+}

Not written in the exact same way as assign_debug_io_direct() but that's fine.

=== 5

+typedef enum ConnectionLogOption
+{
+ LOG_CONNECTION_RECEIVED = (1 << 0),
+ LOG_CONNECTION_AUTHENTICATED = (1 << 1),
+ LOG_CONNECTION_AUTHORIZED = (1 << 2),
+ LOG_CONNECTION_DISCONNECTED = (1 << 3),
+} ConnectionLogOption;

I wonder if it would make sense to add LOG_CONNECTION_ALL here
(LOG_CONNECTION_RECEIVED | LOG_CONNECTION_AUTHENTICATED ..)

That sounds a better place (than defining "all" in check_log_connections()) to
me. It's also how it is done in MonotonicFunction.

That way we could avoid the special case in check_log_connections() and it
looks less likely that we miss to add new flags in LOG_CONNECTION_ALL should
we add more options, thoughts?

We'd need to change all the checks that you added (around log_connections) to
also add a check on LOG_CONNECTION_ALL though.

=== 6

Also not sure if it's worth adding a "MAX" (like it's done for relopt_kind)
because we'd probably not go over it anyay.

"
/* some compilers treat enums as signed ints, so we can't use 1 << 31 */
RELOPT_KIND_MAX = (1 << 30)
"

Just mentioning in passing as I just realized there is this check in relopt_kind.

=== 7

s/ConnectionLogOption/LogConnectionOption/? (as it is linked to "log_connections")

=== 8

All the TAP tests have been modified that way:

-$node->append_conf('postgresql.conf', "log_connections = on");
+$node->append_conf('postgresql.conf', "log_connections = 'all'");

Is it worh to add some checks for the other values?

I did a few manual checks and that seems to work as expected.

I'll look at 0002 later.

Regards,

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