Running sshd with Privilege Seperation drops connection on password change
Nasim, Kam
Kam.Nasim at windriver.com
Thu Dec 17 09:34:11 AEDT 2015
Hi Darren/Damien,
Sorry for responding so late. Still hope we can get this sorted out.
Yes I am indeed using PAM for ssh authentication and disabling priv seperation is a no-go for us since it opens up a security loophole.
From what I can see in ptree and auth logs, when the child passwd process returns with SIGCHLD, the parent sshd process terminates.
Sshd logs are as follows as requested at DEBUG3 verbosity. They indicate the ssh, followed by the password change and finally termination of connection:
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: monitor_read: checking request 12
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: PAM: sshpam_passwd_conv called with 1 messages
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug1: PAM: password authentication accepted for nasim
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_answer_authpassword: sending result 1
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_request_send entering: type 13
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_request_receive_expect entering: type 102
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_request_receive entering
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug1: do_pam_account: called
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: pam_unix(sshd:account): expired password for user nasim (root enforced)
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: PAM: sshpam_passwd_conv called with 1 messages
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: PAM: do_pam_account pam_acct_mgmt = 12 (Authentication token is no longer valid; new one required)
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: sshpam_password_change_required 1
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_request_send entering: type 103
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: Accepted password for nasim from 128.224.145.117 port 52060 ssh2
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug1: monitor_child_preauth: nasim has been authenticated by privileged process
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_get_keystate: Waiting for new keys
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_request_receive_expect entering: type 26
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_request_receive entering
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_newkeys_from_blob: 0x7f175498ad80(138)
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug2: mac_setup: setup hmac-md5-etm at openssh.com
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_get_keystate: Waiting for second key
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_newkeys_from_blob: 0x7f175498ad80(138)
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug2: mac_setup: setup hmac-md5-etm at openssh.com
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_get_keystate: Getting compression state
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_get_keystate: Getting Network I/O buffers
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_auth_password: user authenticated [preauth]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_request_receive entering [preauth]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_do_pam_account returning 1 [preauth]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_send_keystate: Sending new keys: 0x7f17549728f0 0x7f17549733a0 [preauth]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_newkeys_to_blob: converting 0x7f17549728f0 [preauth]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_newkeys_to_blob: converting 0x7f17549733a0 [preauth]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_send_keystate: New keys have been sent [preauth]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_send_keystate: Sending compression state [preauth]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_request_send entering: type 26 [preauth]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_send_keystate: Finished sending state [preauth]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug1: monitor_read_log: child log fd closed
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_share_sync: Share sync
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_share_sync: Share sync end
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug1: PAM: establishing credentials
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: PAM: opening session
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: pam_unix(sshd:session): session opened for user nasim by (uid=0)
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: PAM: sshpam_store_conv called with 1 messages
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: message repeated 2 times: [ debug3: PAM: sshpam_store_conv called with 1 messages]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: User child is on pid 8623
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: SELinux support disabled
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: PAM: establishing credentials
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: permanently_set_uid: 1003/1003
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug2: set_newkeys: mode 0
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug2: set_newkeys: mode 1
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: Entering interactive session for SSH2.
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug2: fd 5 setting O_NONBLOCK
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug2: fd 6 setting O_NONBLOCK
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: server_init_dispatch_20
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: input_session_request
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: channel 0: new [server-session]
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug2: session_new: allocate (allocated 0 max 10)
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug3: session_unused: session id 0 unused
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: session_new: session 0
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: session_open: channel 0
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: session_open: session 0: link with channel 0
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: server_input_channel_open: confirm session
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: server_input_global_request: rtype no-more-sessions at openssh.com want_reply 0
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: server_input_channel_req: channel 0 request pty-req reply 1
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: session_by_channel: session 0 channel 0
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: session_input_channel_req: session 0 req pty-req
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: Allocating pty.
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug3: mm_request_send entering: type 28
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_request_receive entering
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: monitor_read: checking request 28
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_answer_pty entering
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug2: session_new: allocate (allocated 0 max 10)
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: session_unused: session id 0 unused
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug1: session_new: session 0
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug1: SELinux support disabled
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_request_send entering: type 29
Dec 16 22:22:13 knasim-ubuntu1 sshd[8569]: debug3: mm_answer_pty: tty /dev/pts/1 ptyfd 4
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug3: mm_pty_allocate: waiting for MONITOR_ANS_PTY
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug3: mm_request_receive_expect entering: type 29
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug3: mm_request_receive entering
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: session_pty_req: session 0 alloc /dev/pts/1
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: server_input_channel_req: channel 0 request env reply 0
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: session_by_channel: session 0 channel 0
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: session_input_channel_req: session 0 req env
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug2: Setting env 0: LANG=en_US.UTF-8
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: server_input_channel_req: channel 0 request shell reply 1
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: session_by_channel: session 0 channel 0
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug1: session_input_channel_req: session 0 req shell
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: Starting session: shell on pts/1 for nasim from 128.224.145.117 port 52060
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug2: fd 3 setting TCP_NODELAY
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug3: packet_set_tos: set IP_TOS 0x10
Dec 16 22:22:13 knasim-ubuntu1 sshd[8624]: debug1: Setting controlling tty using TIOCSCTTY.
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug2: channel 0: rfd 10 isatty
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug2: fd 10 setting O_NONBLOCK
Dec 16 22:22:13 knasim-ubuntu1 sshd[8623]: debug3: fd 8 is O_NONBLOCK
Dec 16 22:22:24 knasim-ubuntu1 passwd[8624]: pam_unix(passwd:chauthtok): password changed for nasim
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug1: Received SIGCHLD.
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug1: session_by_pid: pid 8624
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug1: session_exit_message: session 0 channel 0 pid 8624
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: request exit-status confirm 0
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug1: session_exit_message: release channel 0
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: write failed
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: close_write
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: send eow
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: output open -> closed
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug3: mm_request_send entering: type 30
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug3: mm_request_receive entering
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug3: monitor_read: checking request 30
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug3: mm_answer_pty_cleanup entering
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug1: session_by_tty: session 0 tty /dev/pts/1
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug3: mm_session_close: session 0 pid 8623
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug3: mm_session_close: tty /dev/pts/1 ptyfd 4
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug1: session_pty_cleanup: session 0 release /dev/pts/1
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug3: session_unused: session id 0 unused
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: notify_done: reading
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: read<=0 rfd 10 len -1
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: read failed
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: close_read
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: input open -> drain
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: ibuf empty
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: send eof
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: input drain -> closed
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: send close
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug3: channel 0: will not send data after close
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: rcvd close
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug3: channel 0: will not send data after close
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: is dead
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: gc: notify user
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug1: session_by_channel: session 0 channel 0
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug1: session_close_by_channel: channel 0 child 0
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug1: session_close: session 0 pid 0
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug3: session_unused: session id 0 unused
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: gc: user detached
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: is dead
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug2: channel 0: garbage collecting
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug1: channel 0: free: server-session, nchannels 1
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug3: channel 0: status: The following connections are open:\r\n #0 server-session (t4 r0 i3/0 o3/0 fd -1/-1 cc -1)\r\n
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: Received disconnect from 128.224.145.117: 11: disconnected by user
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug1: do_cleanup
Dec 16 22:22:24 knasim-ubuntu1 sshd[8623]: debug3: PAM: sshpam_thread_cleanup entering
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug3: mm_request_receive entering
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug1: do_cleanup
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug1: PAM: cleanup
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug1: PAM: closing session
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: pam_unix(sshd:session): session closed for user nasim
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug1: PAM: deleting credentials
Dec 16 22:22:24 knasim-ubuntu1 sshd[8569]: debug3: PAM: sshpam_thread_cleanup entering
Let me know what you guys think.
Thanks,
Kam
-----Original Message-----
From: dtucker at dtucker.net [mailto:dtucker at dtucker.net] On Behalf Of Darren Tucker
Sent: December-06-15 11:48 PM
To: Nasim, Kam
Cc: openssh-unix-dev at mindrot.org
Subject: Re: Running sshd with Privilege Seperation drops connection on password change
There's 3 ways that sshd will force you to change an expired password when you have PAM enabled (which you do):
1) if you're using keyboard-interactive authentication, sshd will call
pam_chauthtok() as part of the authentication. This should work with or without privsep.
If you authenticate some other way (eg password), sshd will force you to change your password once you start your session.
2) if you have privilege separation enabled, by the time your session starts sshd has dropped the privileges needed to successfully call pam_chauthtok(). Instead, it'll exec /bin/passwd.
3) if you have privsep disabled, sshd is still running as root and will call pam_chauthtok().
On Sat, Dec 5, 2015 at 3:23 AM, Nasim, Kam <Kam.Nasim at windriver.com> wrote:
[...]
> PROBLEM:
> If I expire a linux user's password (passwd -e <user>) and then log in via ssh, it will prompt you for a password change.
> On changing the password successfully, sshd will drop the connection and client has to reconnect.
That's working as intended, and you should have seen text to that effect. In session.c (simplified):
static void
do_pwchange(Session *s)
{
fprintf(stderr, "WARNING: Your password has expired.\n");
if (s->ttyfd != -1) {
fprintf(stderr,
"You must change your password now and login again!\n");
execl(_PATH_PASSWD_PROG, "passwd", (char *)NULL);
> If I disable Privilege Seperation ("UsePrivilegeSeperation no") in sshd config then the problem goes away but that opens up a security loophole where the process is running at root privilege even prior to authentication.
RIght, see #3 above.
--
Darren Tucker (dtucker at zip.com.au)
GPG key 8FF4FA69 / D9A3 86E9 7EEE AF4B B2D4 37C9 C982 80C7 8FF4 FA69
Good judgement comes with experience. Unfortunately, the experience usually comes from bad judgement.
-----Original Message-----
From: Damien Miller [mailto:djm at mindrot.org]
Sent: December-06-15 11:16 PM
To: Nasim, Kam
Cc: openssh-unix-dev at mindrot.org
Subject: Re: Running sshd with Privilege Seperation drops connection on password change
Hi,
We'll need to see a full debug log from the server - it's not possible to see what is going one from the abridged ones you sent.
-d
On Fri, 4 Dec 2015, Nasim, Kam wrote:
> Hi folks,
>
> I came across this issue on both stock CentOS(v6.4) and Ubuntu(14.04 LTS) and was wondering if any of you have seen it.
> As far as I can tell this seems like a day-1 bug to me.
>
> PROBLEM:
> If I expire a linux user's password (passwd -e <user>) and then log in via ssh, it will prompt you for a password change.
> On changing the password successfully, sshd will drop the connection and client has to reconnect.
>
>
> ANALYSIS:
>
> Looking at sshd debug logs, it would appear that the child process that runs passwd SIGCHLD's to the parent which appears to be treating that signal as a SIGTERM:
>
> Dec 3 18:36:17 knasim-ubuntu1 passwd[3152]:
> pam_unix(passwd:chauthtok): password changed for wrs <<<<<<< Dec 3
> 18:36:17 knasim-ubuntu1 sshd[3151]: debug1: Received SIGCHLD.
> <<<<<<<<<<<<<<<<<< Dec 3 18:36:17 knasim-ubuntu1 sshd[3151]: debug1:
> session_by_pid: pid 3152 Dec 3 18:36:17 knasim-ubuntu1 sshd[3151]:
> debug1: session_exit_message: session 0 channel 0 pid 3152 Dec 3
> 18:36:17 knasim-ubuntu1 sshd[3151]: debug2: channel 0: request
> exit-status confirm 0 <<<<<<<<<<<
>
>
> By default, in sshd "Privilege Separation" is enabled. What does this mean?
>
> It means that sshd spawns an unprivileged process that does basic authentication and that guy spawns a child process running as root to run passwd (in this case).
>
> After password change, the child SIGCHLD's the parent which instead of handling it properly treats it like a SIGTERM and closes the socket.
>
> The following process tree should give a better idea of the process nestings:
>
> With Privilege Separation:
> ubuntu at knasim-ubuntu1:~$ pstree
> init─┬─acpid
> ├─atd
> ├─cron
> ├─dbus-daemon
> ├─dhclient
> ├─7*[getty]
> ├─rsyslogd───3*[{rsyslogd}]
> ├─sshd───bash───ssh
> ├─sshd───bash───pstree
> ├─sshd───sshd───sshd───passwd
> ├─systemd-logind
> ├─systemd-udevd
> ├─upstart-file-br
> ├─upstart-socket-
> └─upstart-udev-br
>
> Without Privilege Separation:
> init─┬─acpid
> ├─atd
> ├─cron
> ├─dbus-daemon
> ├─dhclient
> ├─7*[getty]
> ├─rsyslogd───3*[{rsyslogd}]
> ├─sshd─┬─sshd───bash───ssh
> │ ├─sshd───bash───pstree
> │ └─sshd───sshd
> ├─systemd-logind
> ├─systemd-udevd
> ├─upstart-file-br
> ├─upstart-socket-
> └─upstart-udev-br
>
> If I disable Privilege Seperation ("UsePrivilegeSeperation no") in sshd config then the problem goes away but that opens up a security loophole where the process is running at root privilege even prior to authentication.
>
>
> What do you guys think? Have others come across this? Is there a patch available for this?
>
> Thanks,
> Kam
> _______________________________________________
> openssh-unix-dev mailing list
> openssh-unix-dev at mindrot.org
> https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
>
More information about the openssh-unix-dev
mailing list