Bug 699428 - slow connection to f15 beta sshd
slow connection to f15 beta sshd
Status: CLOSED NOTABUG
Product: Fedora
Classification: Fedora
Component: openssh (Show other bugs)
15
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: Jan F. Chadima
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2011-04-25 11:38 EDT by Carl Byington
Modified: 2011-04-28 12:15 EDT (History)
4 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2011-04-28 12:15:29 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)

  None (edit)
Description Carl Byington 2011-04-25 11:38:39 EDT
Description of problem:
Connecting from centos5 openssh-clients-4.3p2-72.el5_6.3 to f15 openssh-server-5.6p1-30.fc15.x86_64, the initial prompt is slow to appear. This does not seem to be the common 'no reverse dns for client machine' problem.

Version-Release number of selected component (if applicable):
openssh-server-5.6p1-30.fc15.x86_64

How reproducible:
always

Steps to Reproduce:
1. ssh -v media2
2.
3.
  
Actual results:
multi second delays after two lines in the debug log:
debug1: read PEM private key done: type RSA
debug1: Sending env LANG = en_US.UTF-8

Expected results:
no delays.

Additional info:
Two machines (centos5 and media2(f15)), both with proper reverse dns names for their ipv4 addresses, connecting over ipv4. 

From centos5, ssh -v media2 has two multi-second delays as above. 
From media2, ssh -v centos5 has no such delays.

In media2:/var/log/secure we have:
Apr 25 08:28:57 media2 sshd[7812]: Accepted publickey for root from 192.168.3.2 port 57646 ssh2
Apr 25 15:28:57 media2 sshd[7813]: fatal: mm_request_receive: read: Connection reset by peer
Apr 25 08:29:02 media2 sshd[7812]: pam_systemd(sshd:session): Moving new user session for root into control group /user/root/367.
Apr 25 08:29:02 media2 sshd[7812]: pam_unix(sshd:session): session opened for user root by (uid=0)

It looks like some sshd process is running in UTC, where everything else is in PDT.
Comment 1 Tomas Mraz 2011-04-27 06:40:33 EDT
(In reply to comment #0)
> 
> In media2:/var/log/secure we have:
> Apr 25 08:28:57 media2 sshd[7812]: Accepted publickey for root from 192.168.3.2
> port 57646 ssh2
> Apr 25 15:28:57 media2 sshd[7813]: fatal: mm_request_receive: read: Connection
> reset by peer
> Apr 25 08:29:02 media2 sshd[7812]: pam_systemd(sshd:session): Moving new user
> session for root into control group /user/root/367.
> Apr 25 08:29:02 media2 sshd[7812]: pam_unix(sshd:session): session opened for
> user root by (uid=0)
> 
> It looks like some sshd process is running in UTC, where everything else is in
> PDT.

The UTC time in the syslog is a regression of an old bug - the /etc/localtime should be bind mounted into the unpriviledged child sshd chroot.

But does the fatal message appear on all connection attempts to the F15 sshd?
Comment 2 Jan F. Chadima 2011-04-27 06:49:35 EDT
please create /var/empty/sshd/etc; and make hardlink /etc/localtime into that
new dir (or copy it if it is different fs). This probably repair the timezones,
but probably not delays.
provide the same log if possible, but running sshd thru strace -fff -o ....
-ttt
(maximum f and maximum t)
Thx
Comment 3 Carl Byington 2011-04-27 13:35:29 EDT
mkdir /var/empty/sshd/etc
cd /var/empty/sshd/etc
ln /etc/localtime localtime
kill -HUP 5539 #restart sshd

Apr 27 10:27:38 media2 sshd[31469]: Accepted publickey for root from 192.168.3.2 port 58298 ssh2
Apr 27 10:27:38 media2 sshd[31470]: fatal: mm_request_receive: read: Connection reset by peer
Apr 27 10:27:43 media2 sshd[31469]: pam_systemd(sshd:session): Moving new user session for root into control group /user/root/762.
Apr 27 10:27:43 media2 sshd[31469]: pam_unix(sshd:session): session opened for user root by (uid=0)

Yes, the fatal: mm_request... appears on every ssh connection from centos5->media2.

What is the cleanest way to run sshd under strace on media2? Modify /etc/rc.d/init.d/sshd and 'service sshd restart', or something else? I only have remote ssh access to media2 - the machine is physically hours away (but close to centos5 for which I also only have ssh access).
Comment 4 Jan F. Chadima 2011-04-27 13:39:25 EDT
service sshd stop
strace -ff -o my_trace -ttt /usr/sbin/sshd

You may add -d -d -d   as an argument to the end for getting extra debug
Comment 5 Carl Byington 2011-04-27 14:28:27 EDT
strace -fff -o my_trace -ttt /usr/sbin/sshd

Apr 27 11:13:42 media2 sshd[32258]: Server listening on 0.0.0.0 port 22.
Apr 27 11:13:42 media2 sshd[32258]: Server listening on :: port 22.
Apr 27 11:14:41 media2 sshd[32270]: Accepted publickey for root from 192.168.3.2 port 56576 ssh2
Apr 27 11:14:41 media2 sshd[32271]: fatal: mm_request_receive: read: Connection reset by peer
Apr 27 11:14:46 media2 sshd[32270]: pam_systemd(sshd:session): Moving new user session for root into control group /user/root/771.
Apr 27 11:14:46 media2 sshd[32270]: pam_unix(sshd:session): session opened for user root by (uid=0)

trace files in http://www.five-ten-sg.com/699428.tar.gz
Comment 6 Tomas Mraz 2011-04-27 17:26:40 EDT
Note that the strace files probably contain parts of the media2 server private host keys if you did not explicitly sanitized them - I did not look at them.
Comment 7 Jan F. Chadima 2011-04-28 00:58:09 EDT
you may delete the traces from the internet. thans
Comment 8 Jan F. Chadima 2011-04-28 01:07:01 EDT
I've found there DNS timeouts cca 5 sec longs. Note that rhel5's openssh and f15's openssh handles DNS differently.
Comment 9 Carl Byington 2011-04-28 10:18:10 EDT
After looking at tcpdump for dns packets on media2, and the intermediate routers between media2 and the dns server, something is causing some (but not all) of the AAAA queries to be dropped before they arrive at the dns server, leading to 5 second delays before the dns resolver on media2 retries the query. Clearly not a problem with sshd on media2.
Comment 10 Jan F. Chadima 2011-04-28 12:15:29 EDT
thx, closing as notabug

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