summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorGerald Carter <jerry@samba.org>2007-01-25 01:56:34 +0000
committerGerald (Jerry) Carter <jerry@samba.org>2007-10-10 12:17:27 -0500
commit7e8a068a5edd6676353e80535660d803fc5bdfe4 (patch)
treead643d5d978480f10e99b8e5e21c9c3e3da47e56
parent76fd8f8e1d774f247423ddfe0c76c3f89bbd3b48 (diff)
downloadsamba-7e8a068a5edd6676353e80535660d803fc5bdfe4.tar.gz
samba-7e8a068a5edd6676353e80535660d803fc5bdfe4.tar.bz2
samba-7e8a068a5edd6676353e80535660d803fc5bdfe4.zip
r21012: Patch from Danilo Almeida @ Centeris (via me):
Details: Improve PAM logging - The improved logging is far tracking down PAM-related bugs - PAM_SILENT was being mis-used to suppress syslog output instead of suppressing user output. This lets PAM_SILENT still log to syslog. - Allow logging of item & data state via debug_state config file option. - Logging tracks the pam handle used. (This used to be commit cc1a13a9f06e5c15c8df19d0fbb31dbdeb81a9cc)
-rw-r--r--source3/nsswitch/pam_winbind.c188
-rw-r--r--source3/nsswitch/pam_winbind.h1
2 files changed, 168 insertions, 21 deletions
diff --git a/source3/nsswitch/pam_winbind.c b/source3/nsswitch/pam_winbind.c
index 91a333b93d..593adfe2f2 100644
--- a/source3/nsswitch/pam_winbind.c
+++ b/source3/nsswitch/pam_winbind.c
@@ -12,6 +12,18 @@
#include "pam_winbind.h"
+#define _PAM_LOG_FUNCTION_ENTER(function, pamh, ctrl, flags) \
+ do { \
+ _pam_log_debug(pamh, ctrl, LOG_DEBUG, "[pamh: 0x%08x] ENTER: " function " (flags: 0x%04x)", (uint32) pamh, flags); \
+ _pam_log_state(pamh, ctrl); \
+ } while (0)
+
+#define _PAM_LOG_FUNCTION_LEAVE(function, pamh, ctrl, retval) \
+ do { \
+ _pam_log_debug(pamh, ctrl, LOG_DEBUG, "[pamh: 0x%08x] LEAVE: " function " returning %d", (uint32) pamh, retval); \
+ _pam_log_state(pamh, ctrl); \
+ } while (0)
+
/* data tokens */
#define MAX_PASSWD_TRIES 3
@@ -61,11 +73,16 @@ static void _pam_log_int(const pam_handle_t *pamh, int err, const char *format,
}
#endif /* HAVE_PAM_VSYSLOG */
+static inline int _pam_log_is_silent(int ctrl)
+{
+ return (ctrl & WINBIND_SILENT) ? 1 : 0;
+}
+
static void _pam_log(const pam_handle_t *pamh, int ctrl, int err, const char *format, ...)
{
va_list args;
- if (ctrl & WINBIND_SILENT) {
+ if (_pam_log_is_silent(ctrl)) {
return;
}
@@ -74,15 +91,37 @@ static void _pam_log(const pam_handle_t *pamh, int ctrl, int err, const char *fo
va_end(args);
}
-static void _pam_log_debug(const pam_handle_t *pamh, int ctrl, int err, const char *format, ...)
+static inline int _pam_log_is_debug_enabled(int ctrl)
{
- va_list args;
+ if (ctrl == -1) {
+ return 0;
+ }
- if (ctrl & WINBIND_SILENT) {
- return;
+ if (_pam_log_is_silent(ctrl)) {
+ return 0;
}
if (!(ctrl & WINBIND_DEBUG_ARG)) {
+ return 0;
+ }
+
+ return 1;
+}
+
+static inline int _pam_log_is_debug_state_enabled(int ctrl)
+{
+ if (!(ctrl & WINBIND_DEBUG_STATE)) {
+ return 0;
+ }
+
+ return _pam_log_is_debug_enabled(ctrl);
+}
+
+static void _pam_log_debug(const pam_handle_t *pamh, int ctrl, int err, const char *format, ...)
+{
+ va_list args;
+
+ if (!_pam_log_is_debug_enabled(ctrl)) {
return;
}
@@ -91,6 +130,74 @@ static void _pam_log_debug(const pam_handle_t *pamh, int ctrl, int err, const ch
va_end(args);
}
+static void _pam_log_state_datum(const pam_handle_t *pamh, int ctrl, int item_type, const char *key, int is_string)
+{
+ const void *data = NULL;
+ if (item_type != 0) {
+ pam_get_item(pamh, item_type, &data);
+ } else {
+ pam_get_data(pamh, key, &data);
+ }
+ if (data != NULL) {
+ const char *type = (item_type != 0) ? "ITEM" : "DATA";
+ if (is_string != 0) {
+ _pam_log_debug(pamh, ctrl, LOG_DEBUG, "[pamh: 0x%08x] STATE: %s(%s) = \"%s\" (0x%08x)", (uint32) pamh, type, key, (const char *) data, (uint32) data);
+ } else {
+ _pam_log_debug(pamh, ctrl, LOG_DEBUG, "[pamh: 0x%08x] STATE: %s(%s) = 0x%08x", (uint32) pamh, type, key, (uint32) data);
+ }
+ }
+}
+
+#define _PAM_LOG_STATE_DATA_POINTER(pamh, ctrl, module_data_name) \
+ _pam_log_state_datum(pamh, ctrl, 0, module_data_name, 0)
+
+#define _PAM_LOG_STATE_DATA_STRING(pamh, ctrl, module_data_name) \
+ _pam_log_state_datum(pamh, ctrl, 0, module_data_name, 1)
+
+#define _PAM_LOG_STATE_ITEM_POINTER(pamh, ctrl, item_type) \
+ _pam_log_state_datum(pamh, ctrl, item_type, #item_type, 0)
+
+#define _PAM_LOG_STATE_ITEM_STRING(pamh, ctrl, item_type) \
+ _pam_log_state_datum(pamh, ctrl, item_type, #item_type, 1)
+
+#ifdef DEBUG_PASSWORD
+#define _LOG_PASSWORD_AS_STRING 1
+#else
+#define _LOG_PASSWORD_AS_STRING 0
+#endif
+
+#define _PAM_LOG_STATE_ITEM_PASSWORD(pamh, ctrl, item_type) \
+ _pam_log_state_datum(pamh, ctrl, item_type, #item_type, _LOG_PASSWORD_AS_STRING)
+
+static void _pam_log_state(const pam_handle_t *pamh, int ctrl)
+{
+ if (!_pam_log_is_debug_state_enabled(ctrl)) {
+ return;
+ }
+
+ _PAM_LOG_STATE_ITEM_STRING(pamh, ctrl, PAM_SERVICE);
+ _PAM_LOG_STATE_ITEM_STRING(pamh, ctrl, PAM_USER);
+ _PAM_LOG_STATE_ITEM_STRING(pamh, ctrl, PAM_TTY);
+ _PAM_LOG_STATE_ITEM_STRING(pamh, ctrl, PAM_RHOST);
+ _PAM_LOG_STATE_ITEM_STRING(pamh, ctrl, PAM_RUSER);
+ _PAM_LOG_STATE_ITEM_PASSWORD(pamh, ctrl, PAM_OLDAUTHTOK);
+ _PAM_LOG_STATE_ITEM_PASSWORD(pamh, ctrl, PAM_AUTHTOK);
+ _PAM_LOG_STATE_ITEM_STRING(pamh, ctrl, PAM_USER_PROMPT);
+ _PAM_LOG_STATE_ITEM_POINTER(pamh, ctrl, PAM_CONV);
+#ifdef PAM_FAIL_DELAY
+ _PAM_LOG_STATE_ITEM_POINTER(pamh, ctrl, PAM_FAIL_DELAY);
+#endif
+#ifdef PAM_REPOSITORY
+ _PAM_LOG_STATE_ITEM_POINTER(pamh, ctrl, PAM_REPOSITORY);
+#endif
+
+ _PAM_LOG_STATE_DATA_STRING(pamh, ctrl, PAM_WINBIND_HOMEDIR);
+ _PAM_LOG_STATE_DATA_STRING(pamh, ctrl, PAM_WINBIND_LOGONSCRIPT);
+ _PAM_LOG_STATE_DATA_STRING(pamh, ctrl, PAM_WINBIND_PROFILEPATH);
+ _PAM_LOG_STATE_DATA_STRING(pamh, ctrl, PAM_WINBIND_NEW_AUTHTOK_REQD); /* Use atoi to get PAM result code */
+ _PAM_LOG_STATE_DATA_POINTER(pamh, ctrl, PAM_WINBIND_PWD_LAST_SET);
+}
+
static int _pam_parse(const pam_handle_t *pamh, int flags, int argc, const char **argv, dictionary **result_d)
{
int ctrl = 0;
@@ -124,6 +231,10 @@ static int _pam_parse(const pam_handle_t *pamh, int flags, int argc, const char
ctrl |= WINBIND_DEBUG_ARG;
}
+ if (iniparser_getboolean(d, "global:debug_state", False)) {
+ ctrl |= WINBIND_DEBUG_STATE;
+ }
+
if (iniparser_getboolean(d, "global:cached_login", False)) {
ctrl |= WINBIND_CACHED_LOGIN;
}
@@ -139,7 +250,7 @@ static int _pam_parse(const pam_handle_t *pamh, int flags, int argc, const char
if (iniparser_getstr(d, "global:krb5_ccache_type") != NULL) {
ctrl |= WINBIND_KRB5_CCACHE_TYPE;
}
-
+
if ((iniparser_getstr(d, "global:require-membership-of") != NULL) ||
(iniparser_getstr(d, "global:require_membership_of") != NULL)) {
ctrl |= WINBIND_REQUIRED_MEMBERSHIP;
@@ -194,6 +305,10 @@ config_from_pam:
static void _pam_winbind_cleanup_func(pam_handle_t *pamh, void *data, int error_status)
{
+ int ctrl = _pam_parse(pamh, 0, 0, NULL, NULL);
+ if (_pam_log_is_debug_state_enabled(ctrl)) {
+ _pam_log_debug(pamh, ctrl, LOG_DEBUG, "[pamh: 0x%08x] CLEAN: cleaning up PAM data 0x%08x (error_status = %d)", (uint32) pamh, (uint32) data, error_status);
+ }
SAFE_FREE(data);
}
@@ -275,21 +390,33 @@ static int _make_remark(pam_handle_t * pamh, int type, const char *text)
return retval;
}
-static int _make_remark_format(pam_handle_t * pamh, int type, const char *format, ...)
+static int _make_remark_v(pam_handle_t * pamh, int type, const char *format, va_list args)
{
- va_list args;
char *var;
int ret;
- va_start(args, format);
- vasprintf(&var, format, args);
- va_end(args);
+ ret = vasprintf(&var, format, args);
+ if (ret < 0) {
+ _pam_log(pamh, 0, LOG_ERR, "memory allocation failure");
+ return ret;
+ }
ret = _make_remark(pamh, type, var);
SAFE_FREE(var);
return ret;
}
+static int _make_remark_format(pam_handle_t * pamh, int type, const char *format, ...)
+{
+ int ret;
+ va_list args;
+
+ va_start(args, format);
+ ret = _make_remark_v(pamh, type, format, args);
+ va_end(args);
+ return ret;
+}
+
static int pam_winbind_request(pam_handle_t * pamh, int ctrl,
enum winbindd_cmd req_type,
struct winbindd_request *request,
@@ -972,6 +1099,8 @@ static int _winbind_read_password(pam_handle_t * pamh,
const char *item;
char *token;
+ _pam_log(pamh, ctrl, LOG_DEBUG, "getting password (0x%08x)", ctrl);
+
/*
* make sure nothing inappropriate gets returned
*/
@@ -999,6 +1128,8 @@ static int _winbind_read_password(pam_handle_t * pamh,
} else if (item != NULL) { /* we have a password! */
*pass = item;
item = NULL;
+ _pam_log(pamh, ctrl, LOG_DEBUG,
+ "pam_get_item returned a password");
return PAM_SUCCESS;
} else if (on(WINBIND_USE_FIRST_PASS_ARG, ctrl)) {
return PAM_AUTHTOK_RECOVER_ERR; /* didn't work */
@@ -1188,7 +1319,7 @@ int pam_sm_authenticate(pam_handle_t *pamh, int flags,
goto out;
}
- _pam_log_debug(pamh, ctrl, LOG_DEBUG, "pam_winbind: pam_sm_authenticate (flags: 0x%04x)", flags);
+ _PAM_LOG_FUNCTION_ENTER("pam_sm_authenticate", pamh, ctrl, flags);
/* Get the username */
retval = pam_get_user(pamh, &username, NULL);
@@ -1249,6 +1380,13 @@ out:
if (d) {
iniparser_freedict(d);
}
+
+ if (!new_authtok_required) {
+ pam_set_data(pamh, PAM_WINBIND_NEW_AUTHTOK_REQD, NULL, NULL);
+ }
+
+ _PAM_LOG_FUNCTION_LEAVE("pam_sm_authenticate", pamh, ctrl, retval);
+
return retval;
}
@@ -1266,7 +1404,7 @@ int pam_sm_setcred(pam_handle_t *pamh, int flags,
goto out;
}
- _pam_log_debug(pamh, ctrl, LOG_DEBUG, "pam_winbind: pam_sm_setcred (flags: 0x%04x)", flags);
+ _PAM_LOG_FUNCTION_ENTER("pam_sm_setcred", pamh, ctrl, flags);
switch (flags & ~PAM_SILENT) {
@@ -1295,10 +1433,8 @@ int pam_sm_setcred(pam_handle_t *pamh, int flags,
iniparser_freedict(d);
}
- if (!new_authtok_required) {
- pam_set_data(pamh, PAM_WINBIND_NEW_AUTHTOK_REQD, NULL, NULL);
- }
-
+ _PAM_LOG_FUNCTION_LEAVE("pam_sm_setcred", pamh, ctrl, ret);
+
return ret;
}
@@ -1321,7 +1457,7 @@ int pam_sm_acct_mgmt(pam_handle_t *pamh, int flags,
return PAM_SYSTEM_ERR;
}
- _pam_log_debug(pamh, ctrl, LOG_DEBUG, "pam_winbind: pam_sm_acct_mgmt (flags: 0x%04x)", flags);
+ _PAM_LOG_FUNCTION_ENTER("pam_sm_acct_mgmt", pamh, ctrl, flags);
/* Get the username */
@@ -1391,6 +1527,8 @@ int pam_sm_acct_mgmt(pam_handle_t *pamh, int flags,
iniparser_freedict(d);
}
+ _PAM_LOG_FUNCTION_LEAVE("pam_sm_acct_mgmt", pamh, ctrl, ret);
+
return ret;
}
@@ -1408,7 +1546,7 @@ int pam_sm_open_session(pam_handle_t *pamh, int flags,
goto out;
}
- _pam_log_debug(pamh, ctrl, LOG_DEBUG, "pam_winbind: pam_sm_open_session handler (flags: 0x%04x)", flags);
+ _PAM_LOG_FUNCTION_ENTER("pam_sm_open_session", pamh, ctrl, flags);
ret = PAM_SUCCESS;
@@ -1417,6 +1555,8 @@ int pam_sm_open_session(pam_handle_t *pamh, int flags,
iniparser_freedict(d);
}
+ _PAM_LOG_FUNCTION_LEAVE("pam_sm_open_session", pamh, ctrl, ret);
+
return ret;
}
@@ -1434,7 +1574,7 @@ int pam_sm_close_session(pam_handle_t *pamh, int flags,
goto out;
}
- _pam_log_debug(pamh, ctrl, LOG_DEBUG, "pam_winbind: pam_sm_close_session handler (flags: 0x%04x)", flags);
+ _PAM_LOG_FUNCTION_ENTER("pam_sm_close_session", pamh, ctrl, flags);
if (!(flags & PAM_DELETE_CRED)) {
retval = PAM_SUCCESS;
@@ -1497,6 +1637,9 @@ out:
if (d) {
iniparser_freedict(d);
}
+
+ _PAM_LOG_FUNCTION_LEAVE("pam_sm_close_session", pamh, ctrl, retval);
+
return retval;
}
@@ -1526,7 +1669,7 @@ int pam_sm_chauthtok(pam_handle_t * pamh, int flags,
goto out;
}
- _pam_log_debug(pamh, ctrl, LOG_DEBUG, "pam_winbind: pam_sm_chauthtok (flags: 0x%04x)", flags);
+ _PAM_LOG_FUNCTION_ENTER("pam_sm_chauthtok", pamh, ctrl, flags);
/* clearing offline bit for the auth in the password change */
ctrl &= ~WINBIND_CACHED_LOGIN;
@@ -1739,6 +1882,9 @@ out:
if (d) {
iniparser_freedict(d);
}
+
+ _PAM_LOG_FUNCTION_LEAVE("pam_sm_chauthtok", pamh, ctrl, ret);
+
return ret;
}
diff --git a/source3/nsswitch/pam_winbind.h b/source3/nsswitch/pam_winbind.h
index 87307d740d..91f662d5d0 100644
--- a/source3/nsswitch/pam_winbind.h
+++ b/source3/nsswitch/pam_winbind.h
@@ -86,6 +86,7 @@ do { \
#define WINBIND_CACHED_LOGIN (1<<9)
#define WINBIND_CONFIG_FILE (1<<10)
#define WINBIND_SILENT (1<<11)
+#define WINBIND_DEBUG_STATE (1<<12)
/*
* here is the string to inform the user that the new passwords they