[Bug 300151] Re: ssh slow during logon, when ENTERING INTERACTIVE SESSION

[justinchudgar]

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 at 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 no-more-sessions at openssh.com
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

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to openssh in Ubuntu.
https://bugs.launchpad.net/bugs/300151

Title:
  ssh slow during logon, when ENTERING INTERACTIVE SESSION

Status in ConsoleKit:
  Fix Released
Status in Portable OpenSSH:
  Fix Released
Status in “openssh” package in Ubuntu:
  Fix Released

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(

To manage notifications about this bug go to:
https://bugs.launchpad.net/consolekit/+bug/300151/+subscriptions