Ed Phillips
2003-Sep-22 17:29 UTC
Problem with non-interactive shells on Sol8 with 3.7.1p1
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 problemencountered 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
2003-Sep-22 17:36 UTC
Problem with non-interactive shells on Sol8 with 3.7.1p1
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