Re: Issues with PAM : log that it failed, whether it actually failed or not - Mailing list pgsql-hackers

[ redirecting to pgsql-hackers ]

I wrote:
> La Cancellera Yoann <lacancellera.yoann@gmail.com> writes:
>> I am having issues with PAM auth :
>> it works, password are correctly checked, unknown users cannot access,
>> known user can, everything looks good
>> But, it always log an error by default even if auth is succesful:
>> And if auth is unsuccessful, it will log that very same message twice

> Those aren't errors, they're just log events.

> If you're using psql to connect, the extra messages aren't surprising,
> because psql will first try to connect without a password, and only
> if it gets a failure that indicates that a password is needed will
> it prompt the user for a password (so two connection attempts occur,
> even if the second one is successful).  You can override that default
> behavior with the -W switch, and I bet that will make the extra
> log messages go away.

> Having said that, using LOG level for unsurprising auth failures
> seems excessively chatty.  More-commonly-used auth methods aren't
> that noisy.

I took a closer look at this and realized that the problem is that
the PAM code doesn't support our existing convention of not logging
anything about connections wherein the client side disconnects when
challenged for a password.  0001 attached fixes that, not in a
terribly nice way perhaps, but the PAM code is already relying on
static variables for communication :-(.

Also, 0002 adjusts some messages in the same file to match project
capitalization conventions.

Barring objections, I propose to back-patch 0001 but apply 0002
to HEAD only.

            regards, tom lane

diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index d28271c..909d736 100644
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -110,6 +110,7 @@ static const char *pam_passwd = NULL;    /* Workaround for Solaris 2.6
                                          * brokenness */
 static Port *pam_port_cludge;    /* Workaround for passing "Port *port" into
                                  * pam_passwd_conv_proc */
+static bool pam_no_password;    /* For detecting no-password-given */
 #endif                            /* USE_PAM */


@@ -2099,8 +2099,10 @@ pam_passwd_conv_proc(int num_msg, const struct pam_message **msg,
                     {
                         /*
                          * Client didn't want to send password.  We
-                         * intentionally do not log anything about this.
+                         * intentionally do not log anything about this,
+                         * either here or at higher levels.
                          */
+                        pam_no_password = true;
                         goto fail;
                     }
                 }
@@ -2159,6 +2161,7 @@ CheckPAMAuth(Port *port, const char *user, const char *password)
      */
     pam_passwd = password;
     pam_port_cludge = port;
+    pam_no_password = false;

     /*
      * Set the application data portion of the conversation struct.  This is
@@ -2244,22 +2247,26 @@ CheckPAMAuth(Port *port, const char *user, const char *password)

     if (retval != PAM_SUCCESS)
     {
-        ereport(LOG,
-                (errmsg("pam_authenticate failed: %s",
-                        pam_strerror(pamh, retval))));
+        /* If pam_passwd_conv_proc saw EOF, don't log anything */
+        if (!pam_no_password)
+            ereport(LOG,
+                    (errmsg("pam_authenticate failed: %s",
+                            pam_strerror(pamh, retval))));
         pam_passwd = NULL;        /* Unset pam_passwd */
-        return STATUS_ERROR;
+        return pam_no_password ? STATUS_EOF : STATUS_ERROR;
     }

     retval = pam_acct_mgmt(pamh, 0);

     if (retval != PAM_SUCCESS)
     {
-        ereport(LOG,
-                (errmsg("pam_acct_mgmt failed: %s",
-                        pam_strerror(pamh, retval))));
+        /* If pam_passwd_conv_proc saw EOF, don't log anything */
+        if (!pam_no_password)
+            ereport(LOG,
+                    (errmsg("pam_acct_mgmt failed: %s",
+                            pam_strerror(pamh, retval))));
         pam_passwd = NULL;        /* Unset pam_passwd */
-        return STATUS_ERROR;
+        return pam_no_password ? STATUS_EOF : STATUS_ERROR;
     }

     retval = pam_end(pamh, retval);
diff --git a/src/backend/libpq/auth.c b/src/backend/libpq/auth.c
index d28271c..909d736 100644
--- a/src/backend/libpq/auth.c
+++ b/src/backend/libpq/auth.c
@@ -959,7 +960,7 @@ CheckSCRAMAuth(Port *port, char *shadow_pass, char **logdetail)
             return STATUS_ERROR;
         }

-        elog(DEBUG4, "Processing received SASL response of length %d", buf.len);
+        elog(DEBUG4, "processing received SASL response of length %d", buf.len);

         /*
          * The first SASLInitialResponse message is different from the others.
@@ -1150,7 +1151,7 @@ pg_GSS_recvauth(Port *port)
         gbuf.length = buf.len;
         gbuf.value = buf.data;

-        elog(DEBUG4, "Processing received GSS token of length %u",
+        elog(DEBUG4, "processing received GSS token of length %u",
              (unsigned int) gbuf.length);

         maj_stat = gss_accept_sec_context(
@@ -1427,8 +1428,7 @@ pg_SSPI_recvauth(Port *port)
         outbuf.pBuffers = OutBuffers;
         outbuf.ulVersion = SECBUFFER_VERSION;

-
-        elog(DEBUG4, "Processing received SSPI token of length %u",
+        elog(DEBUG4, "processing received SSPI token of length %u",
              (unsigned int) buf.len);

         r = AcceptSecurityContext(&sspicred,
@@ -2949,7 +2956,7 @@ radius_add_attribute(radius_packet *packet, uint8 type, const unsigned char *dat
          * fail.
          */
         elog(WARNING,
-             "Adding attribute code %d with length %d to radius packet would create oversize packet, ignoring",
+             "adding attribute code %d with length %d to radius packet would create oversize packet, ignoring",
              type, len);
         return;
     }