From 7e8a068a5edd6676353e80535660d803fc5bdfe4 Mon Sep 17 00:00:00 2001 From: Gerald Carter Date: Thu, 25 Jan 2007 01:56:34 +0000 Subject: 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) --- source3/nsswitch/pam_winbind.c | 188 ++++++++++++++++++++++++++++++++++++----- source3/nsswitch/pam_winbind.h | 1 + 2 files changed, 168 insertions(+), 21 deletions(-) (limited to 'source3') 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 -- cgit