Bug 906852 - No shell after successful ssh authentication
Summary: No shell after successful ssh authentication
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: pam
Version: 18
Hardware: x86_64
OS: Linux
unspecified
unspecified
Target Milestone: ---
Assignee: Tomas Mraz
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-02-01 17:25 UTC by Gregor Hlawacek
Modified: 2013-07-25 00:49 UTC (History)
6 users (show)

Fixed In Version: pam-1.1.6-4.fc18
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-07-14 03:31:31 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Gregor Hlawacek 2013-02-01 17:25:47 UTC
Description of problem:
Can't login via ssh. doesn't work over the net as well as locally. Also fails when tryiung to send just a command via the -C option

Version-Release number of selected component (if applicable):
All openssh packages have version: 6.1p1 release: 4.fc18

How reproducible:
ssh localhost

Steps to Reproduce:
1.
2.
3.
  
Actual results:
Connection to localhost closed.

Expected results:
logged in

Additional info:

It seems that it doesn't get a shell or something like this. In the ssh and sshd session logs below I find at least on PAM and one SE-Linux error

PAM: pam_open_session(): Permission denied

ssh_selinux_copy_context: setcon failed with Permission denied

This is an upgraded box from f17 to f18

some help would be appreciated

[lawa@ssp-ws081 ~]$ ssh localhost -v
OpenSSH_6.1p1, OpenSSL 1.0.1c-fips 10 May 2012
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 50: Applying options for *
debug1: Connecting to localhost [127.0.0.1] port 22.
debug1: Connection established.
debug1: identity file /home/lawa/.ssh/id_rsa type -1
debug1: identity file /home/lawa/.ssh/id_rsa-cert type -1
debug1: identity file /home/lawa/.ssh/id_dsa type -1
debug1: identity file /home/lawa/.ssh/id_dsa-cert type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_6.1
debug1: match: OpenSSH_6.1 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.1
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-ctr hmac-md5 none
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Server host key: RSA f3:0b:38:df:c0:d0:c7:d9:1a:83:b3:31:13:1e:ad:ef
debug1: Host 'localhost' is known and matches the RSA host key.
debug1: Found key in /home/lawa/.ssh/known_hosts:11
debug1: ssh_rsa_verify: signature correct
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
debug1: Next authentication method: publickey
debug1: Offering RSA public key: lawa.utwente.nl
debug1: Authentications that can continue: publickey,gssapi-keyex,gssapi-with-mic,password
debug1: Trying private key: /home/lawa/.ssh/id_rsa
debug1: Trying private key: /home/lawa/.ssh/id_dsa
debug1: Next authentication method: password
lawa@localhost's password: 
debug1: Authentication succeeded (password).
Authenticated to localhost ([127.0.0.1]:22).
debug1: channel 0: new [client-session]
debug1: Requesting no-more-sessions
debug1: Entering interactive session.
debug1: Sending environment.
debug1: Sending env XMODIFIERS = @im=ibus
debug1: Sending env LANG = en_US.UTF-8
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: client_input_channel_req: channel 0 rtype eow reply 0
Last login: Fri Feb  1 18:20:34 2013 from ssp-ws081.tnw.utwente.nl
debug1: channel 0: free: client-session, nchannels 1
Connection to localhost closed.
Transferred: sent 2312, received 2208 bytes, in 0.1 seconds
Bytes per second: sent 18119.3, received 17304.2
debug1: Exit status 254

[root@ssp-ws081 ssh]# /usr/sbin/sshd -d
debug1: sshd version OpenSSH_6.1p1
debug1: read PEM private key done: type RSA
debug1: private host key: #0 type 1 RSA
debug1: read PEM private key done: type DSA
debug1: private host key: #1 type 2 DSA
debug1: rexec_argv[0]='/usr/sbin/sshd'
debug1: rexec_argv[1]='-d'
Set /proc/self/oom_score_adj from 0 to -1000
debug1: Bind to port 22 on 0.0.0.0.
Server listening on 0.0.0.0 port 22.
debug1: Bind to port 22 on ::.
Server listening on :: port 22.
debug1: Server will not fork when running in debugging mode.
debug1: rexec start in 5 out 5 newsock 5 pipe -1 sock 8
debug1: inetd sockets after dupping: 3, 3
Connection from 127.0.0.1 port 49594
debug1: Client protocol version 2.0; client software version OpenSSH_6.1
debug1: match: OpenSSH_6.1 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.1
debug1: permanently_set_uid: 74/74 [preauth]
debug1: list_hostkey_types: ssh-rsa,ssh-dss [preauth]
debug1: SSH2_MSG_KEXINIT sent [preauth]
debug1: SSH2_MSG_KEXINIT received [preauth]
debug1: kex: client->server aes128-ctr hmac-md5 none [preauth]
debug1: kex: server->client aes128-ctr hmac-md5 none [preauth]
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received [preauth]
debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT [preauth]
debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug1: KEX done [preauth]
debug1: userauth-request for user lawa service ssh-connection method none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug1: PAM: initializing for "lawa"
debug1: PAM: setting PAM_RHOST to "ssp-ws081.tnw.utwente.nl"
debug1: PAM: setting PAM_TTY to "ssh"
debug1: userauth-request for user lawa service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug1: test whether pkalg/pkblob are acceptable [preauth]
debug1: temporarily_use_uid: 500/500 (e=0/0)
debug1: trying public key file /home/lawa/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 500/500 (e=0/0)
debug1: trying public key file /home/lawa/.ssh/authorized_keys2
debug1: Could not open authorized keys '/home/lawa/.ssh/authorized_keys2': No such file or directory
debug1: restore_uid: 0/0
Failed publickey for lawa from 127.0.0.1 port 49594 ssh2
debug1: userauth-request for user lawa service ssh-connection method password [preauth]
debug1: attempt 2 failures 1 [preauth]
debug1: PAM: password authentication accepted for lawa
debug1: do_pam_account: called
Accepted password for lawa from 127.0.0.1 port 49594 ssh2
debug1: monitor_child_preauth: lawa has been authenticated by privileged process
debug1: monitor_read_log: child log fd closed
debug1: temporarily_use_uid: 500/500 (e=0/0)
debug1: ssh_gssapi_storecreds: Not a GSSAPI mechanism
debug1: restore_uid: 0/0
debug1: SELinux support enabled
debug1: PAM: establishing credentials
PAM: pam_open_session(): Permission denied
User child is on pid 3205
debug1: PAM: establishing credentials
debug1: permanently_set_uid: 500/500
ssh_selinux_copy_context: setcon failed with Permission denied
debug1: Entering interactive session for SSH2.
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
debug1: input_session_request
debug1: channel 0: new [server-session]
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: server_input_global_request: rtype no-more-sessions want_reply 0
debug1: server_input_channel_req: channel 0 request pty-req reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req pty-req
debug1: Allocating pty.
debug1: session_new: session 0
debug1: session_pty_req: session 0 alloc /dev/pts/3
debug1: server_input_channel_req: channel 0 request env reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req env
debug1: server_input_channel_req: channel 0 request env reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req env
debug1: server_input_channel_req: channel 0 request shell reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req shell
debug1: Setting controlling tty using TIOCSCTTY.
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 3206
debug1: session_exit_message: session 0 channel 0 pid 3206
debug1: session_exit_message: release channel 0
debug1: session_by_tty: session 0 tty /dev/pts/3
debug1: session_pty_cleanup: session 0 release /dev/pts/3
Received disconnect from 127.0.0.1: 11: disconnected by user
debug1: do_cleanup
debug1: do_cleanup
debug1: PAM: cleanup
debug1: PAM: deleting credentials

Comment 1 Tomas Mraz 2013-02-01 17:57:46 UTC
Do you see anything related in the 'ausearch -m AVC' output?

What messages from pam modules do you see in /var/log/secure?

Comment 2 Gregor Hlawacek 2013-02-02 08:53:51 UTC
I will supply the info but not before Monday. The described problem prevents me from logging into the machine on the weekend :(

Comment 3 Gregor Hlawacek 2013-02-04 07:43:10 UTC
var/log/messages

Feb  4 08:37:25 ssp-ws081 systemd-logind[648]: New session 106 of user lawa.
Feb  4 08:37:26 ssp-ws081 kernel: [225920.710166] type=1400 audit(1359963446.692:14): avc:  denied  { dyntransition } for  pid=10793 comm="sshd" scontext=unconfined_u:system_r:unconfined_t:s0-s0:c0.c1023 tcontext=unconfined_u:unconfined_r:unconfined_t:s0 tclass=process
Feb  4 08:37:26 ssp-ws081 systemd-logind[648]: Removed session 106.

var/log/secure

Feb  4 08:37:25 ssp-ws081 sshd[10784]: pam_unix(sshd:session): session opened for user lawa by (uid=0)

ausearch -m AVC

/var/log/audit/audit.log permissions should be 0600 or 0640
NOTE - using built-in logs: /var/log/audit/audit.log
<no matches>

However, I will reinstall from scratch there are too many other unresolved issues after upgrading from 17 to 18. I'll report back if it still occurs in a vanilla f18

Comment 4 Gregor Hlawacek 2013-02-04 10:21:45 UTC
Eventually I postpone trashing my system for a lillte while. 

I found out today that I can not login via the console too. I can login into X and open a terminal there and login via su to become root.

However, if I press Ctrl-alt-F2 to get to the console I can not login neither as root nor as user. messages and secure just contain messages from logind that the login has been denied.

Could this be related to the above problem?

Gregor

Comment 5 Petr Lautrbach 2013-02-04 19:33:49 UTC
Please try to switch to SELinux permissive mode with 'setenforce 0' or with enforcing=0 as kernel parameter. Does it help? Also could you try to relabel your filesystem using '/usr/sbin/fixfiles onboot' and reboot?

Comment 6 Gregor Hlawacek 2013-02-04 20:08:11 UTC
Hi Petr,

I am afraid that I will go for my other solution than. Relabeling (and later on relabeling again) ... I think I install F18 from scratch than. This is on my work computer, svn server, ... I need that thing working thanks for the input.

Gregor

Comment 7 Tomasz Ostrowski 2013-02-06 20:35:06 UTC
I think the same bug manifested on my system today. I can't login now, but I could just today at about 10:00 CET.

This is cleanly installed Fedora 18, not an upgrade, so reinstalling from scratch won't necessarily help - so don't do this, Gregor.

As it is probably a selinux problem running "setenforce 0" after reboot should help at least for now. I'll try to narrow it down tomorrow.

Comment 8 Gregor Hlawacek 2013-02-07 07:29:53 UTC
thanks for the warning but too late :-)

I did not have this issue on my laptop which had a fresh install, and so far I also do not see it on the freshly installed desktop machine.

Comment 9 Tomasz Ostrowski 2013-02-07 16:11:25 UTC
I've tracked a cause for this bug in my system's case. The problem wasn't SELinux related though. It was a corrupted /var/log/btmp file.

Yesterday I've logged in to my computer using a password when prompted for login. It was saved in /var/log/secure and /var/log/btmp. So I've stopped rsyslogd and replaced my password in both files with a bunch of "_". But I think I've made a mistake and have written one less "_" than a number of characters in my password.


So:


Version-Release number of selected component (if applicable):
util-linux-2.22.1-2.4.fc18.x86_64


Steps to Reproduce:
1. echo -n > /var/log/btmp
2. ssh foobar@localhost
3. [Ctrl-C at password prompt]
4. sed -i s/foobar/fooba/ /var/log/btmp
5. ssh root@localhost
6. [Enter root password at password prompt]


Actual results:
Last login: Thu Feb  7 16:09:00 2013
Connection to localhost closed.


Expected results:
Last login: Thu Feb  7 16:09:00 2013
root@localhost# 


Additional info:

It's probably util-linux bug, no openssh.

It's pretty serious, as it can prevent root login at all both from ssh and from console when one, unimportant file is slightly corrupted. There is even not a slightest indicator what's a problem - if I haven't remembered that I've messed with btmp, I'd have a system that I could not login to and no clue what did go wrong. I'd have to reinstall this system.

Comment 10 Miroslav Vadkerti 2013-02-12 13:27:31 UTC
I am able to reproduce the issue with these packages:
openssh-6.1p1-4.fc18.x86_64
pam-1.1.6-3.fc18.1.x86_64
util-linux-2.22.2-4.fc18.x86_64

The issue disappears if I comment out postlogin in /etc/pam.d/sshd.

After discussion with Petr this seems as PAM issue. Reassigning.

Comment 11 Tomas Mraz 2013-02-18 15:32:47 UTC
Miroslav, what do you have in /etc/pam.d/postlogin?
Do you see anything in /var/log/secure?

Comment 12 Fedora Update System 2013-07-12 08:23:27 UTC
pam-1.1.6-4.fc18 has been submitted as an update for Fedora 18.
https://admin.fedoraproject.org/updates/pam-1.1.6-4.fc18

Comment 13 Fedora Update System 2013-07-12 08:23:53 UTC
pam-1.1.6-12.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/pam-1.1.6-12.fc19

Comment 14 Fedora Update System 2013-07-13 01:51:23 UTC
Package pam-1.1.6-12.fc19:
* should fix your issue,
* was pushed to the Fedora 19 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing pam-1.1.6-12.fc19'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-12889/pam-1.1.6-12.fc19
then log in and leave karma (feedback).

Comment 15 Fedora Update System 2013-07-14 03:31:31 UTC
pam-1.1.6-12.fc19 has been pushed to the Fedora 19 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 16 Fedora Update System 2013-07-25 00:49:08 UTC
pam-1.1.6-4.fc18 has been pushed to the Fedora 18 stable repository.  If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.