pam_mkhomedir and priv separation

[Chuck McIntyre]

Hello,

I'm not sure if this has already been addressed, I looked through the 
archives and can't seem to find anything. I also did some Usenet 
searching and only found one article mentioning this, and it was
in French.

Anyway, the problem is that it appears as though when using privsep
opensshd doesn't execute pam_session as root, and this causes 
pam_mkhomedir to fail. pam_mkhomedir creates a user's home directory
if it doesn't exist (useful for ldap or other directory based auth
schemes). 

This seems similar to bug 83 (http://bugzilla.mindrot.org/show_bug.cgi?id=83) 
but I am not a developer and I'm not sure if it's the same issue, can 
anyone comment on this? Is there a workaround aside from disabling
privilege separation or making the parent directory (i.e. /home)  
world-writable (both of which do solve the issue)?

Thanks,
Chuck McIntyre


I have attached the debugging information below, if it matters.

--- from sshd -d -d -d ---
debug1: sshd version OpenSSH_3.4p1
debug1: private host key: #0 type 0 RSA1
debug3: Not a RSA1 key file /etc/ssh/ssh_host_rsa_key.
debug1: read PEM private key done: type RSA
debug1: private host key: #1 type 1 RSA
debug3: Not a RSA1 key file /etc/ssh/ssh_host_dsa_key.
debug1: read PEM private key done: type DSA
debug1: private host key: #2 type 2 DSA
socket: Address family not supported by protocol
debug1: Bind to port 22 on 0.0.0.0.
Server listening on 0.0.0.0 port 22.
Generating 768 bit RSA key.
RSA key generation complete.
debug1: Server will not fork when running in debugging mode.
Connection from 10.1.10.107 port 33304
debug1: Client protocol version 2.0; client software version OpenSSH_3.4p1
debug1: match: OpenSSH_3.4p1 pat OpenSSH*
Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-1.99-OpenSSH_3.4p1
debug2: Network child is on pid 4078
debug3: preauth child monitor started
debug3: mm_request_receive entering
debug3: privsep user:group 74:74
debug1: list_hostkey_types: ssh-rsa,ssh-dss
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: first_kex_follows 0 
debug2: kex_parse_kexinit: reserved 0 
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none
debug2: kex_parse_kexinit: none
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: 
debug2: kex_parse_kexinit: first_kex_follows 0 
debug2: kex_parse_kexinit: reserved 0 
debug2: mac_init: found hmac-md5
debug1: kex: client->server aes128-cbc hmac-md5 none
debug2: mac_init: found hmac-md5
debug1: kex: server->client aes128-cbc hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received
debug3: mm_request_send entering: type 0
debug3: monitor_read: checking request 0
debug3: mm_answer_moduli: got parameters: 1024 2048 8192
debug3: mm_request_send entering: type 1
debug2: monitor_read: 0 used once, disabling now
debug3: mm_request_receive entering
debug3: mm_choose_dh: waiting for MONITOR_ANS_MODULI
debug3: mm_request_receive_expect entering: type 1
debug3: mm_request_receive entering
debug3: mm_choose_dh: remaining 0
debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
debug1: dh_gen_key: priv key bits set: 145/256
debug1: bits set: 1565/3191
debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
debug1: bits set: 1640/3191
debug3: mm_key_sign entering
debug3: mm_request_send entering: type 4
debug3: monitor_read: checking request 4
debug3: mm_answer_sign
debug3: mm_answer_sign: signature 0x80a4530(143)
debug3: mm_request_send entering: type 5
debug2: monitor_read: 4 used once, disabling now
debug3: mm_request_receive entering
debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN
debug3: mm_request_receive_expect entering: type 5
debug3: mm_request_receive entering
debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
debug1: kex_derive_keys
debug1: newkeys: mode 1
debug1: SSH2_MSG_NEWKEYS sent
debug1: waiting for SSH2_MSG_NEWKEYS
debug1: newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: KEX done
debug1: userauth-request for user ldapguy service ssh-connection method none
debug1: attempt 0 failures 0
debug3: mm_getpwnamallow entering
debug3: mm_request_send entering: type 6
debug3: monitor_read: checking request 6
debug3: mm_answer_pwnamallow
debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
debug3: mm_request_send entering: type 7
debug2: monitor_read: 6 used once, disabling now
debug3: mm_request_receive entering
debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM
debug3: mm_request_receive_expect entering: type 7
debug3: mm_request_receive entering
debug2: input_userauth_request: setting up authctxt for ldapguy
debug3: mm_start_pam entering
debug3: mm_request_send entering: type 37
debug3: monitor_read: checking request 37
debug1: Starting up PAM with username "ldapguy"
debug3: Trying to reverse map address 10.1.10.107.
debug1: PAM setting rhost to "atreus.quinstreet.net"
debug2: monitor_read: 37 used once, disabling now
debug3: mm_request_receive entering
debug3: mm_inform_authserv entering
debug3: mm_request_send entering: type 3
debug3: monitor_read: checking request 3
debug3: mm_answer_authserv: service=ssh-connection, style=
debug2: monitor_read: 3 used once, disabling now
debug3: mm_request_receive entering
debug2: input_userauth_request: try method none
debug3: mm_auth_password entering
debug3: mm_request_send entering: type 10
debug3: monitor_read: checking request 10
debug3: mm_answer_authpassword: sending result 0
debug3: mm_request_send entering: type 11
Failed none for ldapguy from 10.1.10.107 port 33304 ssh2
debug3: mm_request_receive entering
debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD
debug3: mm_request_receive_expect entering: type 11
debug3: mm_request_receive entering
debug3: mm_auth_password: user not authenticated
Failed none for ldapguy from 10.1.10.107 port 33304 ssh2
debug1: userauth-request for user ldapguy service ssh-connection method publickey
debug1: attempt 1 failures 1
debug2: input_userauth_request: try method publickey
debug1: test whether pkalg/pkblob are acceptable
debug3: mm_key_allowed entering
debug3: mm_request_send entering: type 20
debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED
debug3: mm_request_receive_expect entering: type 21
debug3: mm_request_receive entering
debug3: monitor_read: checking request 20
debug3: mm_answer_keyallowed entering
debug3: mm_answer_keyallowed: key_from_blob: 0x809e008
debug1: temporarily_use_uid: 555/555 (e=0)
debug1: trying public key file /opt/home/ldapguy/.ssh/authorized_keys
debug1: restore_uid
debug1: temporarily_use_uid: 555/555 (e=0)
debug1: trying public key file /opt/home/ldapguy/.ssh/authorized_keys2
debug1: restore_uid
debug3: mm_answer_keyallowed: key 0x809e008 is disallowed
debug3: mm_request_send entering: type 21
debug3: mm_request_receive entering
debug2: userauth_pubkey: authenticated 0 pkalg ssh-dss
Failed publickey for ldapguy from 10.1.10.107 port 33304 ssh2
debug1: userauth-request for user ldapguy service ssh-connection method keyboard-interactive
debug1: attempt 2 failures 2
debug2: input_userauth_request: try method keyboard-interactive
debug1: keyboard-interactive devs 
debug1: auth2_challenge: user=ldapguy devs=
debug1: kbdint_alloc: devices ''
debug2: auth2_challenge_start: devices 
Failed keyboard-interactive for ldapguy from 10.1.10.107 port 33304 ssh2
debug1: userauth-request for user ldapguy service ssh-connection method password
debug1: attempt 3 failures 3
debug2: input_userauth_request: try method password
debug3: mm_auth_password entering
debug3: mm_request_send entering: type 10
debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD
debug3: mm_request_receive_expect entering: type 11
debug3: mm_request_receive entering
debug3: monitor_read: checking request 10
debug1: PAM Password authentication accepted for user "ldapguy"
debug3: mm_answer_authpassword: sending result 1
debug3: mm_request_send entering: type 11
debug3: mm_auth_password: user authenticated
Accepted password for ldapguy from 10.1.10.107 port 33304 ssh2
debug3: mm_send_keystate: Sending new keys: 0x809f298 0x809ddc8
debug3: mm_newkeys_to_blob: converting 0x809f298
debug3: mm_newkeys_to_blob: converting 0x809ddc8
debug3: mm_send_keystate: New keys have been sent
debug3: mm_send_keystate: Sending compression state
debug3: mm_request_send entering: type 24
debug3: mm_send_keystate: Finished sending state
debug2: pam_acct_mgmt() = 0
Accepted password for ldapguy from 10.1.10.107 port 33304 ssh2
debug1: monitor_child_preauth: ldapguy has been authenticated by privileged process
debug3: mm_get_keystate: Waiting for new keys
debug3: mm_request_receive_expect entering: type 24
debug3: mm_request_receive entering
debug3: mm_newkeys_from_blob: 0x8152a60(118)
debug2: mac_init: found hmac-md5
debug3: mm_get_keystate: Waiting for second key
debug3: mm_newkeys_from_blob: 0x8152a60(118)
debug2: mac_init: found hmac-md5
debug3: mm_get_keystate: Getting compression state
debug3: mm_get_keystate: Getting Network I/O buffers
debug3: mm_share_sync: Share sync
debug3: mm_share_sync: Share sync end
debug2: User child is on pid 4079
debug3: mm_request_receive entering
debug1: PAM establishing creds
debug1: newkeys: mode 0
debug1: newkeys: mode 1
debug1: Entering interactive session for SSH2.
debug1: fd 10 setting O_NONBLOCK
debug1: fd 11 setting O_NONBLOCK
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 65536 max 16384
debug1: input_session_request
debug1: channel 0: new [server-session]
debug1: session_new: init
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: server_input_channel_req: channel 0 request pty-req reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req pty-req
debug1: lastlog_openseek: Couldn't open /var/log/lastlog: Permission denied
debug1: Allocating pty.
debug3: mm_request_send entering: type 25
debug3: monitor_read: checking request 25
debug3: mm_answer_pty entering
debug1: session_new: init
debug1: session_new: session 0
debug3: mm_request_send entering: type 26
debug3: mm_answer_pty: tty /dev/pts/14 ptyfd 7
debug3: mm_request_receive entering
debug3: mm_pty_allocate: waiting for MONITOR_ANS_PTY
debug3: mm_request_receive_expect entering: type 26
debug3: mm_request_receive entering
debug1: session_pty_req: session 0 alloc /dev/pts/14
debug3: tty_parse_modes: SSH2 n_bytes 256
debug3: tty_parse_modes: ospeed 38400
debug3: tty_parse_modes: ispeed 38400
debug3: tty_parse_modes: 1 3
debug3: tty_parse_modes: 2 28
debug3: tty_parse_modes: 3 127
debug3: tty_parse_modes: 4 21
debug3: tty_parse_modes: 5 4
debug3: tty_parse_modes: 6 0
debug3: tty_parse_modes: 7 0
debug3: tty_parse_modes: 8 17
debug3: tty_parse_modes: 9 19
debug3: tty_parse_modes: 10 26
debug3: tty_parse_modes: 12 18
debug3: tty_parse_modes: 13 23
debug3: tty_parse_modes: 14 22
debug3: tty_parse_modes: 18 15
debug3: tty_parse_modes: 30 1
debug3: tty_parse_modes: 31 0
debug3: tty_parse_modes: 32 0
debug3: tty_parse_modes: 33 0
debug3: tty_parse_modes: 34 0
debug3: tty_parse_modes: 35 0
debug3: tty_parse_modes: 36 1
debug3: tty_parse_modes: 37 0
debug3: tty_parse_modes: 38 1
debug3: tty_parse_modes: 39 0
debug3: tty_parse_modes: 40 0
debug3: tty_parse_modes: 41 1
debug3: tty_parse_modes: 50 1
debug3: tty_parse_modes: 51 1
debug3: tty_parse_modes: 52 0
debug3: tty_parse_modes: 53 1
debug3: tty_parse_modes: 54 1
debug3: tty_parse_modes: 55 1
debug3: tty_parse_modes: 56 0
debug3: tty_parse_modes: 57 0
debug3: tty_parse_modes: 58 0
debug3: tty_parse_modes: 59 1
debug3: tty_parse_modes: 60 1
debug3: tty_parse_modes: 61 1
debug3: tty_parse_modes: 62 0
debug3: tty_parse_modes: 70 1
debug3: tty_parse_modes: 71 0
debug3: tty_parse_modes: 72 1
debug3: tty_parse_modes: 73 0
debug3: tty_parse_modes: 74 0
debug3: tty_parse_modes: 75 0
debug3: tty_parse_modes: 90 1
debug3: tty_parse_modes: 91 1
debug3: tty_parse_modes: 92 0
debug3: tty_parse_modes: 93 0
debug1: server_input_channel_req: channel 0 request x11-req reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req x11-req
debug1: x11_create_display_inet: Socket family 10 not supported
debug1: fd 14 setting O_NONBLOCK
debug2: fd 14 is O_NONBLOCK
debug1: channel 1: new [X11 inet listener]
debug1: server_input_channel_req: channel 0 request shell reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req shell
debug1: PAM setting tty to "/dev/pts/14"
PAM session setup failed[6]: Permission denied
debug1: Calling cleanup 0x805d290(0x809b700)
debug3: mm_request_send entering: type 27
debug3: monitor_read: checking request 27
debug3: mm_answer_pty_cleanup entering
debug1: session_by_tty: session 0 tty /dev/pts/14
debug3: mm_session_close: session 0 pid 4079
debug3: mm_session_close: tty /dev/pts/14 ptyfd 7
debug1: session_pty_cleanup: session 0 release /dev/pts/14
debug3: mm_request_receive entering
debug1: Calling cleanup 0x8064020(0x0)
debug1: channel_free: channel 0: server-session, nchannels 2
debug3: channel_free: status: The following connections are open:
  #0 server-session (t10 r0 i0/0 o0/0 fd -1/-1)

debug3: channel_close_fds: channel 0: r -1 w -1 e -1
debug1: channel_free: channel 1: X11 inet listener, nchannels 1
debug3: channel_free: status: The following connections are open:

debug3: channel_close_fds: channel 1: r 14 w 14 e -1
debug1: Calling cleanup 0x80549c0(0x0)
debug1: Calling cleanup 0x8071110(0x0)
debug1: Calling cleanup 0x80549c0(0x0)
debug1: Calling cleanup 0x8071110(0x0)
--- END sshd -d -d -d ---