Problem with non-interactive shells on Sol8 with 3.7.1p1

[Ed Phillips]

One more item that might help:

"ssh -t sys1 ls -al" seems to work on the affected systems.  So it would
seem there's something going wrong on these systems whenever sshd isn't
allocating a tty...

	Ed

On Mon, 22 Sep 2003, Ed Phillips wrote:

> We recently started upgrading OpenSSH on our Sol8 systems and we've run
> into a problem were we can run commands on a remote system since we
> installed 3.7.1p1.  The debug output from sshd is attached below.  We use
> PAM in our environment, and have since 2.9.9p2.  I think most of the
> systems were running 3.4p1 prior installing 3.7.1p1 and they were working
> - the only thing we replaced was OpenSSH itself, without changing any
> PAM/system configuration, etc.
>
> The strange part is that it's only some of our Sol8 systems that don't
> work (appears somewhat random which do/don't).  For machines that work,
> they always work ("ssh sys1 ls -al" works all the time).  For those that
> don't work, they never work ("ssh sys1 ls -al" exits with no output).
>
> Interactive logins are unaffected.  Of course, "scp", etc., also don't
> work on the affected systems.  Other Solaris systems running a Solaris
> version other than 8 are don't seem to have the problem with
> non-interactive commands.
>
> From the debug log on an affected system, it appears to be a problem
> encountered in do_pam_session().  I searched some old messages and there
> was talk about some TTY stuff that appears to have been taken out around
> 3.6.1p2, but nothing that came right out and stated, "Yep, this is a
> problem we see on Solaris <version>".
>
> Has anyone else seen this?  Any ideas how to trouble-shoot and solve this
> problem?  Meanwhile, we'll keep digging...
>
> Thanks,
>
> 	Ed
>
> Ed Phillips <ed at udel.edu> University of Delaware (302) 831-6082
> Systems Programmer III, Network and Systems Services
>
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Connection from 128.175.2.36 port 47865
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Connection from 128.175.2.36 port 47865
> Sep 22 13:12:39 ldap1.udel.edu sshd[21118]: [ID 800047 local4.debug] debug1: Forked child 21223.
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: Client protocol version 2.0; client software version OpenSSH_3.7.1p1
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: match: OpenSSH_3.7.1p1 pat OpenSSH*
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: Enabling compatibility mode for protocol 2.0
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: Local version string SSH-1.99-OpenSSH_3.7.1p1
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: list_hostkey_types: ssh-rsa,ssh-dss
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: SSH2_MSG_KEXINIT sent
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: SSH2_MSG_KEXINIT received
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: kex: client->server aes128-cbc hmac-md5 none
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: kex: server->client aes128-cbc hmac-md5 none
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
> Sep 22 13:12:39 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
> Sep 22 13:12:40 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
> Sep 22 13:12:40 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: SSH2_MSG_NEWKEYS sent
> Sep 22 13:12:40 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: expecting SSH2_MSG_NEWKEYS
> Sep 22 13:12:40 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: SSH2_MSG_NEWKEYS received
> Sep 22 13:12:40 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: KEX done
> Sep 22 13:12:40 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: userauth-request for user ed service ssh-connection method none
> Sep 22 13:12:40 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: attempt 0 failures 0
> Sep 22 13:12:40 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: PAM: initializing for "ed"
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: PAM: setting PAM_RHOST to "polycut.nss.udel.edu"
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 859314 local4.debug] pam_set_item(4)
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: PAM: setting PAM_TTY to "ssh"
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 859314 local4.debug] pam_set_item(3)
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Failed none for ed from 128.175.2.36 port 47865 ssh2
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Failed none for ed from 128.175.2.36 port 47865 ssh2
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: userauth-request for user ed service ssh-connection method publickey
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: attempt 1 failures 1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: test whether pkalg/pkblob are acceptable
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: temporarily_use_uid: 16476/10 (e=0/1)
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: trying public key file /home/ldap1/usra/ed/.ssh/authorized_keys
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: restore_uid: 0/1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: temporarily_use_uid: 16476/10 (e=0/1)
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: trying public key file /home/ldap1/usra/ed/.ssh/authorized_keys2
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: matching key found: file /home/ldap1/usra/ed/.ssh/authorized_keys2, line 1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Found matching RSA key: fd:fe:6f:ce:e8:26:bb:2e:58:65:1e:8c:12:00:92:16
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Found matching RSA key: fd:fe:6f:ce:e8:26:bb:2e:58:65:1e:8c:12:00:92:16
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: restore_uid: 0/1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Postponed publickey for ed from 128.175.2.36 port 47865 ssh2
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Postponed publickey for ed from 128.175.2.36 port 47865 ssh2
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: userauth-request for user ed service ssh-connection method publickey
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: attempt 2 failures 1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: temporarily_use_uid: 16476/10 (e=0/1)
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: trying public key file /home/ldap1/usra/ed/.ssh/authorized_keys
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: restore_uid: 0/1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: temporarily_use_uid: 16476/10 (e=0/1)
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: trying public key file /home/ldap1/usra/ed/.ssh/authorized_keys2
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: matching key found: file /home/ldap1/usra/ed/.ssh/authorized_keys2, line 1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Found matching RSA key: fd:fe:6f:ce:e8:26:bb:2e:58:65:1e:8c:12:00:92:16
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Found matching RSA key: fd:fe:6f:ce:e8:26:bb:2e:58:65:1e:8c:12:00:92:16
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: restore_uid: 0/1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: ssh_rsa_verify: signature correct
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 997726 local4.debug] pam_acct_mgmt()
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 305314 local4.debug] load_modules: /usr/lib/security/pam_roles.so.1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 265225 local4.debug] load_function: successful load of pam_sm_acct_mgmt
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 305314 local4.debug] load_modules: /usr/lib/security/pam_projects.so.1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 265225 local4.debug] load_function: successful load of pam_sm_acct_mgmt
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 305314 local4.debug] load_modules: /usr/lib/security/pam_unix.so.1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 265225 local4.debug] load_function: successful load of pam_sm_acct_mgmt
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Accepted publickey for ed from 128.175.2.36 port 47865 ssh2
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Accepted publickey for ed from 128.175.2.36 port 47865 ssh2
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: Entering interactive session for SSH2.
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: server_init_dispatch_20
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: server_input_channel_open: ctype session rchan 0 win 131072 max 32768
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: input_session_request
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: channel 0: new [server-session]
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: session_new: init
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: session_new: session 0
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: session_open: channel 0
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: session_open: session 0: link with channel 0
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: server_input_channel_open: confirm session
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: server_input_channel_req: channel 0 request exec reply 0
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: session_by_channel: session 0 channel 0
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: session_input_channel_req: session 0 req exec
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 859314 local4.debug] pam_set_item(5)
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: PAM: establishing credentials
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 942022 local4.debug] pam_setcred()
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 305314 local4.debug] load_modules: /usr/lib/security/pam_unix.so.1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 265225 local4.debug] load_function: successful load of pam_sm_setcred
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 859314 local4.debug] pam_set_item(5)
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 750988 local4.debug] pam_open_session()
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 305314 local4.debug] load_modules: /usr/lib/security/pam_unix.so.1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 265225 local4.debug] load_function: successful load of pam_sm_open_session
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 770223 local4.debug] pam_open_session: error Can not make/remove entry for session
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 800047 local4.crit] fatal: PAM: pam_open_session(): Can not make/remove entry for session
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 800047 local4.crit] fatal: PAM: pam_open_session(): Can not make/remove entry for session
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 800047 local4.crit] fatal: PAM: pam_open_session(): Can not make/remove entry for session
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 800047 local4.crit] fatal: PAM: pam_open_session(): Can not make/remove entry for session
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 800047 local4.crit] fatal: PAM: pam_open_session(): Can not make/remove entry for session
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 800047 local4.crit] fatal: PAM: pam_open_session(): Can not make/remove entry for session
> Sep 22 13:12:41 ldap1.udel.edu sshd[21224]: [ID 800047 local4.crit] fatal: PAM: pam_open_session(): Can not make/remove entry for session
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: Received SIGCHLD.
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: session_by_pid: pid 21224
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: session_exit_message: session 0 channel 0 pid 21224
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: session_exit_message: release channel 0
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: session_close: session 0 pid 21224
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: channel 0: free: server-session, nchannels 1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Connection closed by 128.175.2.36
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Connection closed by 128.175.2.36
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Closing connection to 128.175.2.36
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.info] Closing connection to 128.175.2.36
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 800047 local4.debug] debug1: PAM: cleanup
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 859314 local4.debug] pam_set_item(5)
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 942022 local4.debug] pam_setcred()
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 305314 local4.debug] load_modules: /usr/lib/security/pam_unix.so.1
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 833576 local4.debug] pam_setcred: error Permission denied
> Sep 22 13:12:41 ldap1.udel.edu sshd[21223]: [ID 690057 local4.debug] pam_end(): status = Success
>

Ed Phillips <ed at udel.edu> University of Delaware (302) 831-6082
Systems Programmer III, Network and Systems Services