Adds more informative syslog support to pam_ldap for troubleshooting - see http://bugzilla.padl.com/attachment.cgi?id=225 and http://improbable.org/chris/index.php?id=201 for details

pam_ldap_bug365.patch

--- ../libpam-ldap-minimal/pam_ldap.c	2008-04-15 14:44:58.000000000 -0400
+++ pam_ldap.c	2008-04-02 18:40:02.000000000 -0400
@@ -1228,10 +1228,14 @@
       int rc = ldapssl_client_init (session->conf->sslpath, NULL);
       if (rc != LDAP_SUCCESS)
 	{
-	  syslog (LOG_ERR, "pam_ldap: ldapssl_client_init %s",
+	  syslog (LOG_ERR, "pam_ldap: _open_session() failed with PAM_SERVICE_ERR: ldapssl_client_init failed: %s",
 		  ldap_err2string (rc));
 	  return PAM_SERVICE_ERR;
 	}
+      else
+        {
+	  syslog (LOG_INFO, "pam_ldap: _open_session(): ldapssl_client_init successful");
+	}
       ssl_initialized = 1;
     }
 
@@ -1239,6 +1243,7 @@
     {
       session->ld = ldapssl_init (session->conf->host,
 				  session->conf->port, TRUE);
+      if (session->ld == NULL) syslog (LOG_ERR, "pam_ldap: _open_session(): ldapssl_init() failed");
     }
   else
 #endif /* HAVE_LDAPSSL_INIT */
@@ -1247,7 +1252,11 @@
       /* set defaults for global TLS-related options */
       if (_set_ssl_default_options (session) != LDAP_SUCCESS)
 	{
-	  syslog (LOG_ERR, "pam_ldap: _set_ssl_default_options failed");
+	  syslog (LOG_ERR, "pam_ldap: _open_session(): _set_ssl_default_options() failed");
+	}
+      else
+	{
+	  syslog (LOG_DEBUG, "pam_ldap: _open_session(): _set_ssl_default_options() successful");
 	}
 #endif
 #ifdef HAVE_LDAP_INITIALIZE
@@ -1256,18 +1265,24 @@
 	  int rc = ldap_initialize (&session->ld, session->conf->uri);
 	  if (rc != LDAP_SUCCESS)
 	    {
-	      syslog (LOG_ERR, "pam_ldap: ldap_initialize %s",
+	      syslog (LOG_ERR, "pam_ldap: _open_session() failed with PAM_SERVICE_ERR: ldap_initialize() failed: %s",
 		      ldap_err2string (rc));
 	      return PAM_SERVICE_ERR;
 	    }
+	  else
+	    {
+        syslog (LOG_DEBUG, "pam_ldap: _open_session(): ldap_initialize() successful");
+      }
 	}
       else
 	{
 #endif /* HAVE_LDAP_INTITIALIZE */
 #ifdef HAVE_LDAP_INIT
 	  session->ld = ldap_init (session->conf->host, session->conf->port);
+    if (session->ld == NULL) syslog (LOG_ERR, "pam_ldap: _open_session(): ldap_init() failed");
 #else
 	  session->ld = ldap_open (session->conf->host, session->conf->port);
+    if (session->ld == NULL) syslog (LOG_ERR, "pam_ldap: _open_session(): ldap_open() failed");
 #endif /* HAVE_LDAP_INIT */
 #ifdef HAVE_LDAP_INITIALIZE
 	}
@@ -1276,9 +1291,12 @@
 
   if (session->ld == NULL)
     {
+      syslog (LOG_ERR, "pam_ldap: _open_session(): failed with PAM_SERVICE_ERR: unable to establish an LDAP session");
       return PAM_SERVICE_ERR;
     }
 
+    syslog (LOG_DEBUG, "pam_ldap: _open_session(): calling ldap_set_option() for SSL");
+
 #if defined(HAVE_LDAP_SET_OPTION) && defined(LDAP_OPT_X_TLS)
   if (session->conf->ssl_on == SSL_LDAPS)
     {
@@ -1286,19 +1304,26 @@
       int rc = ldap_set_option (session->ld, LDAP_OPT_X_TLS, &tls);
       if (rc != LDAP_SUCCESS)
 	{
-	  syslog (LOG_ERR, "pam_ldap: ldap_set_option(LDAP_OPT_X_TLS) %s",
+	  syslog (LOG_ERR, "pam_ldap: _open_session() failed with PAM_SERVICE_ERR: ldap_set_option(LDAP_OPT_X_TLS) failed: %s",
 		  ldap_err2string (rc));
 	  return PAM_SERVICE_ERR;
 	}
+      else
+        {
+          syslog (LOG_DEBUG, "pam_ldap: _open_session(): ldap_set_option(LDAP_OPT_X_TLS) successful");
+        }
 
       /* set up SSL per-context settings */
       if (_set_ssl_options (session) != LDAP_SUCCESS)
 	{
-	  syslog (LOG_ERR, "pam_ldap: _set_ssl_options failed");
+				  syslog (LOG_ERR, "pam_ldap: _open_session(): _set_ssl_options() failed");
 	}
     }
 #endif /* LDAP_OPT_X_TLS */
 
+    syslog (LOG_DEBUG, "pam_ldap: _open_session(): calling ldap_set_option() for misc options");
+
+
 #if defined(HAVE_LDAP_SET_OPTION) && defined(LDAP_OPT_PROTOCOL_VERSION)
   (void) ldap_set_option (session->ld, LDAP_OPT_PROTOCOL_VERSION,
 			  &session->conf->version);
@@ -1333,13 +1358,19 @@
    * we use the bind_timelimit to control this.
    */
   timeout = session->conf->bind_timelimit * 1000;
-  (void) ldap_set_option (session->ld, LDAP_X_OPT_CONNECT_TIMEOUT, &timeout);
+	int rc = ldap_set_option (session->ld, LDAP_X_OPT_CONNECT_TIMEOUT, &timeout);
+  if (rc != LDAP_OPT_SUCCESS) {
+		syslog(LOG_ERR, "pam_ldap:_open_session() failed to set option LDAP_X_OPT_CONNECT_TIMEOUT=%u: %s", timeout, ldap_err2string(rc));
+	}
 #endif
 
 #if defined(HAVE_LDAP_SET_OPTION) && defined(LDAP_OPT_NETWORK_TIMEOUT)
   tv.tv_sec = session->conf->bind_timelimit;
   tv.tv_usec = 0;
-  (void) ldap_set_option (session->ld, LDAP_OPT_NETWORK_TIMEOUT, &tv);
+	int rc = ldap_set_option (session->ld, LDAP_OPT_NETWORK_TIMEOUT, &tv);
+  if (rc != LDAP_OPT_SUCCESS) {
+		syslog(LOG_ERR, "pam_ldap:_open_session() failed to set option LDAP_OPT_NETWORK_TIMEOUT=%u: %s", tv.tv_sec, ldap_err2string(rc));
+	}
 #endif
 
 #if defined(HAVE_LDAP_SET_OPTION) && defined(LDAP_OPT_REFERRALS)
@@ -1372,19 +1403,32 @@
 	  /* set up SSL context */
 	  if (_set_ssl_options (session) != LDAP_SUCCESS)
 	    {
-	      syslog (LOG_ERR, "pam_ldap: _set_ssl_options failed");
+				syslog (LOG_ERR, "pam_ldap: _open_session(): _set_ssl_options() failed in SSL_START_TLS block");
+			}
+			else
+			{
+				syslog (LOG_DEBUG, "pam_ldap: _open_session(): _set_ssl_options() successful");
 	    }
 
 	  rc = ldap_start_tls_s (session->ld, NULL, NULL);
 	  if (rc != LDAP_SUCCESS)
 	    {
-	      syslog (LOG_ERR, "pam_ldap: ldap_starttls_s: %s",
+				syslog (LOG_ERR, "pam_ldap: _open_session() failed with PAM_SERVICE_ERR: ldap_starttls_s() failed: %s",
 		      ldap_err2string (rc));
 	      return PAM_SERVICE_ERR;
 	    }
+			else
+			{
+				syslog (LOG_DEBUG, "pam_ldap: _open_session(): ldap_starttls_s(): successful");
+			}
+		}
+	else
+		{
+			syslog (LOG_ERR, "pam_ldap: _open_session(): ldap_get_option(LDAP_OPT_PROTOCOL_VERSION) failed");
 	}
     }
 #endif /* HAVE_LDAP_START_TLS_S */
+  syslog (LOG_DEBUG, "pam_ldap: _open_session() successful");
   return PAM_SUCCESS;
 }
 
@@ -1515,9 +1559,11 @@
 
   if (session->ld == NULL)
     {
+			if (session->info != NULL) {
+				syslog(LOG_DEBUG, "pam_ldap: _connect_anonymously() called with non-null session: session->info->username = %s", session->info->username);
+			}
       rc = _open_session (session);
-      if (rc != PAM_SUCCESS)
-	return rc;
+      if (rc != PAM_SUCCESS) return rc;
     }
 
   if (session->conf->rootbinddn && geteuid () == 0)
@@ -1525,17 +1571,31 @@
       msgid = ldap_simple_bind (session->ld,
 				session->conf->rootbinddn,
 				session->conf->rootbindpw);
+
+      if (msgid == -1) {
+        syslog (LOG_ERR, 
+					"pam_ldap: _connect_anonymously(): ldap_simple_bind() using rootbinddn %s failed: %s",
+          session->conf->rootbinddn,
+          ldap_err2string (ldap_get_lderrno (session->ld, 0, 0))
+				);
+      }
     }
   else
     {
       msgid = ldap_simple_bind (session->ld,
 				session->conf->binddn, session->conf->bindpw);
+
+      if (msgid == -1) {
+        syslog (LOG_ERR, 
+					"pam_ldap: _connect_anonymously(): ldap_simple_bind() using user dn %s failed: %s",
+          session->conf->binddn,
+          ldap_err2string (ldap_get_lderrno (session->ld, 0, 0))
+				);
+      }
     }
 
   if (msgid == -1)
     {
-      syslog (LOG_ERR, "pam_ldap: ldap_simple_bind %s",
-	      ldap_err2string (ldap_get_lderrno (session->ld, 0, 0)));
       return PAM_AUTHINFO_UNAVAIL;
     }
 
@@ -1544,7 +1604,7 @@
   rc = ldap_result (session->ld, msgid, FALSE, &timeout, &result);
   if (rc == -1 || rc == 0)
     {
-      syslog (LOG_ERR, "pam_ldap: ldap_result %s",
+      syslog (LOG_ERR, "pam_ldap: _connect_anonymously() failed with PAM_AUTHINFO_UNAVAIL: ldap_result %s",
 	      ldap_err2string (ldap_get_lderrno (session->ld, 0, 0)));
       return PAM_AUTHINFO_UNAVAIL;
     }
@@ -1557,7 +1617,7 @@
 
   if (rc != LDAP_SUCCESS)
     {
-      syslog (LOG_ERR, "pam_ldap: error trying to bind (%s)",
+      syslog (LOG_ERR, "pam_ldap: _connect_anonymously() failed with PAM_CRED_INSUFFICIENT: error trying to bind (%s)",
 	      ldap_err2string (rc));
       return PAM_CRED_INSUFFICIENT;
     }
@@ -1885,23 +1945,31 @@
 #endif /* HAVE_LDAP_PARSE_RESULT && HAVE_LDAP_CONTROLS_FREE */
 
   /* avoid binding anonymously with a DN but no password */
-  if (password == NULL || password[0] == '\0')
+  if (password == NULL || password[0] == '\0') {
+		syslog(LOG_INFO, "pam_ldap: _connect_as_user() failed: returning PAM_AUTH_ERR due to null password");
     return PAM_AUTH_ERR;
+	}
 
   /* this shouldn't ever happen */
-  if (session->info == NULL)
+  if (session->info == NULL) {
+		syslog(LOG_ERR, "pam_ldap: _connect_as_user() failed: returning PAM_SYSTEM_ERR due to null session. Please file a bug report - this should be impossible!");
     return PAM_SYSTEM_ERR;
+	}
 
   /* if we already bound as the user don't bother retrying */
-  if (session->info->bound_as_user)
+  if (session->info->bound_as_user) {
+		syslog(LOG_DEBUG, "pam_ldap: _connect_as_user() success: reusing existing session for %s", session->info->username);
     return PAM_SUCCESS;
+	}
 
   if (session->ld == NULL)
     {
       rc = _open_session (session);
-      if (rc != PAM_SUCCESS)
+      if (rc != PAM_SUCCESS) {
+				syslog(LOG_ERR, "pam_ldap: _connect_as_user() failed: _open_sesssion() for user %s returned %d", session->info->username, rc);
 	return rc;
     }
+    }
 
   /*
    * We copy the password temporarily so that when referrals are
@@ -1915,12 +1983,15 @@
     }
 
   session->info->userpw = strdup (password);
-  if (session->info->userpw == NULL)
+  if (session->info->userpw == NULL) {
+		syslog(LOG_ERR, "pam_ldap: _connect_as_user() failed: returning PAM_BUF_ERR due to null password after strdup");
     return PAM_BUF_ERR;
+	}
 
 #if (defined(HAVE_SASL_SASL_H) || defined(HAVE_SASL_H)) && defined(HAVE_LDAP_SASL_INTERACTIVE_BIND_S)
   if (session->conf->sasl_mechanism != NULL)
     {
+			syslog(LOG_DEBUG, "pam_ldap: _connect_as_user() starting SASL negotiation");
       void *args[]  = { pamh, session };
 
       passwd_policy_req.ldctl_oid = LDAP_CONTROL_PASSWORDPOLICYREQUEST;
@@ -1945,13 +2016,16 @@
 					 _do_sasl_interact, &args);
       if (rc != LDAP_SUCCESS)
 	{
-	  syslog (LOG_ERR, "pam_ldap: ldap_sasl_interactive_bind %s",
-		  ldap_err2string (ldap_get_lderrno (session->ld, 0, 0)));
+					syslog (LOG_ERR, "pam_ldap: _connect_as_user() failed: ldap_sasl_interactive_bind(%s) failed: %s",
+						session->info->userdn,
+						ldap_err2string (ldap_get_lderrno (session->ld, 0, 0))
+					);
 	  _pam_overwrite (session->info->userpw);
 	  _pam_drop (session->info->userpw);
 	  return PAM_AUTHINFO_UNAVAIL;
 	}
       session->info->bound_as_user = 1;
+			syslog(LOG_DEBUG, "pam_ldap: _connect_as_user() successful: ldap_sasl_interactive_bind_s complete");
       return PAM_SUCCESS;
     }
 #endif
@@ -1967,17 +2041,21 @@
       srvctrls[0] = &passwd_policy_req;
       srvctrls[1] = 0;
 
-      rc =
-	ldap_sasl_bind (session->ld, session->info->userdn, LDAP_SASL_SIMPLE,
-			&userpw, srvctrls, 0, &msgid);
+      rc = ldap_sasl_bind (session->ld, session->info->userdn, LDAP_SASL_SIMPLE, &userpw, srvctrls, 0, &msgid);
       if (rc != LDAP_SUCCESS || msgid == -1)
 	{
-	  syslog (LOG_ERR, "pam_ldap: ldap_sasl_bind %s",
-		  ldap_err2string (ldap_get_lderrno (session->ld, 0, 0)));
+					syslog (LOG_ERR, "pam_ldap: _connect_as_user(): ldap_sasl_bind(%s) failed: %s",
+						session->info->userdn,
+						ldap_err2string (ldap_get_lderrno (session->ld, 0, 0))
+					);
 	  _pam_overwrite (session->info->userpw);
 	  _pam_drop (session->info->userpw);
 	  return PAM_AUTHINFO_UNAVAIL;
 	}
+			else 
+				{
+					syslog (LOG_DEBUG, "pam_ldap: _connect_as_user(): ldap_sasl_bind(%s) successful", session->info->userdn);
+				}
     }
   else
     {
@@ -1985,12 +2063,18 @@
 				session->info->userpw);
       if (msgid == -1)
 	{
-	  syslog (LOG_ERR, "pam_ldap: ldap_simple_bind %s",
-		  ldap_err2string (ldap_get_lderrno (session->ld, 0, 0)));
+					syslog (LOG_ERR, "pam_ldap: _connect_as_user() failed: ldap_simple_bind(%s) failed: %s",
+						session->info->userdn,
+						ldap_err2string (ldap_get_lderrno (session->ld, 0, 0))
+					);
 	  _pam_overwrite (session->info->userpw);
 	  _pam_drop (session->info->userpw);
 	  return PAM_AUTHINFO_UNAVAIL;
 	}
+			else 
+				{
+					syslog (LOG_DEBUG, "pam_ldap: _connect_as_user(): ldap_simple_bind(%s) successful", session->info->userdn);
+				}
     }
 #else
   msgid =
@@ -1998,12 +2082,18 @@
 		      session->info->userpw);
   if (msgid == -1)
     {
-      syslog (LOG_ERR, "pam_ldap: ldap_simple_bind %s",
-	      ldap_err2string (ldap_get_lderrno (session->ld, 0, 0)));
+			syslog (LOG_ERR, "pam_ldap: _connect_as_user() failed: ldap_simple_bind(%s) failed: %s",
+				session->info->userdn,
+				ldap_err2string (ldap_get_lderrno (session->ld, 0, 0))
+			);
       _pam_overwrite (session->info->userpw);
       _pam_drop (session->info->userpw);
       return PAM_AUTHINFO_UNAVAIL;
     }
+	else 
+		{
+			syslog (LOG_DEBUG, "pam_ldap: _connect_as_user(): ldap_simple_bind(%s) successful", session->info->userdn);
+		}
 #endif /* HAVE_LDAP_SASL_BIND && LDAP_SASL_SIMPLE */
 
   timeout.tv_sec = 10;
@@ -2017,6 +2107,10 @@
       _pam_drop (session->info->userpw);
       return PAM_AUTHINFO_UNAVAIL;
     }
+	else
+		{
+			syslog (LOG_DEBUG, "pam_ldap: _connect_as_user(): ldap_result() successful");
+		}
 
 #if defined(HAVE_LDAP_PARSE_RESULT) && defined(HAVE_LDAP_CONTROLS_FREE)
   controls = 0;
@@ -2030,6 +2124,11 @@
       _pam_drop (session->info->userpw);
       return PAM_SERVICE_ERR;
     }
+	else
+		{
+			syslog (LOG_DEBUG, "pam_ldap: _connect_as_user(): ldap_parse_result() successful");
+		}
+
   if (controls != NULL)
     {
       LDAPControl **ctlp;
@@ -2111,8 +2210,10 @@
 
   if (rc != LDAP_SUCCESS)
     {
-      syslog (LOG_ERR, "pam_ldap: error trying to bind as user \"%s\" (%s)",
-	      session->info->userdn, ldap_err2string (rc));
+      syslog (LOG_ERR, "pam_ldap: _connect_as_user(\"%s\") failed: (%s)",
+	      session->info->userdn, 
+				ldap_err2string (rc)
+			);
       _pam_overwrite (session->info->userpw);
       _pam_drop (session->info->userpw);
       return PAM_AUTH_ERR;
@@ -2127,6 +2228,7 @@
 
   session->info->bound_as_user = 1;
 
+	syslog (LOG_DEBUG, "pam_ldap: _connect_as_user() successfully bound as user \"%s\"", session->info->userdn);
   return PAM_SUCCESS;
 }
 
@@ -2534,8 +2636,7 @@
     }
   else
     {
-      snprintf (filter, sizeof filter, "(%s=%s)",
-		session->conf->userattr, escapedUser);
+      snprintf (filter, sizeof filter, "(%s=%s)", session->conf->userattr, escapedUser);
     }
 
   rc = ldap_search_s (session->ld, ssd->base, ssd->scope,
@@ -2544,9 +2645,13 @@
   if (rc != LDAP_SUCCESS &&
       rc != LDAP_TIMELIMIT_EXCEEDED && rc != LDAP_SIZELIMIT_EXCEEDED)
     {
-      syslog (LOG_ERR, "pam_ldap: ldap_search_s %s", ldap_err2string (rc));
+      syslog (LOG_ERR, "pam_ldap: _get_user_info() failed: ldap_search_s(base=\"%s\", filter=\"%s\") failed: %s", ssd->base, filter, ldap_err2string (rc));
       return PAM_USER_UNKNOWN;
     }
+  else
+    {
+      syslog (LOG_DEBUG, "pam_ldap: _get_user_info(): ldap_search_s(base=\"%s\", filter=\"%s\") successful", ssd->base, filter);
+    }
 
   msg = ldap_first_entry (session->ld, res);
   if (msg == NULL)
@@ -2832,12 +2937,18 @@
     {
       rc = _get_user_info (session, user);
       if (rc != PAM_SUCCESS)
+				{
+					syslog(LOG_INFO, "pam_ldap:_do_authentication() failed: expected PAM_SUCCESS but _get_user_info() returned %d", rc);
 	return rc;
     }
+    }
 
   rc = _session_reopen (session);
   if (rc != PAM_SUCCESS)
+		{
+			syslog(LOG_INFO, "pam_ldap:_do_authentication() failed: expected PAM_SUCCESS but _session_reopen() returned %d", rc);
     return rc;
+		}
 
   rc = _connect_as_user (pamh, session, password);
   _session_reopen (session);
@@ -2896,12 +3007,10 @@
        * user can bypass local password policy
        */
       rc = _session_reopen (session);
-      if (rc != PAM_SUCCESS)
-	return rc;
+      if (rc != PAM_SUCCESS) return rc;
 
       rc = _connect_as_user (pamh, session, old_password);
-      if (rc != PAM_SUCCESS)
-	return rc;
+      if (rc != PAM_SUCCESS) return rc;
     }
 
   switch (session->conf->password_type)
@@ -3224,7 +3333,7 @@
       else if (!strcmp (argv[i], "debug"))
 	;
       else
-	syslog (LOG_ERR, "illegal option %s", argv[i]);
+	syslog (LOG_ERR, "pam_ldap: illegal option %s", argv[i]);
     }
 
   rc = pam_get_user (pamh, (CONST_ARG char **) &username, NULL);
@@ -3356,7 +3465,7 @@
       else if (!strcmp (argv[i], "use_authtok"))
 	use_authtok = 1;
       else
-	syslog (LOG_ERR, "illegal option %s", argv[i]);
+	syslog (LOG_ERR, "pam_ldap: illegal option %s", argv[i]);
     }
 
   if (flags & PAM_SILENT)
@@ -3758,7 +3867,7 @@
       else if (!strcmp (argv[i], "debug"))
 	;
       else
-	syslog (LOG_ERR, "illegal option %s", argv[i]);
+	syslog (LOG_ERR, "pam_ldap: illegal option %s", argv[i]);
     }
 
   if (flags & PAM_SILENT)