[Bug 1667] sshd slow connect with 'UseDNS yes'

[bugzilla-daemon at bugzilla.mindrot.org]

https://bugzilla.mindrot.org/show_bug.cgi?id=1667

--- Comment #2 from Brian <brian.p.stamper at nasa.gov> 2009-10-28 03:12:23 EST ---
Created an attachment (id=1711)
 --> (https://bugzilla.mindrot.org/attachment.cgi?id=1711)
output of sshd -ddde

Attached as requested.  It's not one spot in the log where it pauses. 
I put numbers in roughly once a second at each step the debug output
hung.  So there are roughly 5 spots it hangs for 3-4 seconds.

It's probably also worth noting that there are delays cleaning up the
session on the server side too.  This is what happens when I
disconnect:

debug1: Received SIGCHLD.
debug1: session_by_pid: pid 16135
debug1: session_exit_message: session 0 channel 0 pid 16135
debug2: channel 0: request exit-status confirm 0
debug1: session_exit_message: release channel 0
debug2: channel 0: write failed
debug2: channel 0: close_write
debug2: channel 0: send eow
debug2: channel 0: output open -> closed
debug3: mm_request_send entering: type 28
debug3: monitor_read: checking request 28
debug3: mm_answer_pty_cleanup entering
debug1: session_by_tty: session 0 tty /dev/pts/2
debug3: mm_session_close: session 0 pid 16134
debug3: mm_session_close: tty /dev/pts/2 ptyfd 5
debug1: session_pty_cleanup: session 0 release /dev/pts/2
debug3: session_unused: session id 0 unused
debug3: mm_request_receive entering
debug2: channel 0: read<=0 rfd 10 len -1
debug2: channel 0: read failed
debug2: channel 0: close_read
debug2: channel 0: input open -> drain
debug2: channel 0: ibuf empty
debug2: channel 0: send eof
debug2: channel 0: input drain -> closed
debug2: channel 0: send close
debug2: notify_done: reading
debug3: channel 0: will not send data after close
debug2: channel 0: rcvd close
debug3: channel 0: will not send data after close
debug2: channel 0: is dead
debug2: channel 0: gc: notify user
debug1: session_by_channel: session 0 channel 0
debug1: session_close_by_channel: channel 0 child 0
debug1: session_close: session 0 pid 0
debug3: session_unused: session id 0 unused
debug2: channel 0: gc: user detached
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: server-session, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 server-session (t4 r0 i3/0 o3/0 fd -1/-1 cfd -1)

debug3: channel 0: close_fds r -1 w -1 e -1 c -1
Connection closed by 143.232.109.139
debug1: do_cleanup
debug3: PAM: sshpam_thread_cleanup entering
Transferred: sent 3320, received 1728 bytes
Closing connection to 143.232.109.139 port 45031
debug3: mm_request_send entering: type 59
debug3: monitor_read: checking request 59
debug3: mm_answer_term: tearing down sessions
debug1: PAM: cleanup
debug1: PAM: deleting credentials
1
2
3
4
debug1: PAM: closing session
1
2
3
4


A tcpdump shows that every delay in the login and disconnect process
seems to correspond to a request to my DNS server.  I'm unsure why sshd
would need to do a lookup 8 distinct times per connection and 2 more on
disconnect.

Here is the response time from my dns server forward and reverse, so
it's not just DNS performance or latency:

[root at corvus ~]# time nslookup flux.arc.nasa.gov
Server:         128.102.0.34
Address:        128.102.0.34#53

Name:   flux.arc.nasa.gov
Address: 143.232.109.139


real    0m0.006s
user    0m0.001s
sys     0m0.003s
[root at corvus ~]# time nslookup 143.232.109.139
Server:         128.102.0.34
Address:        128.102.0.34#53

139.109.232.143.in-addr.arpa    name = flux.arc.nasa.gov.


real    0m0.006s
user    0m0.001s
sys     0m0.004s
[root at corvus ~]#

-- 
Configure bugmail: https://bugzilla.mindrot.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.