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)
verified, I'll investigate it later.
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.
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
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.
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.
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 :)
Created attachment 517020 [details] scriptlog from "ssh -vvv -x" to a F15 box
Created attachment 517021 [details] strace -tt -f -o /var/tmp/ssh-strace.log -p [sshd PID]
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.
(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...
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.
Some addition research done by me, (hald.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.
Also, FYI, appears (via code inspection by me) to be fixed in upstream as of openssh-5.7p1.
Hal, did you happen to narrow down the patch? I took a look in their CVSWeb, but seem to have missed it.
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.
Thanks, Hal. Jan should be able to provide insight here.
This package has changed ownership in the Fedora Package Database. Reassigning to the new owner of this component.
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
For the record, this bug is confirmed fixed in at least Fedora 17.