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@xxxxxxxxxxx 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@xxxxxxxxxxx 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@xxxxxxxxxxx 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@xxxxxxxxxxx [mailto:dtucker@xxxxxxxxxxx] On Behalf Of Darren Tucker Sent: December-06-15 11:48 PM To: Nasim, Kam Cc: openssh-unix-dev@xxxxxxxxxxx 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@xxxxxxxxxxxxx> 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@xxxxxxxxxxx] Sent: December-06-15 11:16 PM To: Nasim, Kam Cc: openssh-unix-dev@xxxxxxxxxxx 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@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@xxxxxxxxxxx > https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev > _______________________________________________ openssh-unix-dev mailing list openssh-unix-dev@xxxxxxxxxxx https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev