Thread: Log message for GSS connection is missing once connection authorization is successful.

Hi,

Log message for GSS connection is missing once connection
authorization is successful. We have similar log messages for SSL
connections once the connection authorization is successful. This
message will help the user to identify the connection that was
selected from the logfile. I'm not sure if this log message was
intentionally left out due to some reason for GSS.
If the above analysis looks correct, then please find a patch that
adds log for gss connections.

Thoughts?

Regards,
Vignesh
EnterpriseDB: http://www.enterprisedb.com

On Wed, Oct 28, 2020 at 8:29 AM vignesh C <vignesh21@gmail.com> wrote:
>
> Log message for GSS connection is missing once connection
> authorization is successful. We have similar log messages for SSL
> connections once the connection authorization is successful. This
> message will help the user to identify the connection that was
> selected from the logfile. I'm not sure if this log message was
> intentionally left out due to some reason for GSS.
> If the above analysis looks correct, then please find a patch that
> adds log for gss connections.
>
> Thoughts?
>

+1 for the idea. This is useful in knowing whether or not the user is
authenticated using GSS APIs.

Here are few comments on the patch:

1. How about using(like below) #ifdef, #elif ... #endif directives
instead of #ifdef, #endif, #ifdef, #endif?

#ifdef USE_SSL
       blah,blah,blah...
#elif defined(ENABLE_GSS)
       blah,blah,blah...
#else
       blah,blah,blah...
#endif

2. I think we must use be_gssapi_get_auth(port) instead of
be_gssapi_get_enc(port) in the if condition, because we log for gss
authentications irrespective of encoding is enabled or not. Put it
another way, maybe gss authentications are possible without
encoding[1]. We can have the information whether the encryption is
enabled or not in the log message, be_gssapi_get_enc(port) ? _("on") :
_("off"),.
#ifdef ENABLE_GSS
            if (be_gssapi_get_enc(port))
                ereport(LOG,

We do not need be_gssapi_get_auth(port) ? _("on") : _("off") this in
the log message, only in the if condition we need this check.

[1] By looking at the below code it seems that gss authentication
without encryption is possible.
    #ifdef ENABLE_GSS
        port->gss->auth = true;
        if (port->gss->enc)
            status = pg_GSS_checkauth(port);
        else
        {
            sendAuthRequest(port, AUTH_REQ_GSS, NULL, 0);
            status = pg_GSS_recvauth(port);
        }

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

Greetings,

* vignesh C (vignesh21@gmail.com) wrote:
> Log message for GSS connection is missing once connection
> authorization is successful. We have similar log messages for SSL
> connections once the connection authorization is successful. This
> message will help the user to identify the connection that was
> selected from the logfile. I'm not sure if this log message was
> intentionally left out due to some reason for GSS.
> If the above analysis looks correct, then please find a patch that
> adds log for gss connections.
>
> Thoughts?

I agree with logging the principal and if GSS encryption is being used
or not as part of the connection authorized message.  Not logging the
principal isn't great and has been something I've wanted to fix for a
while, so glad to see someone else is thinking about this.

> From 95c906b9eaf1493ad10ac65d6cf7b27a7dd6acb9 Mon Sep 17 00:00:00 2001
> From: Vignesh C <vignesh21@gmail.com>
> Date: Wed, 28 Oct 2020 08:19:06 +0530
> Subject: [PATCH v1] Log message for GSS connection is missing once connection
>  authorization is successful.
>
> Log message for GSS connection is missing once connection authorization is
> successful. We have similar log message for SSL connections once the connection
> authorization is successful. This message will help the user to identify the
> connection that was selected from the logfile.
> ---
>  src/backend/utils/init/postinit.c | 29 +++++++++++++++++++++++++++++
>  1 file changed, 29 insertions(+)
>
> diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
> index d4ab4c7..0fd38b7 100644
> --- a/src/backend/utils/init/postinit.c
> +++ b/src/backend/utils/init/postinit.c
> @@ -267,6 +267,21 @@ PerformAuthentication(Port *port)
>                                    be_tls_get_compression(port) ? _("on") : _("off"))));
>              else
>  #endif
> +#ifdef ENABLE_GSS
> +            if (be_gssapi_get_enc(port))

This is checking if GSS *encryption* is being used.

> +                ereport(LOG,
> +                        (port->application_name != NULL
> +                         ? errmsg("replication connection authorized: user=%s application_name=%s GSS enabled
(gssapiautorization=%s, principal=%s)", 
> +                                  port->user_name,
> +                                  port->application_name,
> +                                  be_gssapi_get_auth(port) ? _("on") : _("off"),
> +                                  be_gssapi_get_princ(port))
> +                         : errmsg("replication connection authorized: user=%s GSS enabled (gssapi autorization=%s,
principal=%s)",
> +                                  port->user_name,
> +                                  be_gssapi_get_auth(port) ? _("on") : _("off"),
> +                                  be_gssapi_get_princ(port))));

This is checking if GSS *authentication* was used.

You can certainly have GSS authentication used without encryption, and
you can (though I'm not sure how useful it really is) have GSS
encryption with 'trust' authentication, so we should really break this
out into their own sets of checks, which would look something like:

if (be_gssapi_get_auth(port) || be_gssapi_get_princ(port))
    connection authorized: GSS %s (principal=%s)

With the first %s being: (authentication || encrypted || authenticated and encrypted)

Or something along those lines, I would think.

I don't think 'enabled' is a good term to use here.

Thanks,

Stephen

Thanks Stephen for your comments.

On Wed, Oct 28, 2020 at 9:44 PM Stephen Frost <sfrost@snowman.net> wrote:
>
> Greetings,
>
> * vignesh C (vignesh21@gmail.com) wrote:
> > Log message for GSS connection is missing once connection
> > authorization is successful. We have similar log messages for SSL
> > connections once the connection authorization is successful. This
> > message will help the user to identify the connection that was
> > selected from the logfile. I'm not sure if this log message was
> > intentionally left out due to some reason for GSS.
> > If the above analysis looks correct, then please find a patch that
> > adds log for gss connections.
> >
> > Thoughts?
>
> I agree with logging the principal and if GSS encryption is being used
> or not as part of the connection authorized message.  Not logging the
> principal isn't great and has been something I've wanted to fix for a
> while, so glad to see someone else is thinking about this.
>
> > From 95c906b9eaf1493ad10ac65d6cf7b27a7dd6acb9 Mon Sep 17 00:00:00 2001
> > From: Vignesh C <vignesh21@gmail.com>
> > Date: Wed, 28 Oct 2020 08:19:06 +0530
> > Subject: [PATCH v1] Log message for GSS connection is missing once connection
> >  authorization is successful.
> >
> > Log message for GSS connection is missing once connection authorization is
> > successful. We have similar log message for SSL connections once the connection
> > authorization is successful. This message will help the user to identify the
> > connection that was selected from the logfile.
> > ---
> >  src/backend/utils/init/postinit.c | 29 +++++++++++++++++++++++++++++
> >  1 file changed, 29 insertions(+)
> >
> > diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
> > index d4ab4c7..0fd38b7 100644
> > --- a/src/backend/utils/init/postinit.c
> > +++ b/src/backend/utils/init/postinit.c
> > @@ -267,6 +267,21 @@ PerformAuthentication(Port *port)
> >                                                                 be_tls_get_compression(port) ? _("on") :
_("off"))));
> >                       else
> >  #endif
> > +#ifdef ENABLE_GSS
> > +                     if (be_gssapi_get_enc(port))
>
> This is checking if GSS *encryption* is being used.
>
> > +                             ereport(LOG,
> > +                                             (port->application_name != NULL
> > +                                              ? errmsg("replication connection authorized: user=%s
application_name=%sGSS enabled (gssapi autorization=%s, principal=%s)",
 
> > +                                                               port->user_name,
> > +                                                               port->application_name,
> > +                                                               be_gssapi_get_auth(port) ? _("on") : _("off"),
> > +                                                               be_gssapi_get_princ(port))
> > +                                              : errmsg("replication connection authorized: user=%s GSS enabled
(gssapiautorization=%s, principal=%s)",
 
> > +                                                               port->user_name,
> > +                                                               be_gssapi_get_auth(port) ? _("on") : _("off"),
> > +                                                               be_gssapi_get_princ(port))));
>
> This is checking if GSS *authentication* was used.
>
> You can certainly have GSS authentication used without encryption, and
> you can (though I'm not sure how useful it really is) have GSS
> encryption with 'trust' authentication, so we should really break this
> out into their own sets of checks, which would look something like:
>
> if (be_gssapi_get_auth(port) || be_gssapi_get_princ(port))
>     connection authorized: GSS %s (principal=%s)
>
> With the first %s being: (authentication || encrypted || authenticated and encrypted)
>
> Or something along those lines, I would think.
>
> I don't think 'enabled' is a good term to use here.
>

I have made a v2 patch based on the changes you have suggested. The
patch for the same is attached.

Regards,
Vignesh
EnterpriseDB: http://www.enterprisedb.com

Thanks Bharath for your comments.

On Wed, Oct 28, 2020 at 9:48 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
>
> On Wed, Oct 28, 2020 at 8:29 AM vignesh C <vignesh21@gmail.com> wrote:
> >
> > Log message for GSS connection is missing once connection
> > authorization is successful. We have similar log messages for SSL
> > connections once the connection authorization is successful. This
> > message will help the user to identify the connection that was
> > selected from the logfile. I'm not sure if this log message was
> > intentionally left out due to some reason for GSS.
> > If the above analysis looks correct, then please find a patch that
> > adds log for gss connections.
> >
> > Thoughts?
> >
>
> +1 for the idea. This is useful in knowing whether or not the user is
> authenticated using GSS APIs.
>
> Here are few comments on the patch:
>
> 1. How about using(like below) #ifdef, #elif ... #endif directives
> instead of #ifdef, #endif, #ifdef, #endif?
>
> #ifdef USE_SSL
>        blah,blah,blah...
> #elif defined(ENABLE_GSS)
>        blah,blah,blah...
> #else
>        blah,blah,blah...
> #endif
>

I preferred the way it is in the patch to maintain the similar style
that is used in other places like fe-connect.c.

> 2. I think we must use be_gssapi_get_auth(port) instead of
> be_gssapi_get_enc(port) in the if condition, because we log for gss
> authentications irrespective of encoding is enabled or not. Put it
> another way, maybe gss authentications are possible without
> encoding[1]. We can have the information whether the encryption is
> enabled or not in the log message, be_gssapi_get_enc(port) ? _("on") :
> _("off"),.
> #ifdef ENABLE_GSS
>             if (be_gssapi_get_enc(port))
>                 ereport(LOG,
>
> We do not need be_gssapi_get_auth(port) ? _("on") : _("off") this in
> the log message, only in the if condition we need this check.
>
> [1] By looking at the below code it seems that gss authentication
> without encryption is possible.
>     #ifdef ENABLE_GSS
>         port->gss->auth = true;
>         if (port->gss->enc)
>             status = pg_GSS_checkauth(port);
>         else
>         {
>             sendAuthRequest(port, AUTH_REQ_GSS, NULL, 0);
>             status = pg_GSS_recvauth(port);
>         }

Stephen also shared his thoughts for the above changes, I have
provided an updated patch for the same in the previous mail. Please
have a look and let me know if you have any comments.

Regards,
Vignesh
EnterpriseDB: http://www.enterprisedb.com

Greetings,

* vignesh C (vignesh21@gmail.com) wrote:
> I have made a v2 patch based on the changes you have suggested. The
> patch for the same is attached.

> From b067cf823750f200102be0a0cad9a26a08e29a92 Mon Sep 17 00:00:00 2001
> From: Vignesh C <vignesh21@gmail.com>
> Date: Wed, 28 Oct 2020 08:19:06 +0530
> Subject: [PATCH v2] Log message for GSS connection is missing once connection
>  authorization is successful.
>
> Log message for GSS connection is missing once connection authorization is
> successful. We have similar log message for SSL connections once the connection
> authorization is successful. This message will help the user to identify the
> connection that was selected from the logfile.

Just to be clear- it's not that the message is 'missing', it's just not
providing the (certainly useful) information about how the connection
was authorized.  The commit message should make it clear that what we're
doing here is improving the connection authorization message for GSS
authenticated or encrypted connections.

> diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
> index d4ab4c7..7980e92 100644
> --- a/src/backend/utils/init/postinit.c
> +++ b/src/backend/utils/init/postinit.c
> @@ -267,6 +267,21 @@ PerformAuthentication(Port *port)
>                                    be_tls_get_compression(port) ? _("on") : _("off"))));
>              else
>  #endif
> +#ifdef ENABLE_GSS
> +            if (be_gssapi_get_auth(port) || be_gssapi_get_princ(port))
> +                ereport(LOG,
> +                        (port->application_name != NULL
> +                         ? errmsg("replication connection authorized: user=%s application_name=%s GSS %s
(principal=%s)",
> +                                  port->user_name,
> +                                  port->application_name,
> +                                  be_gssapi_get_auth(port) || be_gssapi_get_enc(port) ? _("on") : _("off"),
> +                                  be_gssapi_get_princ(port))
> +                         : errmsg("replication connection authorized: user=%s GSS %s (principal=%s)",
> +                                  port->user_name,
> +                                  be_gssapi_get_auth(port) || be_gssapi_get_enc(port) ? _("on") : _("off"),
> +                                  be_gssapi_get_princ(port))));
> +            else
> +#endif

No, this isn't what I was suggesting.  "on" and "off" really isn't
communicating the details about the GSS-using connection.  What I
suggested before was something like:

errmsg("replication connection authorized: user=%s application_name=%s GSS %s (principal=%s)",
    port->user_name,
    port->application_name,
    (be_gssapi_get_auth(port) && be_gssapi_get_enc(port)) ?  "authenticated and encrypted" : be_gssapi_get_auth(port) ?
"authenticated" : "encrypted", 
    be_gssapi_get_princ(port))

Though I'll admit that perhaps there's something better which could be
done here- but just 'on/off' certainly isn't that.  Another option might
be:

errmsg("replication connection authorized: user=%s application_name=%s GSS authenticated: %s, encrypted: %s, principal:
%s",
    port->user_name,
    port->application_name,
    be_gssapi_get_auth(port) ? "yes" : "no",
    be_gssapi_get_enc(port) ? "yes" : "no",
    be_gssapi_get_princ(port))

Also, it would be good to see if there's a way to add to the tests we
have for GSSAPI authentication/encryption to show that we hit each of
the possible cases and check that we get the correct messages in the log
as a result.

Thanks,

Stephen

On Thu, Oct 29, 2020 at 7:26 PM Stephen Frost <sfrost@snowman.net> wrote:
>
> Greetings,
>
> * vignesh C (vignesh21@gmail.com) wrote:
> > I have made a v2 patch based on the changes you have suggested. The
> > patch for the same is attached.
>
> > From b067cf823750f200102be0a0cad9a26a08e29a92 Mon Sep 17 00:00:00 2001
> > From: Vignesh C <vignesh21@gmail.com>
> > Date: Wed, 28 Oct 2020 08:19:06 +0530
> > Subject: [PATCH v2] Log message for GSS connection is missing once connection
> >  authorization is successful.
> >
> > Log message for GSS connection is missing once connection authorization is
> > successful. We have similar log message for SSL connections once the connection
> > authorization is successful. This message will help the user to identify the
> > connection that was selected from the logfile.
>
> Just to be clear- it's not that the message is 'missing', it's just not
> providing the (certainly useful) information about how the connection
> was authorized.  The commit message should make it clear that what we're
> doing here is improving the connection authorization message for GSS
> authenticated or encrypted connections.
>

I have updated the commit message accordingly.

> > diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
> > index d4ab4c7..7980e92 100644
> > --- a/src/backend/utils/init/postinit.c
> > +++ b/src/backend/utils/init/postinit.c
> > @@ -267,6 +267,21 @@ PerformAuthentication(Port *port)
> >                                                                 be_tls_get_compression(port) ? _("on") :
_("off"))));
> >                       else
> >  #endif
> > +#ifdef ENABLE_GSS
> > +                     if (be_gssapi_get_auth(port) || be_gssapi_get_princ(port))
> > +                             ereport(LOG,
> > +                                             (port->application_name != NULL
> > +                                              ? errmsg("replication connection authorized: user=%s
application_name=%sGSS %s (principal=%s)",
 
> > +                                                               port->user_name,
> > +                                                               port->application_name,
> > +                                                               be_gssapi_get_auth(port) || be_gssapi_get_enc(port)
?_("on") : _("off"),
 
> > +                                                               be_gssapi_get_princ(port))
> > +                                              : errmsg("replication connection authorized: user=%s GSS %s
(principal=%s)",
> > +                                                               port->user_name,
> > +                                                               be_gssapi_get_auth(port) || be_gssapi_get_enc(port)
?_("on") : _("off"),
 
> > +                                                               be_gssapi_get_princ(port))));
> > +                     else
> > +#endif
>
> No, this isn't what I was suggesting.  "on" and "off" really isn't
> communicating the details about the GSS-using connection.  What I
> suggested before was something like:
>
> errmsg("replication connection authorized: user=%s application_name=%s GSS %s (principal=%s)",
>         port->user_name,
>         port->application_name,
>         (be_gssapi_get_auth(port) && be_gssapi_get_enc(port)) ?  "authenticated and encrypted" :
be_gssapi_get_auth(port)?  "authenticated" : "encrypted",
 
>         be_gssapi_get_princ(port))
>
> Though I'll admit that perhaps there's something better which could be
> done here- but just 'on/off' certainly isn't that.  Another option might
> be:
>
> errmsg("replication connection authorized: user=%s application_name=%s GSS authenticated: %s, encrypted: %s,
principal:%s",
 
>         port->user_name,
>         port->application_name,
>         be_gssapi_get_auth(port) ? "yes" : "no",
>         be_gssapi_get_enc(port) ? "yes" : "no",
>         be_gssapi_get_princ(port))
>

I like the above method that you suggested, I have changed it based on
the above.

> Also, it would be good to see if there's a way to add to the tests we
> have for GSSAPI authentication/encryption to show that we hit each of
> the possible cases and check that we get the correct messages in the log
> as a result.
>

I have added the log validation to the existing tests that are present
for authentication.

Attached v3 patch has the change for the same.

Regards,
Vignesh
EnterpriseDB: http://www.enterprisedb.com

Thanks for the comments Bharath.

On Thu, Oct 29, 2020 at 12:15 PM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
> 1. Instead of just "on/off" after GSS %s in the log message, wouldn't it be informative if we have authenticated
and/orencrypted as suggested by Stephen? 
>
> So the log message would look like this:
>
> if(be_gssapi_get_auth(port))
> replication connection authorized: user=bob application_name=foo GSS authenticated (principal=bar)
>
> if(be_gssapi_get_enc(port))
> replication connection authorized: user=bob application_name=foo GSS encrypted (principal=bar)
>
> if(be_gssapi_get_auth(port) && be_gssapi_get_enc(port))
> replication connection authorized: user=bob application_name=foo GSS authenticated and encrypted (principal=bar)
>
> +#ifdef ENABLE_GSS
> +            if (be_gssapi_get_auth(port) || be_gssapi_get_princ(port))
> +                ereport(LOG,
> +                        (port->application_name != NULL
> +                         ? errmsg("replication connection authorized: user=%s application_name=%s GSS %s
(principal=%s)",
> +                                  port->user_name,
> +                                  port->application_name,
> +                                  be_gssapi_get_auth(port) || be_gssapi_get_enc(port) ? _("on") : _("off"),
> +                                  be_gssapi_get_princ(port))
> +                         : errmsg("replication connection authorized: user=%s GSS %s (principal=%s)",
> +                                  port->user_name,
> +                                  be_gssapi_get_auth(port) || be_gssapi_get_enc(port) ? _("on") : _("off"),
> +                                  be_gssapi_get_princ(port))));
> +            else
>

This is handled in v3 patch posted at [1].

> 2. I think the log message preparation looks a bit clumsy with ternary operators and duplicate log message texts(I
knowthat we already do this for SSL). Can we have the log message prepared using StringInfoData data structure/APIs and
usejust a single ereport? This way, that part of the code looks cleaner. 
>
> Here's what I'm visualizing:
>
> if (Log_connections)
> {
> StringInfoData msg;
>
> if (am_walsender)
> append("replication connection authorized: user=%s");
> else
> append("connection authorized: user=%s database=%s");
>
> if (port->application_name)
> append("application_name=%s");
>
> #ifdef USE_SSL
> if (port->ssl_in_use)
> append("SSL enabled (protocol=%s, cipher=%s, bits=%d, compression=%s");
> #elif defined(ENABLE_GSS)
>         blah,blah,blah
> #endif
>
> ereport (LOG, msg.data);
> }

This is handled in the v3 patch posted.

>
> 3. +            if (be_gssapi_get_auth(port) || be_gssapi_get_princ(port))
>
> If be_gssapi_get_auth(port) returns false, I think there's no way that be_gssapi_get_princ(port) would return a non
nullvalue, see the comment. The function be_gssapi_get_princ() returns NULL if the auth is false, so the check if (
be_gssapi_get_princ(port))would suffice. 
>
> gss_name_t    name;            /* GSSAPI client name */
>     char       *princ;            /* GSSAPI Principal used for auth, NULL if
>                                  * GSSAPI auth was not used */
>     bool        auth;            /* GSSAPI Authentication used */
>     bool        enc;            /* GSSAPI encryption in use */
>

This is handled in the v3 patch posted.


Regards,
Vignesh
EnterpriseDB: http://www.enterprisedb.com

On Fri, Oct 30, 2020 at 6:35 PM Euler Taveira
<euler.taveira@2ndquadrant.com> wrote:
>
> + appendStringInfo(&logmsg, "replication ");
> +
> + appendStringInfo(&logmsg, "connection authorized: user=%s",
> + port->user_name);
> + if (!am_walsender)
> + appendStringInfo(&logmsg, " database=%s", port->database_name);
> +
> + if (port->application_name != NULL)
> + appendStringInfo(&logmsg, " application_name=%s",
> + port->application_name);
> +
>
> Your approach breaks localization. You should use multiple errmsg.
>

IIUC, isn't it enough calling a single errmsg() inside ereport() with
the prepared logmsg.data (which is a string)? The errmsg() function
will do the required translation of the logmsg.data. Why do we need
multiple errmsg() calls? Could you please elaborate a bit on how the
way currently it is done in the patch breaks localization?

+        ereport(LOG, errmsg("%s", logmsg.data));

>
> +$node->append_conf('postgresql.conf', "logging_collector= 'on'");
> +$node->append_conf('postgresql.conf', "log_connections= 'on'");
>
> booleans don't need quotes.
>

I think that's not correct. If I'm right, the snippet pointed above is
from a perl script. In C, the strings are null terminated and they are
represented within double quotes. So we need to use double quotes for
_("on") : _("off"). And also the definition of _( ) macro points to a
function err_gettext() that expects C-style string i.e null
terminated.

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

On Sat, Oct 31, 2020 at 9:04 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
>
> > +$node->append_conf('postgresql.conf', "logging_collector= 'on'");
> > +$node->append_conf('postgresql.conf', "log_connections= 'on'");
> >
> > booleans don't need quotes.
> >
>
> I think that's not correct. If I'm right, the snippet pointed above is
> from a perl script. In C, the strings are null terminated and they are
> represented within double quotes. So we need to use double quotes for
> _("on") : _("off"). And also the definition of _( ) macro points to a
> function err_gettext() that expects C-style string i.e null
> terminated.
>

I'm sorry for the above point, I misunderstood it. I took a further
look at the patch. It seems like it's a mix. In some place we are not
using quotes for booleans, for instance,

$node->append_conf('postgresql.conf', 'autovacuum=off');
$node->append_conf('postgresql.conf', 'track_commit_timestamp = on');

but in one place we are using quotes

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

Either way seems to be fine as we don't have any variables inside the
strings to be replaced by the perl interpreter.

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

On Fri, Oct 30, 2020 at 6:13 PM vignesh C <vignesh21@gmail.com> wrote:
>
> I have added the log validation to the existing tests that are present
> for authentication.
>

I took a look at v3 patch. Here are some comments.

1. Why are the input strings(not the newly added GSS log message
string) to test_access() function are in some places double-quoted and
in some places single quoted?

    'succeeds with mapping with default gssencmode and host hba',
    'connection authorized: user=test1 database=postgres
application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes,
principal=test1\@EXAMPLE.COM\)'
);
    "succeeds with GSS-encrypted access required with host hba",
    'connection authorized: user=test1 database=postgres
application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes,
principal=test1\@EXAMPLE.COM\)'
);

And also for

test_access(
    $node,
    'test1',    <<< single quotes

test_access(
    $node,
    "test1",   <<< double quotes

Looks like we use double quoted strings in perl if we have any
variables inside the string to be replaced by the interpreter or else
single quoted strings are fine[1]. If this is true, can we make it
uniform across this file at least?

2. Instead of using hardcoded values for application_name and
principal, can we use variables? For application_name we can directly
use a single variable and use it. I think principal name is a formed
value, can we use that formed variable?

 application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes,
principal=test1\@EXAMPLE.COM\)'

3. Why are we using escape character before ( and @, IIUC, to not let
interpreter replace it with any value. If this is correct, it doesn't
make sense here as we are using single quoted strings. The perl
interpreter replaces the variables only when strings are used in
double quotes[1].

+    'connection authorized: user=test1 database=postgres
application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes,
principal=test1\@EXAMPLE.COM\)'
+);

I ran the keroberos tests on my dev machine. make check of 001_auth.pl
is passing.

[1] - https://www.geeksforgeeks.org/perl-quoted-interpolated-and-escaped-strings/

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

Thanks for the comments Bharath.
On Sat, Oct 31, 2020 at 10:18 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
>
> I took a look at v3 patch. Here are some comments.
>
> 1. Why are the input strings(not the newly added GSS log message
> string) to test_access() function are in some places double-quoted and
> in some places single quoted?
>
>     'succeeds with mapping with default gssencmode and host hba',
>     'connection authorized: user=test1 database=postgres
> application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes,
> principal=test1\@EXAMPLE.COM\)'
> );
>     "succeeds with GSS-encrypted access required with host hba",
>     'connection authorized: user=test1 database=postgres
> application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes,
> principal=test1\@EXAMPLE.COM\)'
> );
>
> And also for
>
> test_access(
>     $node,
>     'test1',    <<< single quotes
>
> test_access(
>     $node,
>     "test1",   <<< double quotes
>
> Looks like we use double quoted strings in perl if we have any
> variables inside the string to be replaced by the interpreter or else
> single quoted strings are fine[1]. If this is true, can we make it
> uniform across this file at least?

I have made this uniform across this file.

>
> 2. Instead of using hardcoded values for application_name and
> principal, can we use variables? For application_name we can directly
> use a single variable and use it. I think principal name is a formed
> value, can we use that formed variable?
>
>  application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes,
> principal=test1\@EXAMPLE.COM\)'
>

Used variables for this.

> 3. Why are we using escape character before ( and @, IIUC, to not let
> interpreter replace it with any value. If this is correct, it doesn't
> make sense here as we are using single quoted strings. The perl
> interpreter replaces the variables only when strings are used in
> double quotes[1].
>
> +    'connection authorized: user=test1 database=postgres
> application_name=001_auth.pl GSS \(authenticated=yes, encrypted=yes,
> principal=test1\@EXAMPLE.COM\)'
> +);
>
> I ran the keroberos tests on my dev machine. make check of 001_auth.pl
> is passing.
>

I have changed this within double quotes now as it includes passing of
the variable also. Removed the escape sequence which is not required.

The v4 patch attached has the fixes for this.

Regards,
Vignesh
EnterpriseDB: http://www.enterprisedb.com

On Sun, Nov 1, 2020 at 3:34 AM Euler Taveira
<euler.taveira@2ndquadrant.com> wrote:
>
> No. The strings are specified in the appendStringInfo, hence you should add _()
> around the string to be translated. There is nothing to be translated if you
> specify only the format identifier. You can always test if gettext extracts the
> string to be translated by executing 'make update-po' (after specifying
> --enable-nls in the configure).  Search for your string in one of the generated
> files (po/LL.po.new).
>

Thanks a lot for the detailed explanation.

>
> You shouldn't split messages like that because not all languages have the same
> order as English. Having said that you risk providing a nonsense translation
> because someone decided to translate pieces of a sentence separately.
>
> +           appendStringInfo(&logmsg, "replication ");
> +
> +       appendStringInfo(&logmsg, "connection authorized: user=%s",
> +                        port->user_name);
>
> This hunk will break translation. In Portuguese, the adjective "replication" is
> translated after the noun "connection". If you decided to keep this code as is,
> the printed message won't follow the grammar rules. You will have "replicação
> conexão autorizada" instead of "conexão de replicação autorizada". The former
> isn't grammatically correct. Avoid splitting sentences that are translated.
>

Agreed. Looks like we don't break localization rules if we have
something like below, which is done in similar way for a log message
in heap_vacuum_rel(): msgfmt = _("automatic aggressive vacuum to
prevent wraparound of table \"%s.%s.%s\": index scans: %d\n");

   if (am_walsender)
           appendStringInfo(&logmsg, _("replication connection
authorized: user=%s"),
                         port->user_name);
        else
          appendStringInfo(&logmsg, _("connection authorized: user=%s"),
                         port->user_name);

    if (!am_walsender)
        appendStringInfo(&logmsg, _(" database=%s"), port->database_name);

    if (port->application_name != NULL)
        appendStringInfo(&logmsg, _(" application_name=%s"),
                         port->application_name);

#ifdef USE_SSL
    if (port->ssl_in_use)
        appendStringInfo(&logmsg, _(" SSL enabled (protocol=%s,
cipher=%s, bits=%d, compression=%s)"),
                         be_tls_get_version(port),
                         be_tls_get_cipher(port),
                         be_tls_get_cipher_bits(port),
                         be_tls_get_compression(port) ? _("on") : _("off"));
#endif
#ifdef ENABLE_GSS
    if (be_gssapi_get_princ(port))
        appendStringInfo(&logmsg, _(" GSS (authenticated=%s,
encrypted=%s, principal=%s)"),
                         be_gssapi_get_auth(port) ? _("yes") : _("no"),
                         be_gssapi_get_enc(port) ? _("yes") : _("no"),
                         be_gssapi_get_princ(port));
#endif

    ereport(LOG, errmsg_internal("%s", logmsg.data));

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

On Sun, Nov 1, 2020 at 3:34 AM Euler Taveira
<euler.taveira@2ndquadrant.com> wrote:
>
> On Sat, 31 Oct 2020 at 00:34, Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote:
>>
>> On Fri, Oct 30, 2020 at 6:35 PM Euler Taveira
>> <euler.taveira@2ndquadrant.com> wrote:
>> >
>> > + appendStringInfo(&logmsg, "replication ");
>> > +
>> > + appendStringInfo(&logmsg, "connection authorized: user=%s",
>> > + port->user_name);
>> > + if (!am_walsender)
>> > + appendStringInfo(&logmsg, " database=%s", port->database_name);
>> > +
>> > + if (port->application_name != NULL)
>> > + appendStringInfo(&logmsg, " application_name=%s",
>> > + port->application_name);
>> > +
>> >
>> > Your approach breaks localization. You should use multiple errmsg.
>> >
>>
>> IIUC, isn't it enough calling a single errmsg() inside ereport() with
>> the prepared logmsg.data (which is a string)? The errmsg() function
>> will do the required translation of the logmsg.data. Why do we need
>> multiple errmsg() calls? Could you please elaborate a bit on how the
>> way currently it is done in the patch breaks localization?
>>
>
> No. The strings are specified in the appendStringInfo, hence you should add _()
> around the string to be translated. There is nothing to be translated if you
> specify only the format identifier. You can always test if gettext extracts the
> string to be translated by executing 'make update-po' (after specifying
> --enable-nls in the configure).  Search for your string in one of the generated
> files (po/LL.po.new).
>
> You shouldn't split messages like that because not all languages have the same
> order as English. Having said that you risk providing a nonsense translation
> because someone decided to translate pieces of a sentence separately.
>
> +           appendStringInfo(&logmsg, "replication ");
> +
> +       appendStringInfo(&logmsg, "connection authorized: user=%s",
> +                        port->user_name);
>
> This hunk will break translation. In Portuguese, the adjective "replication" is
> translated after the noun "connection". If you decided to keep this code as is,
> the printed message won't follow the grammar rules. You will have "replicação
> conexão autorizada" instead of "conexão de replicação autorizada". The former
> isn't grammatically correct. Avoid splitting sentences that are translated.
>

Thanks for the explanation, I have attached a v5 patch with the
changes where the translation should not have any problem.

Regards,
Vignesh
EnterpriseDB: http://www.enterprisedb.com

On Tue, Nov 3, 2020 at 12:49 PM vignesh C <vignesh21@gmail.com> wrote:
>
> Thanks for the explanation, I have attached a v5 patch with the
> changes where the translation should not have any problem.
>

I took a look at the V5 patch. Below are some comments:

1. Do we need to generate and add the translation of the new GSS
message in all the language specific files under po/ directory?. See
below for the translated SSL log message added in all the language
specific .po files. [1] may help.
I'm not quite sure whether translation should be part of the patch or
is it done separately? Say someone doing tralsations for a bunch of
log messages together in a single commit?

#: utils/init/postinit.c:237
#, c-format
msgid "replication connection authorized: user=%s SSL enabled
(protocol=%s, cipher=%s, compression=%s)"
msgstr "conexão de replicação autorizada: usuário=%s SSL habilitado
(protocolo=%s, cifra=%s, compressão=%s)"

2. I have one concern about the test case, where we look for an
expected message[2](in English language), but what happens if the
logging collector collects the log messages in a different language,
say[3]? Will the test case fail? I saw that in 004_logrotate.pl we
look for "division by zero" in the logs, will the same concern apply
to this as well?

[1] - https://www.postgresql.org/docs/current/nls-translator.html
[2] - "connection authorized: user=$username database=$dbname
application_name=$application
[3] - "conexão autorizada: usuário=%s banco de dados=%s SSL habilitado
(protocolo=%s, cifra=%s, compressão=%s)"

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

On Thu, Nov 5, 2020 at 9:50 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
>
> On Thu, Nov 5, 2020 at 7:55 AM Euler Taveira <euler.taveira@2ndquadrant.com> wrote:
> >
> > No. Don't worry with translations during the development. Make sure to follow
> > the instructions provided here [1]. Translations are coordinated in a different
> > mailing list: pgsql-translators [2]. There is a different repository [3] for
> > handling PO files and the updated files are merged by Peter Eisentraut just
> > before each minor/major release. We usually start to update translations after
> > feature freeze.
> >
>
> Thanks.
>
> On Tue, Nov 3, 2020 at 12:49 PM vignesh C <vignesh21@gmail.com> wrote:
> >
> > Thanks for the explanation, I have attached a v5 patch with the
> > changes where the translation should not have any problem.
> >
>
> I have taken a further look at the V5 patch:
>
> 1. We wait 10sec until the syslogger process logs the expected message, what happens if someone intentionally made
thesyslogger process to wait for a longer duration?  Will the new tests fail? 
>     # might need to retry if logging collector process is slow...
>         my $max_attempts = 10 * 10;
>         my $first_logfile;
>         for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
>         {
>             $first_logfile = slurp_file($node->data_dir . '/' . $lfname);
>             last if $first_logfile =~ m/$expect_log_msg /;
>             usleep(100_000);
>         }
>

Yes the test will fail if it takes more than the max_attempts as there
is a like statement immediately after the loop:
                like($first_logfile, qr/\Q$expect_log_msg\E/,
                         'found expected log file content');
I have also increased the attempts to 180 seconds just like other
tests to avoid failure in very slow systems.

> 2. I intentionally altered(for testing purpose only) the expected log message input given to test_access(), expecting
thetests to fail, but the test succeeded. Am I missing something here? Is it that the syslogger process not logging the
messageat all or within the 10sec waiting? Do we need to increase the wait duration? Do we need to do something to fail
thetest when we don't see the expected log message in test_access()? 
>
> "cXNnnection authorized: user=......
> "connecTEion authorized: user=....
> "connection auTThorized:.....
>

Thanks for testing this, I had missed testing this. The expression
matching was not correct. Attached v6 patch which includes the fix for
this.

Regards,
Vignesh
EnterpriseDB: http://www.enterprisedb.com

On Sat, Nov 7, 2020 at 9:27 AM vignesh C <vignesh21@gmail.com> wrote:
>
> Yes the test will fail if it takes more than the max_attempts as there
> is a like statement immediately after the loop:
>                 like($first_logfile, qr/\Q$expect_log_msg\E/,
>                          'found expected log file content');
> I have also increased the attempts to 180 seconds just like other
> tests to avoid failure in very slow systems.
>

+1 for this.

>
> > 2. I intentionally altered(for testing purpose only) the expected log message input given to test_access(),
expectingthe tests to fail, but the test succeeded. Am I missing something here? Is it that the syslogger process not
loggingthe message at all or within the 10sec waiting? Do we need to increase the wait duration? Do we need to do
somethingto fail the test when we don't see the expected log message in test_access()? 
> >
> > "cXNnnection authorized: user=......
> > "connecTEion authorized: user=....
> > "connection auTThorized:.....
> >
>
> Thanks for testing this, I had missed testing this. The expression
> matching was not correct. Attached v6 patch which includes the fix for
> this.
>

This use case works as expected i.e. test fails if the log message is
altered intentionally.

>
> Attached v6 patch which includes the fix for this.
>

Thanks. I have no further comments on the V6 patch, it looks good to
me. make check of 001_auth.pl, regression tests make check and make
check world passes. It can be passed to committer for further review.

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

Greetings,

* vignesh C (vignesh21@gmail.com) wrote:
> Thanks for testing this, I had missed testing this. The expression
> matching was not correct. Attached v6 patch which includes the fix for
> this.

This generally looks pretty good to me.  I did reword the commit message
a bit, run pgindent, and added the appropriate log message for the last
test (was there a reason you didn't include that..?).  In general, this
looks pretty good to commit to me.

I'll look at it again over the weekend or early next week and unless
there's objections, I'll push it.

Thanks,

Stephen

Greetings,

* Stephen Frost (sfrost@snowman.net) wrote:
> * vignesh C (vignesh21@gmail.com) wrote:
> > Thanks for testing this, I had missed testing this. The expression
> > matching was not correct. Attached v6 patch which includes the fix for
> > this.
>
> This generally looks pretty good to me.  I did reword the commit message
> a bit, run pgindent, and added the appropriate log message for the last
> test (was there a reason you didn't include that..?).  In general, this
> looks pretty good to commit to me.
>
> I'll look at it again over the weekend or early next week and unless
> there's objections, I'll push it.

And committed.

Thanks!

Stephen

On Wed, Dec 02, 2020 at 02:44:31PM -0500, Stephen Frost wrote:
> And committed.

This has been committed as of dc11f31a, that changed the configuration
of the node in the kerberos test to use logging_collector.  Wouldn't
it be simpler to not use the logging collector here and use a logic
similar to what we do in PostgresNode::issues_sql_like() where we
truncate the log file before checking for a pattern?

It seems to me that this would make the tests faster, that the test
would not need to wait for the logging collector and that the code
could just use slurp_file($node->logfile) to get the data it wants to
check for a given pattern without looking at current_logfiles.  I also
think that not using truncate() on the logfile generated has the
disadvantage to make the code fuzzy for its verification once we
introduce patterns close to each other, as there could easily be an
overlap.  That's one problem that SQL pattern checks had to deal with
in the past.  Thoughts?
--
Michael

On Sat, Mar 20, 2021 at 05:37:47PM +0900, Michael Paquier wrote:
> It seems to me that this would make the tests faster, that the test
> would not need to wait for the logging collector and that the code
> could just use slurp_file($node->logfile) to get the data it wants to
> check for a given pattern without looking at current_logfiles.  I also
> think that not using truncate() on the logfile generated has the
> disadvantage to make the code fuzzy for its verification once we
> introduce patterns close to each other, as there could easily be an
> overlap.  That's one problem that SQL pattern checks had to deal with
> in the past.  Thoughts?

And, in terms of code, this really simplifies things.  Please see the
attached that I would like to apply.
--
Michael

On Sat, Mar 20, 2021 at 4:59 PM Michael Paquier <michael@paquier.xyz> wrote:
>
> On Sat, Mar 20, 2021 at 05:37:47PM +0900, Michael Paquier wrote:
> > It seems to me that this would make the tests faster, that the test
> > would not need to wait for the logging collector and that the code
> > could just use slurp_file($node->logfile) to get the data it wants to
> > check for a given pattern without looking at current_logfiles.  I also
> > think that not using truncate() on the logfile generated has the
> > disadvantage to make the code fuzzy for its verification once we
> > introduce patterns close to each other, as there could easily be an
> > overlap.  That's one problem that SQL pattern checks had to deal with
> > in the past.  Thoughts?
>
> And, in terms of code, this really simplifies things.  Please see the
> attached that I would like to apply.

+1 from me.  So, after every call to test_access, the node's current
logfile gets truncated and we don't need the logging collector process
to step in for rotation of the logfile.

The patch looks good to me and the kerberos regression tests pass with it.

With Regards,
Bharath Rupireddy.
EnterpriseDB: http://www.enterprisedb.com

Greetings,

* Michael Paquier (michael@paquier.xyz) wrote:
> On Sat, Mar 20, 2021 at 05:37:47PM +0900, Michael Paquier wrote:
> > It seems to me that this would make the tests faster, that the test
> > would not need to wait for the logging collector and that the code
> > could just use slurp_file($node->logfile) to get the data it wants to
> > check for a given pattern without looking at current_logfiles.  I also
> > think that not using truncate() on the logfile generated has the
> > disadvantage to make the code fuzzy for its verification once we
> > introduce patterns close to each other, as there could easily be an
> > overlap.  That's one problem that SQL pattern checks had to deal with
> > in the past.  Thoughts?
>
> And, in terms of code, this really simplifies things.  Please see the
> attached that I would like to apply.

Agreed, that does look better/simpler.

Thanks!

Stephen

On Sun, Mar 21, 2021 at 05:53:04PM +0530, Bharath Rupireddy wrote:
> +1 from me.  So, after every call to test_access, the node's current
> logfile gets truncated and we don't need the logging collector process
> to step in for rotation of the logfile.
>
> The patch looks good to me and the kerberos regression tests pass with it.

Thanks Stephen and Bharath for looking at it!  I have applied that
now.
--
Michael