Problem with non-interactive shells on Sol8 with 3.7.1p1

[Ed Phillips]

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