WebbBLOG
Michael Webb's Weblog

Debugging PAM in Native LDAP (Part 2)

Quick Review of authentication:

pam_start() service=su, user=test1, pam_conv= 23230, pamh= 26f60

pam_authenticate() pamh=26f60 flags=0

pam_get_item() service=su
pam_get_user (pamh=26f60)
pam_get_item() user=test1

pam_get_item() conv=12618

pam_get_item() authtok=********

pam_authtok_get.so.1 returned Ignore module

pam_dhkeys.so.1 returned Ignore module

pam_unix_auth.so.1 returned Ignore module

pam_ldap.so.1 returned Success

Nov 18 13:26:11 ldapserver su: [ID 473974 local6.debug] PAM[23983]:
pam_acct_mgmt(26f60, 0)

The pam_acct_mgmt() function is called to determine if the current user's account is valid. It checks for password and account expiration, and verifies access hour restrictions. This function is typically called after the user has been authenticated with pam_authenticate(3PAM).

The pamh argument is an authentication handle obtained by a prior call to pam_start()

pam_acct_mgmt() pamh=26f60, flags=0

Nov 18 13:26:11 ldapserver su: [ID 472425 local6.debug] PAM[23983]:
load_modules(26f60, pam_sm_acct_mgmt)=/usr/lib/security/pam_roles.so.1

Nov 18 13:26:11 ldapserver su: [ID 899501 local6.debug] PAM[23983]:
load_function: successful load of pam_sm_acct_mgmt
Nov 18 13:26:11 ldapserver su: [ID 472425 local6.debug] PAM[23983]:
load_modules(26f60,
pam_sm_acct_mgmt)=/usr/lib/security/pam_projects.so.1
Nov 18 13:26:11 ldapserver su: [ID 899501 local6.debug] PAM[23983]:
load_function: successful load of pam_sm_acct_mgmt
Nov 18 13:26:11 ldapserver su: [ID 472425 local6.debug] PAM[23983]:
load_modules(26f60,

pam_sm_acct_mgmt)=/usr/lib/security/pam_unix_account.so.1
Nov 18 13:26:11 ldapserver su: [ID 899501 local6.debug] PAM[23983]:
load_function: successful load of pam_sm_acct_mgmt
Nov 18 13:26:11 ldapserver su: [ID 472425 local6.debug] PAM[23983]:
load_modules(26f60, pam_sm_acct_mgmt)=/usr/lib/security/pam_ldap.so.1
Nov 18 13:26:11 ldapserver su: [ID 899501 local6.debug] PAM[23983]:
load_function: successful load of pam_sm_acct_mgmt

The following modules are now “stacked” from pam account management:

pam_roles.so.1

pam_projects.so.1
pam_unix_account.so.1
pam_ldap.so.1

This should be very familiar by now

Nov 18 13:26:11 ldapserver su: [ID 393443 local6.debug] PAM[23983]:
pam_get_item(26f60:user)=test1

Nov 18 13:26:11 ldapserver su: [ID 393443 local6.debug] PAM[23983]:
pam_get_item(26f60:ruser)=NULL
Nov 18 13:26:11 ldapserver su: [ID 393443 local6.debug] PAM[23983]:
pam_get_item(26f60:service)=su
Nov 18 13:26:11 ldapserver su: [ID 975205 local6.debug] PAM[23983]:
pam_get_data(26f60:libpam)=2ab70
Nov 18 13:26:11 ldapserver su: [ID 579194 local6.debug] PAM[23983]:
pam_acct_mgmt(26f60, 0): /usr/lib/security/pam_roles.so.1 returned
Ignore module

Nov 18 13:26:11 ldapserver su: [ID 393443 local6.debug] PAM[23983]:
pam_get_item(26f60:user)=test1
Nov 18 13:26:11 ldapserver su: [ID 393443 local6.debug] PAM[23983]:
pam_get_item(26f60:service)=su
Nov 18 13:26:11 ldapserver su: [ID 975205 local6.debug] PAM[23983]:
pam_get_data(26f60:libpam)=2ab70
Nov 18 13:26:11 ldapserver su: [ID 579194 local6.debug] PAM[23983]:
pam_acct_mgmt(26f60, 0): /usr/lib/security/pam_projects.so.1 returned
Success

PAM went through the stacked modules until pam_projects.so.1 was successful

Nov 18 13:26:11 ldapserver su: [ID 393443 local6.debug] PAM[23983]:
pam_get_item(26f60:user)=test1
Nov 18 13:26:11 ldapserver su: [ID 975208 local6.debug] PAM[23983]:
pam_get_data(26f60:SUNW-UNIX-AUTHTOK-DATA)=PAM_NO_MODULE_DATA
Nov 18 13:26:11 ldapserver su: [ID 999781 local6.debug] PAM[23983]:
pam_set_data(26f60:SUNW-UNIX-AUTHTOK-DATA)=52310

Nov 18 13:26:11 ldapserver su: [ID 975205 local6.debug] PAM[23983]:
pam_get_data(26f60:libpam)=2ab70
Nov 18 13:26:11 ldapserver su: [ID 579194 local6.debug] PAM[23983]:
pam_acct_mgmt(26f60, 0): /usr/lib/security/pam_unix_account.so.1
returned Ignore module
Nov 18 13:26:11 ldapserver su: [ID 393443 local6.debug] PAM[23983]:
pam_get_item(26f60:user)=test1
Nov 18 13:26:11 ldapserver su: [ID 393443 local6.debug] PAM[23983]:
pam_get_item(26f60:authtok)=********

Nov 18 13:26:11 ldapserver su: [ID 975205 local6.debug] PAM[23983]:
pam_get_data(26f60:libpam)=2ab70
Nov 18 13:26:11 ldapserver su: [ID 579194 local6.debug] PAM[23983]:
pam_acct_mgmt(26f60, 0): /usr/lib/security/pam_ldap.so.1 returned
Success

PAM contines through the stacked modules until pam_ldap.so.1 was successful

Nov 18 13:26:11 ldapserver su: [ID 975205 local6.debug] PAM[23983]:
pam_get_data(26f60:libpam)=2ab70

Nov 18 13:26:11 ldapserver su: [ID 560004 local6.debug] PAM[23983]:
pam_acct_mgmt(26f60, 0): final: Success
Nov 18 13:26:11 ldapserver su[23983]: [ID 473974 local6.debug]
PAM[23983]: pam_setcred(26f60, 1)

The pam_setcred() function is used to establish, modify, or delete user credentials. It is typically called after the user has been authenticated and after a session has been opened. See pam_authenticate(3PAM), pam_acct_mgmt(3PAM), and pam_open_session(3PAM).

The user is specified by a prior call to pam_start() or pam_set_item(), and is referenced by the authentication handle, pamh.

pam_setcred() pamh=26f60, flags=1

Nov 18 13:26:11 ldapserver su[23983]: [ID 472425 local6.debug]
PAM[23983]: load_modules(26f60,
pam_sm_setcred)=/usr/lib/security/pam_authtok_get.so.1
Nov 18 13:26:11 ldapserver su[23983]: [ID 899501 local6.debug]
PAM[23983]: load_function: successful load of pam_sm_setcred
Nov 18 13:26:11 ldapserver su[23983]: [ID 472425 local6.debug]
PAM[23983]: load_modules(26f60,
pam_sm_setcred)=/usr/lib/security/pam_dhkeys.so.1
Nov 18 13:26:11 ldapserver su[23983]: [ID 899501 local6.debug]

PAM[23983]: load_function: successful load of pam_sm_setcred
Nov 18 13:26:11 ldapserver su[23983]: [ID 472425 local6.debug]
PAM[23983]: load_modules(26f60,
pam_sm_setcred)=/usr/lib/security/pam_unix_auth.so.1
Nov 18 13:26:11 ldapserver su[23983]: [ID 899501 local6.debug]
PAM[23983]: load_function: successful load of pam_sm_setcred
Nov 18 13:26:11 ldapserver su[23983]: [ID 472425 local6.debug]
PAM[23983]: load_modules(26f60,
pam_sm_setcred)=/usr/lib/security/pam_ldap.so.1

Nov 18 13:26:11 ldapserver su[23983]: [ID 899501 local6.debug]
PAM[23983]: load_function: successful load of pam_sm_setcred

pam_setcred invokes pam_sm_setcred and loads the following modules:

pam_authtok_get.so.1

pam_dhkeys.so.1

pam_unix_auth.so.1
pam_ldap.so.1

Nov 18 13:26:11 ldapserver su[23983]: [ID 975205 local6.debug]
PAM[23983]: pam_get_data(26f60:libpam)=2ab70
Nov 18 13:26:11 ldapserver su[23983]: [ID 579194 local6.debug]
PAM[23983]: pam_setcred(26f60, 1):
/usr/lib/security/pam_authtok_get.so.1 returned Ignore module
Nov 18 13:26:11 ldapserver su[23983]: [ID 393443 local6.debug]
PAM[23983]: pam_get_item(26f60:user)=test1
Nov 18 13:26:11 ldapserver su[23983]: [ID 393443 local6.debug]

PAM[23983]: pam_get_item(26f60:authtok)=********
Nov 18 13:26:11 ldapserver su[23983]: [ID 393443 local6.debug]
PAM[23983]: pam_get_item(26f60:repository)=NULL
Nov 18 13:26:11 ldapserver su[23983]: [ID 975205 local6.debug]
PAM[23983]: pam_get_data(26f60:libpam)=2ab70
Nov 18 13:26:11 ldapserver su[23983]: [ID 579194 local6.debug]
PAM[23983]: pam_setcred(26f60, 1): /usr/lib/security/pam_dhkeys.so.1
returned Success
Nov 18 13:26:11 ldapserver su[23983]: [ID 975205 local6.debug]

PAM[23983]: pam_get_data(26f60:libpam)=2ab70
Nov 18 13:26:11 ldapserver su[23983]: [ID 579194 local6.debug]
PAM[23983]: pam_setcred(26f60, 1): /usr/lib/security/pam_unix_auth.so.1
returned Success
Nov 18 13:26:11 ldapserver su[23983]: [ID 967791 local6.debug]
PAM[23983]: pam_setcred(26f60, 1): binding: success

Module stack as follows:

pam_authtok_get.so.1 returned Ignore module

pam_dhkeys.so.1 returned Success

pam_unix_auth.so.1 returned Success 
pam_ldap.so.1

As long as one “Success” gets returned within the stack, 

the module returns overall success.  A binding, requisite or required flag 

will instruct whether to proceed “down the stack” once a success is achieved

Nov 18 13:26:11 ldapserver su[23983]: [ID 167879 local6.debug]
PAM[23983]: pam_getenvlist(26f60)

The pam_getenvlist() function returns a list of all the PAM environment variables stored in the PAM handle pamh. The list is returned as a null-terminated array of pointers to strings. Each string contains a single PAM environment variable of the form name=value. The list returned is a duplicate copy of all the environment variables stored in pamh. It is the responsibility of the calling application to free the memory returned by pam_getenvlist().

Nov 18 13:26:11 ldapserver su[23983]: [ID 975205 local6.debug]
PAM[23983]: pam_get_data(26f60:libpam)=2ab70
Nov 18 13:26:11 ldapserver su[23983]: [ID 117046 local6.debug]

PAM[23983]: pam_end(26f60): status = Success

The pam_end() function is called to terminate the authentication transaction identified by pamh and to free any storage area allocated by the authentication module. The argument, status, is passed to the cleanup(|) function stored within the pam handle, and is used to determine what module-specific state must be purged. A cleanup function is attached to the handle by the underlying PAM modules through a call to pam_set_data(3PAM) to free module-specific data.