openssh unix dev - Dec 2015 - Running sshd with Privilege Seperation drops connection on password change

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

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
>

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.

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
>