Ubuntu
openssh package

ssh slow during logon, when ENTERING INTERACTIVE SESSION

Bug #300151 reported by ichudov
32
This bug affects 6 people
Affects Status Importance Assigned to Milestone
ConsoleKit
Fix Released
Undecided
Unassigned
portable OpenSSH
Fix Released
Undecided
Unassigned
openssh (Ubuntu)
Fix Released
Undecided
Unassigned

Bug Description

I am using a Ubuntu Intrepid 32 bit server with all latest patches.

Logging on via ssh (USING KEYS) is incredibly, painfully slow.

I have done some investigation.

1. Slowness is mild after a reboot and, as time goes on, it becomes progressively slower and sloowweerr and ssslllooowwweeerrrr.

2. If I run ssh -v, then I can see that the ssh process is stuck for many seconds after saying "entering interactive session".

3. This even happens if I do, from that server, a command "ssh localhost".

4. Disabling GSSAPI authentication, as well as saying "UseDNS no", in sshd_config, does not help.

5. A similar problems applies to use of "su" and can be more easily debugged. If, as root, I say "su - <username> date", it is also incredibly slow. If I debug that with

  strace -o q -f su - <myuserid> date

then I see that su tries to connect to UNIX socket /var/run/dbus/system_bus_socket, and then it is stuck doing poll(), which remains <unfinished>. Not sure if it is related, but it could be.

munmap(0x7f21ab91a000, 2970) = 0
close(4) = 0
socket(PF_FILE, SOCK_STREAM, 0) = 4
connect(4, {sa_family=AF_FILE, path="/var/run/dbus/system_bus_socket"}, 33) = 0
fcntl(4, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
fcntl(4, F_GETFD) = 0
fcntl(4, F_SETFD, FD_CLOEXEC) = 0
geteuid() = 0
poll([{fd=4, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
write(4, "\0", 1) = 1
write(4, "AUTH EXTERNAL 30\r\n", 18) = 18
poll([{fd=4, events=POLLIN, revents=POLLIN}], 1, -1) = 1
read(4, "OK 951631a86cc350048c747bce491f8"..., 2048) = 37
poll([{fd=4, events=POLLOUT, revents=POLLOUT}], 1, -1) = 1
write(4, "BEGIN\r\n", 7) = 7
poll([{fd=4, events=POLLIN|POLLOUT, revents=POLLOUT}], 1, -1) = 1
writev(4, [{"l\1\0\1\0\0\0\0\1\0\0\0n\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 128}, {"", 0}], 2) = 128
gettimeofday({1227143564, 211248}, NULL) = 0
poll([{fd=4, events=POLLIN, revents=POLLIN}], 1, 25000) = 1
read(4, "l\2\1\1\r\0\0\0\1\0\0\0E\0\0\0\6\1s\0\10\0\0\0:1.28259"..., 2048) = 282
read(4, 0x24686e0, 2048) = -1 EAGAIN (Resource temporarily unavailable)
writev(4, [{"l\1\0\1\304\0\0\0\2\0\0\0\273\0\0\0\1\1o\0#\0\0\0/org/"..., 208}, {"\274\0\0\0\0\0\0\0\t\0\0\0unix-user\0\1i\0\0\0\0\350\3"..., 196}], 2) = 404
gettimeofday({1227143564, 213048}, NULL) = 0
poll(

Revision history for this message
ichudov (igor-chudov) wrote :

I think that I have a track. Based on similar "su" problems, I decided to explore the possibility that it is the fault of "dbus". Based on results below, I believe it to be the case and I reassign this issue to "dbus". Restarting dbus fixes this issue.

So I did:

1) time how long ssh to localhost takes:

==>time ssh localhost date
Thu Nov 20 22:55:54 CST 2008

real 0m0.248s
user 0m0.000s
sys 0m0.004s

2) Restarted dbus as root:

root:~ ###/etc/init.d/dbus restart
 * Stopping System Tools Backends system-tools-backends
   ...done.
 * Stopping bluetooth
   ...done.
 * Stopping Hardware abstraction layer hald
   ...done.
 * Stopping system message bus dbus
   ...done.
 * Starting system message bus dbus
   ...done.
 * Starting Hardware abstraction layer hald
   ...done.
 * Starting bluetooth
   ...done.
 * Starting System Tools Backends system-tools-backends
   ...done.

(this killed gnome-panel and stuff also, no biggy)

3) tried ssh again:
==>time ssh localhost date
Thu Nov 20 22:56:06 CST 2008

real 0m0.268s
user 0m0.000s
sys 0m0.008s

So restarting dbus fixed this issue.

Revision history for this message
ichudov (igor-chudov) wrote :

oops, bad paste, first ssh took 25 seconds.

Revision history for this message
James Westby (james-w) wrote :

Hi,

This sounds similar to bug 284229, is console-kit-daemon using a lot
of CPU on the system you are logging in to?

Thanks,

James

Revision history for this message
ichudov (igor-chudov) wrote : Re: [Bug 300151] Re: ssh slow during logon, when ENTERING INTERACTIVE SESSION

On Mon, Nov 24, 2008 at 11:46:35PM -0000, James Westby wrote:
> This sounds similar to bug 284229, is console-kit-daemon using a lot
> of CPU on the system you are logging in to?

Yep, quite a bit of cpu used by it

Revision history for this message
Jeff Enns (cyberpenguinks) wrote :

I'm just checking to see if this issue has been resolved. The bug this was related to was fixed in a later release. Let me know this is or is not the case. Thank you!

Changed in consolekit:
status: New → Invalid
Changed in openssh:
status: New → Invalid
Changed in openssh (Ubuntu):
status: New → Invalid
Revision history for this message
ichudov (igor-chudov) wrote :

Yes, fixed in Jaunty.

i

On Sat, Jun 06, 2009 at 12:11:58AM -0000, Jeff Enns wrote:
> I'm just checking to see if this issue has been resolved. The bug this
> was related to was fixed in a later release. Let me know this is or is
> not the case. Thank you!
>
> ** Changed in: consolekit
> Status: New => Invalid
>
> ** Changed in: openssh
> Status: New => Invalid
>
> ** Changed in: openssh (Ubuntu)
> Status: New => Invalid
>

Revision history for this message
Jeff Enns (cyberpenguinks) wrote :

Good to hear! Thank you.

Jeff Enns (cyberpenguinks)
Changed in openssh (Ubuntu):
status: Invalid → Fix Released
Changed in openssh:
status: Invalid → Fix Released
Changed in consolekit:
status: Invalid → Fix Released
Revision history for this message
tristan_lefebure (tristanl) wrote :

I do experience the same symptoms on Jaunty, i.e. 20s break in "Entering interactive session." while loging through ssh. Any idea if this is the same bug?

Revision history for this message
ichudov (igor-chudov) wrote :

On Fri, Oct 09, 2009 at 01:43:32PM -0000, tristan_lefebure wrote:
> I do experience the same symptoms on Jaunty, i.e. 20s break in
> "Entering interactive session." while loging through ssh. Any idea if
> this is the same bug?
>

Do "top" on your server and see if consolekit something occupies 100%
of CPU.

It could also be related to avahi-daemon.

You can stop avahi daemon

sudo /etc/init.d/avahi-daemon stop

and then you can ssh again and see if it is faster.

i

Revision history for this message
tristan_lefebure (tristanl) wrote :

No, I don't see consolekit consuming lots of memory. That said, I can see some consolekit zombies:

[tristan@babylon ~] ps -le | grep Z
F S UID PID PPID C PRI NI ADDR SZ WCHAN TTY TIME CMD
5 Z 0 4658 1 0 80 0 - 0 exit ? 00:00:00 console-kit-dae <defunct>
5 Z 0 7122 1 0 80 0 - 0 exit ? 00:00:00 console-kit-dae <defunct>
5 Z 0 8257 1 0 80 0 - 0 exit ? 00:00:00 console-kit-dae <defunct>

Stopping the avahi daemon, does not make any difference.

Any clue?

Revision history for this message
Justin Chudgar (justinzane) wrote :

Using Oneiric, I am still experiencing the delay noted above. The server showing this delay is currently very underutilized, that is, low CPU utilization, lots of free RAM, low net if utilization, etc. There are no process hogs.

Stopping/restarting avahi-daemon did not help at all. No console-kit zombies, nothing.

$ time ssh -v root@tiny date
OpenSSH_5.8p1 Debian-7ubuntu1, OpenSSL 1.0.0e 6 Sep 2011
...
debug1: Authentication succeeded (publickey).
Authenticated to tiny ([192.168.0.10]:22).
debug1: channel 0: new [client-session]
debug1: Requesting <email address hidden>
debug1: Entering interactive session.
...
<HUGE_DELAY_HERE>
...
Transferred: sent 2536, received 2152 bytes, in 25.8 seconds
Bytes per second: sent 98.3, received 83.4
debug1: Exit status 0

real 0m26.258s
user 0m0.028s
sys 0m0.008s

Revision history for this message
Quinn Plattel (qiet72) wrote :

Restart the dbus service on the ssh server "sudo restart dbus" - that should help.
If not, try adding "UseDNS=no" to your ssh server's sshd_config file and restart the service "sudo restart ssh"
If the UseDNS trick works, check your dns server setup.

Revision history for this message
Quinn Plattel (qiet72) wrote :

Correction, it is "UseDNS no".

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.