Bug 711156 - sshd reports a fatal read error on every new connection
sshd reports a fatal read error on every new connection
Status: CLOSED WONTFIX
Product: Fedora
Classification: Fedora
Component: openssh (Show other bugs)
15
i686 Linux
unspecified Severity low
: ---
: ---
Assigned To: Petr Lautrbach
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2011-06-06 13:06 EDT by Andreas Girgensohn
Modified: 2012-08-08 11:12 EDT (History)
24 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-08-07 14:04:22 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
scriptlog from "ssh -vvv -x" to a F15 box (2.61 KB, application/x-gzip)
2011-08-06 20:40 EDT, Christian Kujau
no flags Details
strace -tt -f -o /var/tmp/ssh-strace.log -p [sshd PID] (222.76 KB, application/x-gzip)
2011-08-06 20:41 EDT, Christian Kujau
no flags Details

  None (edit)
Description Andreas Girgensohn 2011-06-06 13:06:41 EDT
Description of problem:

sshd produces this log message in /var/log/secure for every new ssh connection.

sshd[NNN+1]: fatal: mm_request_receive: read: Connection reset by peer

The process ID is always one higher than that of the preceding log message logging the accepted publickey or password.  Nothing else seems to be wrong but the messages clutter the log and the logwatch emails.

Version-Release number of selected component (if applicable):
openssh-server-5.6p1-31.fc15.1.i686

How reproducible:
Always

Steps to Reproduce:
1. Connect to the ssh server using publickey or password authentication
2. Check /var/log/secure on the server
  
Actual results:
Log message: sshd[NNN+1]: fatal: mm_request_receive: read: Connection reset by peer

Expected results:
Not that log message.

Additional info:

Below are some samples of such log messages from /var/log/secure.  Initially, the time zone for the offending message (but not the messages around it) was UTC instead of PDT.  However, the suggestion in Bug 699428 of linking /etc/localtime fixed the time zone problem.

Jun  6 03:15:01 fedora sshd[25001]: Accepted publickey for root from 192.168.21.229 port 48304 ssh2
Jun  6 03:15:01 fedora sshd[25002]: fatal: mm_request_receive: read: Connection reset by peer
Jun  6 03:15:01 fedora sshd[25001]: pam_systemd(sshd:session): Moving new user session for root into control group /user/root/108.
Jun  6 03:15:01 fedora sshd[25001]: pam_unix(sshd:session): session opened for user root by (uid=0)
Jun  6 03:15:01 fedora sshd[25001]: Received disconnect from 192.168.21.229: 11: disconnected by user
--
Jun  6 06:15:05 fedora sshd[25984]: Accepted publickey for root from 192.168.21.229 port 60485 ssh2
Jun  6 06:15:05 fedora sshd[25985]: fatal: mm_request_receive: read: Connection reset by peer
Jun  6 06:15:05 fedora sshd[25984]: pam_systemd(sshd:session): Moving new user session for root into control group /user/root/114.
Jun  6 06:15:05 fedora sshd[25984]: pam_unix(sshd:session): session opened for user root by (uid=0)
Jun  6 06:15:06 fedora sshd[25984]: Received disconnect from 192.168.21.229: 11: disconnected by user
--
Jun  6 09:15:04 fedora sshd[26498]: Accepted publickey for root from 192.168.21.229 port 39372 ssh2
Jun  6 09:15:04 fedora sshd[26499]: fatal: mm_request_receive: read: Connection reset by peer
Jun  6 09:15:04 fedora sshd[26498]: pam_systemd(sshd:session): Moving new user session for root into control group /user/root/119.
Jun  6 09:15:04 fedora sshd[26498]: pam_unix(sshd:session): session opened for user root by (uid=0)
Jun  6 09:15:04 fedora sshd[26498]: Received disconnect from 192.168.21.229: 11: disconnected by user
--
Jun  6 09:30:19 fedora sshd[26551]: Accepted publickey for root from 192.168.21.229 port 54833 ssh2
Jun  6 09:30:19 fedora sshd[26552]: fatal: mm_request_receive: read: Connection reset by peer
Jun  6 09:30:19 fedora sshd[26551]: pam_systemd(sshd:session): Moving new user session for root into control group /user/root/120.
Jun  6 09:30:19 fedora sshd[26551]: pam_unix(sshd:session): session opened for user root by (uid=0)
Jun  6 09:30:20 fedora sshd[26551]: Received disconnect from 192.168.21.229: 11: disconnected by user
--
Jun  6 09:46:18 fedora sshd[26620]: Accepted publickey for andreasg from 192.168.21.229 port 53715 ssh2
Jun  6 09:46:18 fedora sshd[26621]: fatal: mm_request_receive: read: Connection reset by peer
Jun  6 09:46:18 fedora sshd[26620]: pam_systemd(sshd:session): Moving new user session for andreasg into control group /user/andreasg/121.
Jun  6 09:46:18 fedora sshd[26620]: pam_unix(sshd:session): session opened for user andreasg by (uid=0)
Jun  6 09:46:26 fedora sudo: andreasg : TTY=pts/0 ; PWD=/home/andreasg ; USER=root ; COMMAND=/bin/tcsh
--
Jun  6 09:52:36 fedora sshd[26684]: Accepted password for root from 192.168.21.229 port 32976 ssh2
Jun  6 09:52:36 fedora sshd[26685]: fatal: mm_request_receive: read: Connection reset by peer
Jun  6 09:52:36 fedora sshd[26684]: pam_systemd(sshd:session): Moving new user session for root into control group /user/root/122.
Jun  6 09:52:36 fedora sshd[26684]: pam_unix(sshd:session): session opened for user root by (uid=0)
Comment 1 Jan F. Chadima 2011-06-09 07:22:39 EDT
verified, I'll investigate it later.
Comment 2 Bojan Smojver 2011-07-01 03:58:07 EDT
Hmm just got this as well and got kicked out:
--------------
Jul  1 17:53:44 host sshd[29686]: pam_systemd(sshd:session): Failed to create runtime directory: No such file or directory
Jul  1 17:53:44 host sshd[29686]: pam_unix(sshd:session): session opened for user root by (uid=0)
Jul  1 17:53:45 host sshd[29686]: Received disconnect from <IP>: 11: disconnected by user
Jul  1 17:53:45 host sshd[29686]: pam_systemd(sshd:session): Failed to determine whether a session remains: No such file or directory
--------------

Next attempt worked though.
Comment 3 Håkon Løvdal 2011-07-25 23:00:29 EDT
I also experience the same problem with mm_request_receive messages (including the localtime issue, solved as noted in https://bugzilla.redhat.com/show_bug.cgi?id=674633). Andreas notes that "Nothing else seems to be wrong", however for me xauth (when logging in with "ssh -Y") fails, and I assume that is related to this.

I started asking a question at http://superuser.com/questions/315050/xauth-x11-ssh-forwarding-problem, so I do not repeat that information here.

Debugging sshd like suggested in https://bugzilla.redhat.com/show_bug.cgi?id=674633 gives the following screen output before error

Accepted publickey for hlovdal from x.x.x.x port 41278 ssh2
debug3: mm_do_pam_account returning 1
debug1: monitor_child_preauth: hlovdal has been authenticated by privileged process
debug3: mm_get_keystate: Waiting for new keys
debug3: mm_send_keystate: Sending new keys: 0x...........................
debug3: mm_request_receive_expect entering: type 25
debug3: mm_newkeys_to_blob: converting 0x..........
debug3: mm_request_receive entering
debug3: mm_newkeys_to_blob: converting 0x............
debug3: mm_send_keystate: New keys have been sent
debug3: mm_send_keystate: Sending compression state
debug3: mm_request_send entering: type 25
debug3: mm_send_keystate: Finished sending state
debug3: mm_newkeys_from_blob: 0x.........(122)
debug3: mm_request_send entering: type 78
debug2: mac_setup: found hmac-md5
debug3: mm_request_receive_expect entering: type 79
debug3: mm_request_receive entering
debug3: mm_get_keystate: Waiting for second key
debug3: mm_newkeys_from_blob: 0x..........(122)
debug2: mac_setup: found hmac-md5
debug3: mm_get_keystate: Getting compression state
debug3: mm_get_keystate: Getting Network I/O buffers
debug3: mm_share_sync: Share sync
mm_request_receive: read: Connection reset by peer


and from strace of the process that prints mm_request_receive:

1311647064.113653 write(2, "debug3: mm_request_send entering: type 78\r\n", 43) = 43
1311647064.113772 write(4, "\0\0\0\5N", 5) = 5
1311647064.113883 write(4, "\0\0\0\2", 4) = 4
1311647064.114140 write(2, "debug3: mm_request_receive_expect entering: type 79\r\n", 53) = 53
1311647064.114271 write(2, "debug3: mm_request_receive entering\r\n", 37) = 37
1311647064.114394 read(4, 0x7fff55d99e00, 4) = -1 ECONNRESET (Connection reset by peer)
1311647064.115344 write(2, "mm_request_receive: read: Connection reset by peer\r\n", 52) = 52
1311647064.115507 write(2, "debug1: do_cleanup\r\n", 20) = 20
1311647064.115672 write(2, "debug3: PAM: sshpam_thread_cleanup entering\r\n", 45) = 45
1311647064.115939 exit_group(255)       = ?


And debug output on the client side during login:

Last login: ...
debug3: mm_request_send entering: type 80
debug3: mm_request_receive_expect entering: type 81
debug3: mm_request_receive entering
debug3: Copy environment: SELINUX_ROLE_REQUESTED=
debug3: Copy environment: SELINUX_LEVEL_REQUESTED=
debug3: Copy environment: SELINUX_USE_CURRENT_RANGE=
debug3: Copy environment: XDG_RUNTIME_DIR=/run/user/hlovdal
debug3: Copy environment: XDG_SESSION_ID=23
Environment:
  ...
debug3: channel 0: close_fds r -1 w -1 e -1
debug3: channel 1: close_fds r 8 w 8 e -1
debug3: channel 2: close_fds r 9 w 9 e -1
Running /usr/bin/xauth remove unix:10.0
/usr/bin/xauth add unix:10.0 MIT-MAGIC-COOKIE-1 ................................
/usr/bin/xauth:  error in locking authority file /home/hlovdal/.Xauthority
Comment 4 Håkon Løvdal 2011-07-25 23:04:51 EDT
This is by the way with openssh-server-5.6p1-33.fc15.1.x86_64 on the server and openssh-5.6p1-33.fc15.1.i686 on the client.
Comment 5 Andreas Girgensohn 2011-07-26 14:01:06 EDT
According to this discussion, the .Xauthority lock files stick around if xauth crashes, preventing future xauth invocations.

http://lists.freebsd.org/pipermail/freebsd-x11/2006-January/002469.html

This may be an xauth problem rather than an ssh problem.
Comment 6 Christian Kujau 2011-08-06 20:38:45 EDT
This mm_request_receive message even appears when connecting with X11 connection forwarding disabled (-x on the client). The strace from the sshd looks rather scary, for just one successful login there are 8258 -EBADF messages:

$ cat ssh-strace.txt | grep ...
 118 -1 ESPIPE (Illegal seek)
 125 -1 EINVAL (Invalid argument)
 136 -1 ENOENT (No such file or directory)
8258 -1 EBADF (Bad file descriptor)

On a completely different system, there are about 80 -EBADF messages. Maybe someone wants to take a look at those strace outputs?

Funny sidenote: strace also shows:

  open("/root/.ssh/authorized_keys", O_RDONLY|O_NONBLOCK|O_LARGEFILE) = -1 EACCES

and thus public key authentication is not possible on Fedora too, at least not at the moment. But that's something for another bugreport :)
Comment 7 Christian Kujau 2011-08-06 20:40:29 EDT
Created attachment 517020 [details]
scriptlog from "ssh -vvv -x" to a F15 box
Comment 8 Christian Kujau 2011-08-06 20:41:28 EDT
Created attachment 517021 [details]
strace -tt -f -o /var/tmp/ssh-strace.log -p [sshd PID]
Comment 9 Edgar Hoch 2011-08-31 11:35:53 EDT
We also notice a delay when connecting to a fedora 15 host using ssh.

I found that every new ssh connection creates lines like the following in /var/log/secure. The second line is the interesting one:

The time is in UTC instead of localtime (we have UTC+2 currently because of daylight saving time), and there is an error message like in the comments above.
This error messages and the wrong time log appears both on standalone hosts and on networked hosts with nfs home dirs and nis network service.

Aug 31 16:52:00 myhost sshd[11712]: Accepted publickey for myuser from 192.0.2.100 port 57761 ssh2
Aug 31 14:52:00 myhost sshd[11713]: fatal: mm_request_receive: read: Connection reset by peer
Aug 31 16:52:00 myhost sshd[11712]: pam_unix(sshd:session): session opened for user myuser by (uid=0)

I also tried with no X11 forwarding like this
ssh -x -o ClearAllForwardings=yes -o ForwardX11=no -o ForwardX11Trusted=no -o ForwardAgent=no 
but this does not change the messages.
Comment 10 Bojan Smojver 2011-09-11 20:08:09 EDT
(In reply to comment #1)
> verified, I'll investigate it later.

Can we get a build to test or something? It's now been over 3 months since the issue was first reported and a few OpenSSH releases happened in the meantime...
Comment 11 Bill McGonigle 2011-09-16 00:00:16 EDT
I get this error when trying to use remmina to setup an NX session.  Trick is, I can't figure out what remmina is doing to try to setup SSH.  My regular ssh sessions work great.  If I knew what the difference was, perhaps that would be useful here.  This is the log:

[SSH] SSH server banner: SSH-2.0-OpenSSH_5.6
[SSH] Analyzing banner: SSH-2.0-OpenSSH_5.6
[SSH] We are talking to an OpenSSH client version: 5.6 (50600)
[SSH] SSH_MSG_NEWKEYS sent
[SSH] Got SSH_MSG_NEWKEYS
[SSH] Trying to open /home/me/.ssh/id_rsa
[SSH] Trying to read /home/me/.ssh/id_rsa, passphase=true, authcb=false
[SSH] Creating a channel 43 with 64000 window and 32000 max packet
[SSH] Sent a SSH_MSG_CHANNEL_OPEN type direct-tcpip for channel 43
[SSH] placing 21 bytes into channel buffer (stderr=0)
[SSH] channel_write wrote 22 bytes
[SSH] placing 784 bytes into channel buffer (stderr=0)
[SSH] channel_write wrote 296 bytes
[SSH] placing 720 bytes into channel buffer (stderr=0)
[SSH] channel_write wrote 16 bytes
[SSH] channel_write wrote 52 bytes
[SSH] placing 52 bytes into channel buffer (stderr=0)
[SSH] channel_write wrote 580 bytes
[SSH] placing 84 bytes into channel buffer (stderr=0)

If I do what remmina ought to be doing by hand, it logs in no problem.
Comment 12 Hal Duston 2011-10-06 16:47:01 EDT
Some addition research done by me, (hald@kc.rr.com):

PARENT: debug3: mm_request_receive_expect entering: type 25
 CHILD: debug3: mm_newkeys_to_blob: converting 0x7f2cfff65df0
 CHILD: debug3: mm_request_receive entering
 CHILD: debug3: mm_newkeys_to_blob: converting 0x7f2cfff5a770
 CHILD: debug3: mm_send_keystate: New keys have been sent
 CHILD: debug3: mm_send_keystate: Sending compression state
 CHILD: debug3: mm_request_send entering: type 25
 CHILD: debug3: mm_send_keystate: Finished sending state
PARENT: debug3: mm_newkeys_from_blob: 0x7f2cfff753b0(122)
 CHILD: debug3: mm_request_send entering: type 78
PARENT: debug2: mac_setup: found hmac-md5
PARENT: debug3: mm_get_keystate: Waiting for second key
PARENT: debug3: mm_newkeys_from_blob: 0x7f2cfff753b0(122)
 CHILD: debug3: mm_request_receive_expect entering: type 79
PARENT: debug2: mac_setup: found hmac-md5
PARENT: debug3: mm_request_receive entering
 CHILD: debug3: mm_get_keystate: Getting compression state
 CHILD: debug3: mm_get_keystate: Getting Network I/O buffers
== At this point the PARENT closes the socket, so CHILD socket is forcibly closed. ==
 CHILD: mm_request_receive: read: Connection reset by peer
PARENT: debug3: mm_share_sync: Share sync
 CHILD: debug1: do_cleanup
 CHILD: debug3: PAM: sshpam_thread_cleanup entering
...

 CHILD code in monitor_wrap.c:mm_audit_session_key_free_body()
                  ....
        mm_request_send(pmonitor->m_recvfd, MONITOR_REQ_AUDIT_SESSION_KEY_FREE, &m);
        mm_request_receive_expect(pmonitor->m_recvfd, MONITOR_ANS_AUDIT_SESSION_KEY_FREE, &m);
                  ....
 CHILD code in sshd.c:main()
                  ....
        /*
         * If we use privilege separation, the unprivileged child transfers
         * the current keystate and exits
         */
        if (use_privsep) {
                mm_send_keystate(pmonitor);
                packet_destroy_all();
                audit_session_key_free(2);
                exit(0);
        }
                  ....

PARENT code in sshd.c:privsep_preauth()
                   ....
                monitor_child_preauth(authctxt, pmonitor);
                close(pmonitor->m_sendfd);
                   ....

PARENT code in monitor.c:monitor_child_preauth()
                  ....
        debug("%s: %s has been authenticated by privileged process",
            __func__, authctxt->user);

        mm_get_keystate(pmonitor);
}

The above PARENT code receives the CHILD's mm_send_keystate socket data, but never receives with the CHILD's audit_session_key_free socket data before closing the socket.
Comment 13 Hal Duston 2011-10-06 17:06:57 EDT
Also, FYI, appears (via code inspection by me) to be fixed in upstream as of openssh-5.7p1.
Comment 14 Bill McGonigle 2011-10-11 09:55:24 EDT
Hal, did you happen to narrow down the patch?  I took a look in their CVSWeb, but seem to have missed it.
Comment 15 Hal Duston 2011-10-11 10:58:13 EDT
Bill, Belay my last, I didn't conduct a proper dig.  The error is introduced by a Fedora patch to the 5.6p1 upstream.

I've now dug deeper into it, and found that the CHILD calling audit_session_key_free(2) from main() was introduced in 5.6p1-25 (openssh-5.6p1-audit5.patch).

The newly introduced code does an additional send and receive from the CHILD to the PARENT during PRIVSEP setup finalization. The PARENT never receives or acknowledges it, but closes the socket while the data is still pending thereby generating the "Connection reset by peer" error in the CHILD.
Comment 16 Bill McGonigle 2011-10-13 13:02:03 EDT
Thanks, Hal.  Jan should be able to provide insight here.
Comment 17 Fedora Admin XMLRPC Client 2011-11-30 07:25:52 EST
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.
Comment 18 Fedora End Of Life 2012-08-07 14:04:25 EDT
This message is a notice that Fedora 15 is now at end of life. Fedora
has stopped maintaining and issuing updates for Fedora 15. It is
Fedora's policy to close all bug reports from releases that are no
longer maintained. At this time, all open bugs with a Fedora 'version'
of '15' have been closed as WONTFIX.

(Please note: Our normal process is to give advanced warning of this
occurring, but we forgot to do that. A thousand apologies.)

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, feel free to reopen
this bug and simply change the 'version' to a later Fedora version.

Bug Reporter: Thank you for reporting this issue and we are sorry that
we were unable to fix it before Fedora 15 reached end of life. If you
would still like to see this bug fixed and are able to reproduce it
against a later version of Fedora, you are encouraged to click on
"Clone This Bug" (top right of this page) and open it against that
version of Fedora.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

The process we are following is described here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 19 Edward Z. Yang 2012-08-08 11:12:22 EDT
For the record, this bug is confirmed fixed in at least Fedora 17.

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