Обсуждение: [PATCH] Include application_name in "connection authorized" log message

Greetings,

* Don Seiler (don@seiler.us) wrote:
> In trying to troubleshoot the source of a recent connection storm, I was
> frustrated to find that the app name was not included in the connection
> messages. It is there in the log_line_prefix on the disconnection messages
> but I would prefer it be directly visible with the connection itself. With
> some guidance from Stephen Frost I've put together this patch which does
> that.

Yeah, I tend to agree that it'd be extremely useful to have this
included in the 'connection authorized' message.

> It adds a new application_name field to the Port struct, stores the
> application name there when processing the startup packet, and then reads
> from there when logging the "connection authorized" message.

Right, to have this included in the 'connection authorized' message, we
need to have it be captured early on, prior to generic GUC handling, and
stored momentairly to be used by the 'connection authorized' message.
Using Port for that seems reasonable (and we already store other things
like user and database there).

Taking a look at the patch itself...

diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 7698cd1f88..088ef346a8 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -135,6 +135,7 @@ typedef struct Port
      */
     char       *database_name;
     char       *user_name;
+    char       *application_name;
     char       *cmdline_options;
     List       *guc_options;

We should have some comments here about how this is the "startup packet
application_name" and that it's specifically used for the "connection
authorized" message and that it shouldn't really be used
post-connection-startup (the GUC should be used instead, as applications
can change it post-startup).

diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index a4b53b33cd..8e75c80728 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -2094,6 +2094,10 @@ retry1:
                                             pstrdup(nameptr));
                 port->guc_options = lappend(port->guc_options,
                                             pstrdup(valptr));
+
+                /* Copy application_name to port as well */
+                if (strcmp(nameptr, "application_name") == 0)
+                    port->application_name = pstrdup(valptr);
             }
             offset = valoffset + strlen(valptr) + 1;
         }

That comment feels a bit lacking- this is a pretty special case which
should be explained.

diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 09e0df290d..86db7630d5 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -266,8 +266,8 @@ PerformAuthentication(Port *port)
 #ifdef USE_SSL
             if (port->ssl_in_use)
                 ereport(LOG,
-                        (errmsg("connection authorized: user=%s database=%s SSL enabled (protocol=%s, cipher=%s,
bits=%d,compression=%s)", 
-                                port->user_name, port->database_name,
+                        (errmsg("connection authorized: user=%s database=%s application=%s SSL enabled (protocol=%s,
cipher=%s,bits=%d, compression=%s)", 
+                                port->user_name, port->database_name, port->application_name
                                 be_tls_get_version(port),
                                 be_tls_get_cipher(port),
                                 be_tls_get_cipher_bits(port),
@@ -275,8 +275,8 @@ PerformAuthentication(Port *port)
             else
 #endif
                 ereport(LOG,
-                        (errmsg("connection authorized: user=%s database=%s",
-                                port->user_name, port->database_name)));
+                        (errmsg("connection authorized: user=%s database=%s application=%s",
+                                port->user_name, port->database_name, port->application_name)));
         }
     }

You definitely need to be handling the case where application_name is
*not* passed in more cleanly.  I don't think we should output anything
different from what we do today in those cases.

Also, these don't need to be / shouldn't be 3 seperate patches/commits,
and there should be a sensible commit message which explains what the
change is entirely.

If you could update the patch accordingly and re-send, that'd be
awesome. :)

Thanks!

Stephen

On Wed, Jun 20, 2018 at 3:45 PM, Stephen Frost <sfrost@snowman.net> wrote:
> * Don Seiler (don@seiler.us) wrote:
>> In trying to troubleshoot the source of a recent connection storm, I was
>> frustrated to find that the app name was not included in the connection
>> messages. It is there in the log_line_prefix on the disconnection messages
>> but I would prefer it be directly visible with the connection itself. With
>> some guidance from Stephen Frost I've put together this patch which does
>> that.
>
> Yeah, I tend to agree that it'd be extremely useful to have this
> included in the 'connection authorized' message.

I don't get it.  It seems like a bad idea to me to copy information
that can already be logged using log_line_prefix into the message
itself.  If we start doing that, we'll end up with duplicated
information all over the place, and even worse, it won't be
consistent, because different people will want different things
duplicated into different messages.

Am I missing something?

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Greetings,

* Robert Haas (robertmhaas@gmail.com) wrote:
> On Wed, Jun 20, 2018 at 3:45 PM, Stephen Frost <sfrost@snowman.net> wrote:
> > * Don Seiler (don@seiler.us) wrote:
> >> In trying to troubleshoot the source of a recent connection storm, I was
> >> frustrated to find that the app name was not included in the connection
> >> messages. It is there in the log_line_prefix on the disconnection messages
> >> but I would prefer it be directly visible with the connection itself. With
> >> some guidance from Stephen Frost I've put together this patch which does
> >> that.
> >
> > Yeah, I tend to agree that it'd be extremely useful to have this
> > included in the 'connection authorized' message.
>
> I don't get it.  It seems like a bad idea to me to copy information
> that can already be logged using log_line_prefix into the message
> itself.  If we start doing that, we'll end up with duplicated
> information all over the place, and even worse, it won't be
> consistent, because different people will want different things
> duplicated into different messages.
>
> Am I missing something?

The issue here is exactly that at the point where we emit the
'connection authorized' message, we haven't processed generic GUCs from
the startup packet yet and therefore application_name isn't set as a
GUC and, as a result, isn't included in the 'connection authorized'
message, even if it's specified in log_line_prefix.

There's no way, today, to get the application name included in the
'connection authorized' message, which certainly seems unfortunate and a
bit surprising, hence this patch to fix that.

Thanks!

Stephen

On Fri, Jun 22, 2018 at 11:17 AM, Stephen Frost <sfrost@snowman.net> wrote:
> The issue here is exactly that at the point where we emit the
> 'connection authorized' message, we haven't processed generic GUCs from
> the startup packet yet and therefore application_name isn't set as a
> GUC and, as a result, isn't included in the 'connection authorized'
> message, even if it's specified in log_line_prefix.
>
> There's no way, today, to get the application name included in the
> 'connection authorized' message, which certainly seems unfortunate and a
> bit surprising, hence this patch to fix that.

OK, that makes more sense, but I'm still skeptical of adding a special
case particularly for application_name.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Greetings,

* Robert Haas (robertmhaas@gmail.com) wrote:
> On Fri, Jun 22, 2018 at 11:17 AM, Stephen Frost <sfrost@snowman.net> wrote:
> > The issue here is exactly that at the point where we emit the
> > 'connection authorized' message, we haven't processed generic GUCs from
> > the startup packet yet and therefore application_name isn't set as a
> > GUC and, as a result, isn't included in the 'connection authorized'
> > message, even if it's specified in log_line_prefix.
> >
> > There's no way, today, to get the application name included in the
> > 'connection authorized' message, which certainly seems unfortunate and a
> > bit surprising, hence this patch to fix that.
>
> OK, that makes more sense, but I'm still skeptical of adding a special
> case particularly for application_name.

I'd argue that application_name, when available, makes as much sense to
have in the connection authorization message as the other hard-coded
values (user, database), and those actually do get set and included in
the log_line_prefix when connection authorized is logged, if they're
asked for.  There certainly wasn't too much concern raised over adding
the SSL information to that same message, nor complaints from what I
recall.

I did also look at the other items available through log_line_prefix and
didn't see anything else that really felt like it should be included.

Thanks!

Stephen

On 2018-06-22 12:16:18 -0400, Robert Haas wrote:
> On Fri, Jun 22, 2018 at 11:17 AM, Stephen Frost <sfrost@snowman.net> wrote:
> > The issue here is exactly that at the point where we emit the
> > 'connection authorized' message, we haven't processed generic GUCs from
> > the startup packet yet and therefore application_name isn't set as a
> > GUC and, as a result, isn't included in the 'connection authorized'
> > message, even if it's specified in log_line_prefix.
> >
> > There's no way, today, to get the application name included in the
> > 'connection authorized' message, which certainly seems unfortunate and a
> > bit surprising, hence this patch to fix that.
> 
> OK, that makes more sense, but I'm still skeptical of adding a special
> case particularly for application_name.

I think a fair argument could be made that you'd want to have
application_name logged exactly once, not in every line. Just to cope
with log volume. With decent log analysis tools once is enough.

Greetings,

Andres Freund

On 2018-Jun-22, Andres Freund wrote:

> On 2018-06-22 12:16:18 -0400, Robert Haas wrote:

> > OK, that makes more sense, but I'm still skeptical of adding a special
> > case particularly for application_name.
> 
> I think a fair argument could be made that you'd want to have
> application_name logged exactly once, not in every line. Just to cope
> with log volume. With decent log analysis tools once is enough.

Seems harder than it sounds ... because if the user turns off
log_connections then it's not longer in the log.  And what about the
application changing it after the fact?  One idea would be to have a log
line designed specifically to be printed once at connection start (if
not log_connections) and then once immediately after it changes.  Am I
the only one for whom this sounds like overengineering?

I think the idea is nice, but I'm not sure about feasibility.

I further think that the idea in the OP is sound enough.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 2018-06-22 15:26:06 -0400, Alvaro Herrera wrote:
> On 2018-Jun-22, Andres Freund wrote:
> 
> > On 2018-06-22 12:16:18 -0400, Robert Haas wrote:
> 
> > > OK, that makes more sense, but I'm still skeptical of adding a special
> > > case particularly for application_name.
> > 
> > I think a fair argument could be made that you'd want to have
> > application_name logged exactly once, not in every line. Just to cope
> > with log volume. With decent log analysis tools once is enough.
> 
> Seems harder than it sounds ... because if the user turns off
> log_connections then it's not longer in the log.

That's superuser only, so I really don't quite buy that argument.


> And what about the application changing it after the fact?

I don't think that matters in a lot of scenarios. Poolers are the  big
exception to that, obviously.


> One idea would be to have a log line designed specifically to be
> printed once at connection start (if not log_connections) and then
> once immediately after it changes.  Am I the only one for whom this
> sounds like overengineering?

Yea. I think on balance, I don't buy that it's worth the cost. But I
don't think it's a clear cut "you don't need this".

Greetings,

Andres Freund

On 2018-Jun-22, Andres Freund wrote:

> On 2018-06-22 15:26:06 -0400, Alvaro Herrera wrote:
> > On 2018-Jun-22, Andres Freund wrote:
> > 
> > > On 2018-06-22 12:16:18 -0400, Robert Haas wrote:
> > 
> > > > OK, that makes more sense, but I'm still skeptical of adding a special
> > > > case particularly for application_name.
> > > 
> > > I think a fair argument could be made that you'd want to have
> > > application_name logged exactly once, not in every line. Just to cope
> > > with log volume. With decent log analysis tools once is enough.
> > 
> > Seems harder than it sounds ... because if the user turns off
> > log_connections then it's not longer in the log.
> 
> That's superuser only, so I really don't quite buy that argument.

I meant if the DBA disables it in postgresql.conf then the info is
nowhere.

> > One idea would be to have a log line designed specifically to be
> > printed once at connection start (if not log_connections) and then
> > once immediately after it changes.  Am I the only one for whom this
> > sounds like overengineering?
> 
> Yea. I think on balance, I don't buy that it's worth the cost. But I
> don't think it's a clear cut "you don't need this".

Yeah, that's true, particularly for the case of the connection pooler ...
(I'm anxious to see where the Odyssey thing goes, because pgbouncer at
this point doesn't seem to be cutting it anymore.  If odyssey takes off,
we could start listening more from them on what they need.)

For the time being, I think adding it to the log_connections line is a
good change, so +1.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 2018-06-22 15:50:06 -0400, Alvaro Herrera wrote:
> On 2018-Jun-22, Andres Freund wrote:
> 
> > On 2018-06-22 15:26:06 -0400, Alvaro Herrera wrote:
> > > On 2018-Jun-22, Andres Freund wrote:
> > > > I think a fair argument could be made that you'd want to have
> > > > application_name logged exactly once, not in every line. Just to cope
> > > > with log volume. With decent log analysis tools once is enough.
> > > 
> > > Seems harder than it sounds ... because if the user turns off
> > > log_connections then it's not longer in the log.
> > 
> > That's superuser only, so I really don't quite buy that argument.
> 
> I meant if the DBA disables it in postgresql.conf then the info is
> nowhere.

I'm not following - application_name isn't logged anywhere by default
currently either.


Greetings,

Andres Freund

On 2018-Jun-22, Andres Freund wrote:

> On 2018-06-22 15:50:06 -0400, Alvaro Herrera wrote:
> > On 2018-Jun-22, Andres Freund wrote:
> > 
> > > On 2018-06-22 15:26:06 -0400, Alvaro Herrera wrote:
> > > > On 2018-Jun-22, Andres Freund wrote:
> > > > > I think a fair argument could be made that you'd want to have
> > > > > application_name logged exactly once, not in every line. Just to cope
> > > > > with log volume. With decent log analysis tools once is enough.
> > > > 
> > > > Seems harder than it sounds ... because if the user turns off
> > > > log_connections then it's not longer in the log.
> > > 
> > > That's superuser only, so I really don't quite buy that argument.
> > 
> > I meant if the DBA disables it in postgresql.conf then the info is
> > nowhere.
> 
> I'm not following - application_name isn't logged anywhere by default
> currently either.

Right.  I +1'd the proposal to have it in the log_connections line.

My mind was wandering about doing more than that (or doing something
different), but let's not derail the thread.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Wed, Jun 20, 2018 at 2:45 PM, Stephen Frost <sfrost@snowman.net> wrote:

diff --git a/src/include/libpq/libpq-be.h b/src/include/libpq/libpq-be.h
index 7698cd1f88..088ef346a8 100644
--- a/src/include/libpq/libpq-be.h
+++ b/src/include/libpq/libpq-be.h
@@ -135,6 +135,7 @@ typedef struct Port
         */
        char       *database_name;
        char       *user_name;
+       char       *application_name;
        char       *cmdline_options;
        List       *guc_options;

We should have some comments here about how this is the "startup packet
application_name" and that it's specifically used for the "connection
authorized" message and that it shouldn't really be used
post-connection-startup (the GUC should be used instead, as applications
can change it post-startup).

Makes sense. I've now moved that variable declaration underneath the others with a small comment block above it.

 

diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index a4b53b33cd..8e75c80728 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -2094,6 +2094,10 @@ retry1:
                                                                                        pstrdup(nameptr));
                                port->guc_options = lappend(port->guc_options,
                                                                                        pstrdup(valptr));
+
+                               /* Copy application_name to port as well */
+                               if (strcmp(nameptr, "application_name") == 0)
+                                       port->application_name = pstrdup(valptr);
                        }
                        offset = valoffset + strlen(valptr) + 1;
                }

That comment feels a bit lacking- this is a pretty special case which
should be explained.

I've added longer comment explaining again why we are doing this here.

 

diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 09e0df290d..86db7630d5 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -266,8 +266,8 @@ PerformAuthentication(Port *port)
 #ifdef USE_SSL
                        if (port->ssl_in_use)
                                ereport(LOG,
-                                               (errmsg("connection authorized: user=%s database=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
-                                                               port->user_name, port->database_name,
+                                               (errmsg("connection authorized: user=%s database=%s application=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
+                                                               port->user_name, port->database_name, port->application_name
                                                                be_tls_get_version(port),
                                                                be_tls_get_cipher(port),
                                                                be_tls_get_cipher_bits(port),
@@ -275,8 +275,8 @@ PerformAuthentication(Port *port)
                        else
 #endif
                                ereport(LOG,
-                                               (errmsg("connection authorized: user=%s database=%s",
-                                                               port->user_name, port->database_name)));
+                                               (errmsg("connection authorized: user=%s database=%s application=%s",
+                                                               port->user_name, port->database_name, port->application_name)));
                }
        }

You definitely need to be handling the case where application_name is
*not* passed in more cleanly.  I don't think we should output anything
different from what we do today in those cases.

I've added some conditional logic similar to the ternary operator usage in src/backend/catalog/pg_collation.c:92. If application_name is set, we'll include "application=%s" in the log message, otherwise we make no mention of it now (output will be identical to what we currently do).

 

Also, these don't need to be / shouldn't be 3 seperate patches/commits,
and there should be a sensible commit message which explains what the
change is entirely.

After much head scratching/banging on both our parts yesterday, I've finally figured this out. Thanks again for your patience and time.

 

If you could update the patch accordingly and re-send, that'd be
awesome. :)

See attached. 

--

Don Seiler
www.seiler.us

Hi,

I've reviewed this patch, log entry is the following when "log_connection = on" ajnd application_name is set:

    2018-06-25 17:01:30.079 CEST [22002] LOG:  connection authorized: user=postgres database=postgres application=psql

when application_name is not set:

    2018-06-25 17:04:22.653 CEST [22076] LOG:  connection authorized: user=dbuser database=test

I would prefer the following output to conform to elog.c output:

    2018-06-25 17:32:46.854 CEST [23265] LOG:  connection authorized: user=postgres database=postgres application=[unknown]

I think this will make changes to src/backend/utils/init/postinit.c code more readable with less duplicated code when written as follow:

diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 09e0df290d..0b3323eaf2 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -263,11 +263,16 @@ PerformAuthentication(Port *port)
                }
                else
                {
+                       const char *appname = port->application_name;
+
+                       if (appname == NULL || *appname == '\0')
+                               appname = _("[unknown]");
+
 #ifdef USE_SSL
                        if (port->ssl_in_use)
                                ereport(LOG,
-                                               (errmsg("connection authorized: user=%s database=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
-                                                               port->user_name, port->database_name,
+                                               (errmsg("connection authorized: user=%s database=%s application=%s SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s)",
+                                                               port->user_name, port->database_name, appname,
                                                                be_tls_get_version(port),
                                                                be_tls_get_cipher(port),
                                                                be_tls_get_cipher_bits(port),
@@ -275,8 +280,8 @@ PerformAuthentication(Port *port)
                        else
 #endif
                                ereport(LOG,
-                                               (errmsg("connection authorized: user=%s database=%s",
-                                                               port->user_name, port->database_name)));
+                                               (errmsg("connection authorized: user=%s database=%s application=%s",
+                                                               port->user_name, port->database_name, appname)));
                }
        }
 

-- 
Gilles Darold
Consultant PostgreSQL
http://dalibo.com - http://dalibo.org

On Mon, Jun 25, 2018 at 10:50 AM, Gilles Darold <gilles.darold@dalibo.com> wrote:

I would prefer the following output to conform to elog.c output:

    2018-06-25 17:32:46.854 CEST [23265] LOG:  connection authorized: user=postgres database=postgres application=[unknown]

Hello Gilles,

The different cases were for Stephen's request earlier in this thread. I'm happy to write it either way and agree it would be nice to not have a lot of duplicate code. Do you want me to submit another patch?

-- 
Gilles Darold
Consultant PostgreSQL
http://dalibo.com - http://dalibo.org

Greetings

On Mon, Jun 25, 2018 at 15:57 Don Seiler <don@seiler.us> wrote:

On Mon, Jun 25, 2018 at 10:50 AM, Gilles Darold <gilles.darold@dalibo.com> wrote:

I would prefer the following output to conform to elog.c output:

    2018-06-25 17:32:46.854 CEST [23265] LOG:  connection authorized: user=postgres database=postgres application=[unknown]

Hello Gilles,

The different cases were for Stephen's request earlier in this thread. I'm happy to write it either way and agree it would be nice to not have a lot of duplicate code. Do you want me to submit another patch?

I think it’s better to not change the line when application name isn’t being set, as the latest patch has. That also matches how we handle the SSL info- it’s only shown if ssl is in place on the connection. 

-- 
Gilles Darold
Consultant PostgreSQL
http://dalibo.com - http://dalibo.org

On 21.06.18 16:21, Don Seiler wrote:
> -                                               (errmsg("connection
> authorized: user=%s database=%s",
> -                                                             
>  port->user_name, port->database_name)));
> +                                               (errmsg("connection
> authorized: user=%s database=%s application=%s",
> +                                                             
>  port->user_name, port->database_name, port->application_name)));

Why is it "application" and not "application_name"?

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 02.07.18 15:12, Don Seiler wrote:
> On Mon, Jul 2, 2018 at 2:13 AM, Peter Eisentraut
> <peter.eisentraut@2ndquadrant.com
> <mailto:peter.eisentraut@2ndquadrant.com>> wrote:
> 
>     On 21.06.18 16:21, Don Seiler wrote:
>     > -                                               (errmsg("connection
>     > authorized: user=%s database=%s",
>     > -                                                             
>     >  port->user_name, port->database_name)));
>     > +                                               (errmsg("connection
>     > authorized: user=%s database=%s application=%s",
>     > +                                                             
>     >  port->user_name, port->database_name, port->application_name)));
> 
>     Why is it "application" and not "application_name"?
> 
> 
> I was trying to be consistent since we don't use "user_name" or
> "database_name" as labels even though those are the variable names.

"user" and "database" are the keys used in the startup packet.

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Greetings,

* Peter Eisentraut (peter.eisentraut@2ndquadrant.com) wrote:
> On 02.07.18 15:12, Don Seiler wrote:
> > On Mon, Jul 2, 2018 at 2:13 AM, Peter Eisentraut
> > <peter.eisentraut@2ndquadrant.com
> > <mailto:peter.eisentraut@2ndquadrant.com>> wrote:
> >
> >     On 21.06.18 16:21, Don Seiler wrote:
> >     > -                                               (errmsg("connection
> >     > authorized: user=%s database=%s",
> >     > -                                                             
> >     >  port->user_name, port->database_name)));
> >     > +                                               (errmsg("connection
> >     > authorized: user=%s database=%s application=%s",
> >     > +                                                             
> >     >  port->user_name, port->database_name, port->application_name)));
> >
> >     Why is it "application" and not "application_name"?
> >
> >
> > I was trying to be consistent since we don't use "user_name" or
> > "database_name" as labels even though those are the variable names.
>
> "user" and "database" are the keys used in the startup packet.

There's a good deal lacking here when it comes to consistency- the
string that users actually use most (the libpq connection string)
requires the database to be specified as 'dbname', not 'database', for
example.

Still, what's specified in the libpq connection string is
'application_name' and that's what the GUC is, and what's in the startup
packet, so it seems like we could at least be consistent with that.

Don, do you want to update the patch accordingly?  If not, I'm happy to
handle it when I go to commit it, which I'm thinking of doing sometime
this weekend as it seems to be pretty uncontroversial at this point.

As an independent patch, it might be nice to have libpq accept
'database' in place of 'dbname' and update the docs to recommend that,
and maybe then even have a 'database' read-only GUC, and maybe a 'user'
one too (though it looks like we might have to hack the grammar some to
get that to work cleanly...), just to move things to be more consistent
across the board.  That's all very clearly independent from this patch
though.

Thanks!

Stephen

On 13/07/2018 20:20, Don Seiler wrote:
> See attached for latest revision.

This doesn't compile with SSL enabled because there is a comma missing.

This implementation doesn't run the application_name through
check_application_name(), so it could end up logging application_name
values that are otherwise not acceptable.  I'm not sure of the best way
to fix that.

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Greetings,

* Don Seiler (don@seiler.us) wrote:
> On Mon, Jul 30, 2018 at 5:20 AM, Peter Eisentraut <
> peter.eisentraut@2ndquadrant.com> wrote:
>
> > On 13/07/2018 20:20, Don Seiler wrote:
> > > See attached for latest revision.
> >
> > This doesn't compile with SSL enabled because there is a comma missing.
>
> Hmm I'll check this out tonight. Sorry I wasn't able to get to this until
> now.

Thanks.

> > This implementation doesn't run the application_name through
> > check_application_name(), so it could end up logging application_name
> > values that are otherwise not acceptable.  I'm not sure of the best way
> > to fix that.
>
> Is the concern that any user can set their client's application name value
> to any string they want? Is there a reason we can't call
> check_application_name() before setting it in the Port struct in
> postmaster.c?

I've not looked very closely, but I don't think it's necessairly a big
deal to print out the application name provided by the client system
into the log before we run check_application_name(), as long as there
isn't any risk that printing it out or passing it around without
performing that check will cause incorrect operation or such.

I'm guessing it's not easy because check_application_name() isn't easily
available from where we're wanting to print it out or earlier, but,
again, haven't looked closely.  If you aren't sure or run into issues,
feel free to ping me on slack and I'll be happy to help.

Thanks!

Stephen

Stephen Frost <sfrost@snowman.net> writes:
> * Don Seiler (don@seiler.us) wrote:
>> Is the concern that any user can set their client's application name value
>> to any string they want? Is there a reason we can't call
>> check_application_name() before setting it in the Port struct in
>> postmaster.c?

> I've not looked very closely, but I don't think it's necessairly a big
> deal to print out the application name provided by the client system
> into the log before we run check_application_name(), as long as there
> isn't any risk that printing it out or passing it around without
> performing that check will cause incorrect operation or such.

I think the issue is exactly that putting a malformed appname into the
postmaster log could confuse log-reading apps (eg by causing encoding
problems).  Moreover, if you don't check it then the appname recorded
by log_connections would not match appearances for the same session
later in the log, which puts the entire use-case for this patch into
question.  So no, this concern must not be dismissed.

However ... I've not looked at the patch, but I thought the idea was to
allow assignment of that GUC to occur before the log_connections log entry
is emitted, so that it'd show up in the entry's log_line_prefix.  Wouldn't
check_application_name happen automatically at that point?

            regards, tom lane

Greetings,

* Tom Lane (tgl@sss.pgh.pa.us) wrote:
> Stephen Frost <sfrost@snowman.net> writes:
> > * Don Seiler (don@seiler.us) wrote:
> >> Is the concern that any user can set their client's application name value
> >> to any string they want? Is there a reason we can't call
> >> check_application_name() before setting it in the Port struct in
> >> postmaster.c?
>
> > I've not looked very closely, but I don't think it's necessairly a big
> > deal to print out the application name provided by the client system
> > into the log before we run check_application_name(), as long as there
> > isn't any risk that printing it out or passing it around without
> > performing that check will cause incorrect operation or such.
>
> I think the issue is exactly that putting a malformed appname into the
> postmaster log could confuse log-reading apps (eg by causing encoding
> problems).

Evidently, I need to go look at this, since it seems like this would be
the exact same risk with "user", which is part of why I wasn't terribly
concerned about it here.  Considering the concern raised here, if we're
serious about that issue, then I wonder if we have an existing issue.

> Moreover, if you don't check it then the appname recorded
> by log_connections would not match appearances for the same session
> later in the log, which puts the entire use-case for this patch into
> question.  So no, this concern must not be dismissed.

If the call to check_application_name() fails then I had been expecting
the connection to fail.  If we continue to let the connection go on then
we've already got an issue as someone might pass in an application name
that isn't being set to the GUC and isn't being therefore used in the
existing log_line_prefix where it should be.

> However ... I've not looked at the patch, but I thought the idea was to
> allow assignment of that GUC to occur before the log_connections log entry
> is emitted, so that it'd show up in the entry's log_line_prefix.  Wouldn't
> check_application_name happen automatically at that point?

We log that message quite early and it certainly didn't look trivial to
set up the GUC to be already in place at that point, so the plan was to
simply spit out what gets passed in (as we were doing for "user", if I'm
remembering that code correctly...).

Thanks!

Stephen

Greetings Don,

* Don Seiler (don@seiler.us) wrote:
> On Tue, Aug 7, 2018 at 8:46 AM, Stephen Frost <sfrost@snowman.net> wrote:
> > * Don Seiler (don@seiler.us) wrote:
> > > On Mon, Jul 30, 2018 at 5:20 AM, Peter Eisentraut <
> > > peter.eisentraut@2ndquadrant.com> wrote:
> > >
> > > > On 13/07/2018 20:20, Don Seiler wrote:
> > > > > See attached for latest revision.
> > > >
> > > > This doesn't compile with SSL enabled because there is a comma missing.
> > >
> > > Hmm I'll check this out tonight. Sorry I wasn't able to get to this until
> > > now.
> >
> > Thanks.
>
> Attaching a new patch fixing the missing comma. Sorry for missing this,
> obviously my previous test builds didn't have SSL enabled. Mea culpa.

No worries, it happens. :)  Thanks for working on a new patch.

> I'll send a new one if we require a change for the check_application_name()
> concern. I need the git rebase/autosquash practice anyway.

Sounds like maybe we should be looking at if the concerns raised by Tom
might be applicable to the other strings being written out by that log
message, and if not, why not, and can we do whatever we're doing for
those for application_name as well.

Thanks!

Stephen

Stephen Frost <sfrost@snowman.net> writes:
> * Tom Lane (tgl@sss.pgh.pa.us) wrote:
>> Moreover, if you don't check it then the appname recorded
>> by log_connections would not match appearances for the same session
>> later in the log, which puts the entire use-case for this patch into
>> question.  So no, this concern must not be dismissed.

> If the call to check_application_name() fails then I had been expecting
> the connection to fail.  If we continue to let the connection go on then
> we've already got an issue as someone might pass in an application name
> that isn't being set to the GUC and isn't being therefore used in the
> existing log_line_prefix where it should be.

No, check_application_name doesn't reject funny names, it just silently
modifies them in-place.

>> However ... I've not looked at the patch, but I thought the idea was to
>> allow assignment of that GUC to occur before the log_connections log entry
>> is emitted, so that it'd show up in the entry's log_line_prefix.  Wouldn't
>> check_application_name happen automatically at that point?

> We log that message quite early and it certainly didn't look trivial to
> set up the GUC to be already in place at that point, so the plan was to
> simply spit out what gets passed in (as we were doing for "user", if I'm
> remembering that code correctly...).

Hm.  Well, the code isn't exactly complicated, you could duplicate it.
Or maybe better refactor to allow it to be called from $wherever.
Looks like check_cluster_name, for one, could also share use of
an ascii-lobotomizing subroutine.

But having said that, I don't exactly see why you couldn't force it
with an ultimately-redundant SetConfigOption call to put the value
in place before the ereport happens.  The GUC machinery is surely
functional before we do authorization.

            regards, tom lane

Greetings Tom,

* Tom Lane (tgl@sss.pgh.pa.us) wrote:
> Stephen Frost <sfrost@snowman.net> writes:
> > * Tom Lane (tgl@sss.pgh.pa.us) wrote:
> >> Moreover, if you don't check it then the appname recorded
> >> by log_connections would not match appearances for the same session
> >> later in the log, which puts the entire use-case for this patch into
> >> question.  So no, this concern must not be dismissed.
>
> > If the call to check_application_name() fails then I had been expecting
> > the connection to fail.  If we continue to let the connection go on then
> > we've already got an issue as someone might pass in an application name
> > that isn't being set to the GUC and isn't being therefore used in the
> > existing log_line_prefix where it should be.
>
> No, check_application_name doesn't reject funny names, it just silently
> modifies them in-place.

Blargh, that doesn't seem particularly good to me, but I guess no one
has been comlaining about it either.

> >> However ... I've not looked at the patch, but I thought the idea was to
> >> allow assignment of that GUC to occur before the log_connections log entry
> >> is emitted, so that it'd show up in the entry's log_line_prefix.  Wouldn't
> >> check_application_name happen automatically at that point?
>
> > We log that message quite early and it certainly didn't look trivial to
> > set up the GUC to be already in place at that point, so the plan was to
> > simply spit out what gets passed in (as we were doing for "user", if I'm
> > remembering that code correctly...).
>
> Hm.  Well, the code isn't exactly complicated, you could duplicate it.
> Or maybe better refactor to allow it to be called from $wherever.
> Looks like check_cluster_name, for one, could also share use of
> an ascii-lobotomizing subroutine.

Yeah, I'd be alright with either of those approaches.

> But having said that, I don't exactly see why you couldn't force it
> with an ultimately-redundant SetConfigOption call to put the value
> in place before the ereport happens.  The GUC machinery is surely
> functional before we do authorization.

If that's the approach you think makes the most sense, I wouldn't object
to it.  I will point out that we'd end up with the application name in
the log line if it's also included in log_line_prefix, but that's what
happens with "user" anyway, isn't it?, so that doesn't seem to be a big
deal.  I do think it's still good to have appplication_name explicitly
in the log message for users who want to just log application_name on
connection and not have it on every single log line.

Thanks!

Stephen

Stephen Frost <sfrost@snowman.net> writes:
> * Tom Lane (tgl@sss.pgh.pa.us) wrote:
>> But having said that, I don't exactly see why you couldn't force it
>> with an ultimately-redundant SetConfigOption call to put the value
>> in place before the ereport happens.  The GUC machinery is surely
>> functional before we do authorization.

> If that's the approach you think makes the most sense, I wouldn't object
> to it.  I will point out that we'd end up with the application name in
> the log line if it's also included in log_line_prefix, but that's what
> happens with "user" anyway, isn't it?, so that doesn't seem to be a big
> deal.  I do think it's still good to have appplication_name explicitly
> in the log message for users who want to just log application_name on
> connection and not have it on every single log line.

Well, if you're going to insist on that part, it's probably not worth
making the application_name GUC have inconsistent behavior.

            regards, tom lane

Don Seiler <don@seiler.us> writes:
> On Tue, Aug 7, 2018 at 11:29 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Well, if you're going to insist on that part, it's probably not worth
>> making the application_name GUC have inconsistent behavior.

> OK so just to make sure I understand:

> 1. We want to make a generic, central ascii-lobotomizing function similar
> to check_application_name that we can re-use there and for other checks (eg
> user name).
> 2. Change check_application_name to call this function (or just call this
> function instead of check_application_name()?)

check_application_name's API is dictated by the GUC check-hook interface,
and doesn't really make sense for this other use.  So the first part of
that, not the second.

> 3. Call this function when storing the value in the port struct.

I'm not sure where exactly is the most sensible place to call it,
but trying to minimize the number of places that know about this
kluge seems like a good principle.

            regards, tom lane

Greetings Don!

* Don Seiler (don@seiler.us) wrote:
> On Tue, Aug 7, 2018 at 12:32 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> > Don Seiler <don@seiler.us> writes:
> >
> > > 1. We want to make a generic, central ascii-lobotomizing function similar
> > > to check_application_name that we can re-use there and for other checks
> > (eg
> > > user name).
> > > 2. Change check_application_name to call this function (or just call this
> > > function instead of check_application_name()?)
> >
> > check_application_name's API is dictated by the GUC check-hook interface,
> > and doesn't really make sense for this other use.  So the first part of
> > that, not the second.
> >
> > > 3. Call this function when storing the value in the port struct.
> >
> > I'm not sure where exactly is the most sensible place to call it,
> > but trying to minimize the number of places that know about this
> > kluge seems like a good principle.
>
> OK I created a new function called clean_ascii() in common/string.c. I call
> this from my new logic in postmaster.c as well as replacing the logic in
> guc.c's check_application_name() and check_cluster_name().

Since we're putting it into common/string.c (which seems pretty
reasonable to me, at least), I went ahead and changed it to be
'pg_clean_ascii'.  I didn't see any other obvious cases where we could
use this function (though typecmds.c does have an interesting ASCII
check for type categories..).

Otherwise, I added some comments, added application_name to the
replication 'connection authorized' messages (seems like we really
should be consistent across all of them...), ran it through pgindent,
and updated a variable name or two here and there.

> I've been fighting my own confusion with git and rebasing and fighting the
> same conflicts over and over and over, but this patch should be what I
> want. If anyone has time to review my git process, I would appreciate it. I
> must be doing something wrong to have these same conflicts every time I
> rebase (or I completely misunderstand what it actually does).

I'd be happy to chat about it sometime, of course, just have to find
time when we both have a free moment. :)

Attached is the updated patch.  If you get a chance to look over it
again and make sure it looks good to you, that'd be great.  I did a bit
of testing of it myself but wouldn't complain if someone else wanted to
also.

One thing I noticed while testing is that our 'disconnection' message
still emits 'database=' for replication connections even though the
'connection authorized' message doesn't (presumably because we realized
it's a bit silly to do so when we say 'replication connection'...).
Seems like it'd be nice to have the log_connection / log_disconnection
messages have some consistency about them but that's really a different
discussion from this.

Thanks!

Stephen

On 24/09/2018 23:10, Stephen Frost wrote:
> Since we're putting it into common/string.c (which seems pretty
> reasonable to me, at least), I went ahead and changed it to be
> 'pg_clean_ascii'.  I didn't see any other obvious cases where we could
> use this function (though typecmds.c does have an interesting ASCII
> check for type categories..).

I think we might want to contain this functionality to guc.c.  In
general, we should allow more non-ASCII things rather than encourage
more "ASCII cleaning".

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Greetings,

* Peter Eisentraut (peter.eisentraut@2ndquadrant.com) wrote:
> On 24/09/2018 23:10, Stephen Frost wrote:
> > Since we're putting it into common/string.c (which seems pretty
> > reasonable to me, at least), I went ahead and changed it to be
> > 'pg_clean_ascii'.  I didn't see any other obvious cases where we could
> > use this function (though typecmds.c does have an interesting ASCII
> > check for type categories..).
>
> I think we might want to contain this functionality to guc.c.  In
> general, we should allow more non-ASCII things rather than encourage
> more "ASCII cleaning".

If we're going in that direction then I'd ask again why we are doing
things here to clean down to 'ascii only' when 'user', for example, is
not "cleaned":

2018-09-27 17:26:25.550 EDT [12579] êāŁƛǚ@postgres LOG:  connection authorized: user=êāŁƛǚ database=postgres SSL
enabled(protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, compression=off) 

Meaning we get all kinds of interesting in the exact same message that
we're talking about here when someone has a funky username.

It's not like we don't *also* update the process title with the username
too:

postgres 14811  0.0  0.0 327596 12432 ?        Ss   17:37   0:00 postgres: 10/main: êāŁ?ǚ postgres 127.0.0.1(54252)
idle

Meaning that the "cleaning" for 'cluster name', whose entire purpose is
to go into the process title, hardly makes sense either.

I get that username and database are things that an admin can control
and perhaps there's an argument that someone's broken log parsing system
is "ok" because it only ever has to deal with known-simple usernames or
databases because that's all the admin ever created, but I don't think
we have historically, nor should we now, write code to help keep
objectively broken systems working across major (or even minor, really,
though I'm certainly not pushing for this change to go into
back-branches) releases.

I'd be just as happy to rip out the code that's cleaning things down to
ASCII in all of these.

Of course, if I'm missing something as to why the ascii-cleaning makes
sense or is necessary, I'm all ears, but I'm just not seeing it.

Thanks!

Stephen

Hi,

On 2018-09-27 17:41:56 -0400, Stephen Frost wrote:
> Of course, if I'm missing something as to why the ascii-cleaning makes
> sense or is necessary, I'm all ears, but I'm just not seeing it.

There's many reasons. For example you can send terminal control
characters to the server. When somebody then looks at the log, you can
screw with them pretty good, unless they're always careful to go through
less (without -r).  We should be *more* not *less* careful about this
kind of hting.

Greetings,

Andres Freund

Greetings,

* Andres Freund (andres@anarazel.de) wrote:
> On 2018-09-27 17:41:56 -0400, Stephen Frost wrote:
> > Of course, if I'm missing something as to why the ascii-cleaning makes
> > sense or is necessary, I'm all ears, but I'm just not seeing it.
>
> There's many reasons. For example you can send terminal control
> characters to the server. When somebody then looks at the log, you can
> screw with them pretty good, unless they're always careful to go through
> less (without -r).  We should be *more* not *less* careful about this
> kind of hting.

I seriously doubt we're going to start stripping usernames down to ASCII
for them to be displayed in the log file.

I'll put it down to this then- we aren't changing things with this
patch in that regard, and the function needs to be available in both
places and I don't think including guc.h into postmaster.c is a good
idea.

I'll add a comment that hackers should try to avoid using the function,
and that we should really try to do better here but it's unclear how to
do so without inviting problems, along with your comment above regarding
the kinds of problems we could run into.

Thanks!

Stephen

On September 27, 2018 2:55:56 PM PDT, Stephen Frost <sfrost@snowman.net> wrote:
>Greetings,
>
>* Andres Freund (andres@anarazel.de) wrote:
>> On 2018-09-27 17:41:56 -0400, Stephen Frost wrote:
>> > Of course, if I'm missing something as to why the ascii-cleaning
>makes
>> > sense or is necessary, I'm all ears, but I'm just not seeing it.
>>
>> There's many reasons. For example you can send terminal control
>> characters to the server. When somebody then looks at the log, you
>can
>> screw with them pretty good, unless they're always careful to go
>through
>> less (without -r).  We should be *more* not *less* careful about this
>> kind of hting.
>
>I seriously doubt we're going to start stripping usernames down to
>ASCII
>for them to be displayed in the log file.

So? As you say, they are much more control from the a admins of the server.  I guess at some point we should have more
expansivewhitelisting than just ASCII, but that seems separate. 

Andres
--
Sent from my Android device with K-9 Mail. Please excuse my brevity.

Greetings,

* Andres Freund (andres@anarazel.de) wrote:
> On September 27, 2018 2:55:56 PM PDT, Stephen Frost <sfrost@snowman.net> wrote:
> >* Andres Freund (andres@anarazel.de) wrote:
> >> On 2018-09-27 17:41:56 -0400, Stephen Frost wrote:
> >> > Of course, if I'm missing something as to why the ascii-cleaning
> >makes
> >> > sense or is necessary, I'm all ears, but I'm just not seeing it.
> >>
> >> There's many reasons. For example you can send terminal control
> >> characters to the server. When somebody then looks at the log, you
> >can
> >> screw with them pretty good, unless they're always careful to go
> >through
> >> less (without -r).  We should be *more* not *less* careful about this
> >> kind of hting.
> >
> >I seriously doubt we're going to start stripping usernames down to
> >ASCII
> >for them to be displayed in the log file.
>
> So? As you say, they are much more control from the a admins of the server.  I guess at some point we should have
moreexpansive whitelisting than just ASCII, but that seems separate. 

I still don't see that as a reason for tools to be suseptible to serious
issues if a funky user gets created and I'd be surprised if there
weren't other ways to get funky characters into the log file, but that's
all ultimately an independent issue from this.  I'll add the comments as
discussed and discourage using the clean ascii function, but otherwise
keep things as-is in that regard.

Thanks!

Stephen

Greetings, all,

* Stephen Frost (sfrost@snowman.net) wrote:
> I still don't see that as a reason for tools to be suseptible to serious
> issues if a funky user gets created and I'd be surprised if there
> weren't other ways to get funky characters into the log file, but that's
> all ultimately an independent issue from this.  I'll add the comments as
> discussed and discourage using the clean ascii function, but otherwise
> keep things as-is in that regard.

Updated patch with lots of comments added around pg_clean_ascii() about
why it exists, why we do the cleaning, and warnings to discourage people
from using it without good cause.  I've also done some additional
testing with it and it seems to be working well.  I'll poke at it a bit
more tomorrow but if there aren't any other concerns, I'll commit it
towards the end of the day.

Thanks!

Stephen

Greetings,

* Stephen Frost (sfrost@snowman.net) wrote:
> * Stephen Frost (sfrost@snowman.net) wrote:
> > I still don't see that as a reason for tools to be suseptible to serious
> > issues if a funky user gets created and I'd be surprised if there
> > weren't other ways to get funky characters into the log file, but that's
> > all ultimately an independent issue from this.  I'll add the comments as
> > discussed and discourage using the clean ascii function, but otherwise
> > keep things as-is in that regard.
>
> Updated patch with lots of comments added around pg_clean_ascii() about
> why it exists, why we do the cleaning, and warnings to discourage people
> from using it without good cause.  I've also done some additional
> testing with it and it seems to be working well.  I'll poke at it a bit
> more tomorrow but if there aren't any other concerns, I'll commit it
> towards the end of the day.

Pushed, thanks all for the help and discussion, and thanks to Don for
his patch!

Thanks!

Stephen