SSH connection pause - SSH

This is a discussion on SSH connection pause - SSH ; Hi all, I have a problem with an SSH server we have here, where any SSH connections to it will take around 30 seconds before prompting the user for a password. The most common cause of such pauses from reading ...

+ Reply to Thread
Results 1 to 7 of 7

Thread: SSH connection pause

  1. SSH connection pause

    Hi all,

    I have a problem with an SSH server we have here, where any SSH
    connections to it will take around 30 seconds before prompting the
    user for a password. The most common cause of such pauses from reading
    other posts would appear to be reverse lookups failing, but that
    doesn't seem to be the case here.

    Everything seems to go ok until the client requests the server's
    protocol and SSH version. At that point, there is a pause for around
    20 - 25 secs before it responds with "Remote protocol version 1.99,
    remote software version OpenSSH_4.1".

    The server is running AIX 4.3.3 and OpenSSH 4.1p1. The client is AIX
    5.3 with OpenSSH 3.8, though I've tried connecting from various
    clients and it doesn't seem to matter what version is used, the same
    problem occurs. When the server eventually does respond with a
    password request, the rest of the connection works fine.

    Does anyone have any ideas why the server is apparently taking so long
    to return it's version and negotiate the protocol? I've tried forcing
    protocol version 1 and 2 by the way, which makes no difference.

    Debug output from a connection below (server name/IP changed):

    OpenSSH_3.8.1p1, OpenSSL 0.9.6m 17 Mar 2004
    debug1: Reading configuration data /etc/ssh/ssh_config
    debug1: Failed dlopen: /usr/krb5/lib/libkrb5.a(libkrb5.a.so):
    0509-022 Cannot load module /usr/krb5/lib/libkrb5.a(libkrb5.a.so).
    0509-026 System error: A file or directory in the path name
    does not exist.

    debug1: Error loading Kerberos, disabling Kerberos auth.
    debug2: ssh_connect: needpriv 0
    debug1: Connecting to mysshserver [10.10.10.10] port 22.
    debug1: Connection established.
    debug1: identity file /.ssh/identity type -1
    debug1: identity file /.ssh/id_rsa type -1
    debug1: identity file /.ssh/id_dsa type -1

    <--------------------PAUSE HERE FOR ~25
    SECS------------------------------------------>

    debug1: Remote protocol version 1.99, remote software version
    OpenSSH_4.1
    debug1: match: OpenSSH_4.1 pat OpenSSH*
    debug1: Enabling compatibility mode for protocol 2.0
    debug1: Local version string SSH-2.0-OpenSSH_3.8.1p1
    debug1: SSH2_MSG_KEXINIT sent
    debug1: SSH2_MSG_KEXINIT received
    debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-
    hellman-group1-sha1
    debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
    debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-
    cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-
    ctr,aes192-ctr,aes256-ctr
    debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-
    cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-
    ctr,aes192-ctr,aes256-ctr
    debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-
    ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
    debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-
    ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
    debug2: kex_parse_kexinit: none,zlib
    debug2: kex_parse_kexinit: none,zlib
    debug2: kex_parse_kexinit:
    debug2: kex_parse_kexinit:
    debug2: kex_parse_kexinit: first_kex_follows 0
    debug2: kex_parse_kexinit: reserved 0
    debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-
    hellman-group14-sha1,diffie-hellman-group1-sha1
    debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
    debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-
    cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-
    ctr,aes192-ctr,aes256-ctr
    debug2: kex_parse_kexinit: aes128-cbc,3des-cbc,blowfish-cbc,cast128-
    cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-
    ctr,aes192-ctr,aes256-ctr
    debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-
    ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
    debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-
    ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
    debug2: kex_parse_kexinit: none,zlib
    debug2: kex_parse_kexinit: none,zlib
    debug2: kex_parse_kexinit:
    debug2: kex_parse_kexinit:
    debug2: kex_parse_kexinit: first_kex_follows 0
    debug2: kex_parse_kexinit: reserved 0
    debug2: mac_init: found hmac-md5
    debug1: kex: server->client aes128-cbc hmac-md5 none
    debug2: mac_init: found hmac-md5
    debug1: kex: client->server aes128-cbc hmac-md5 none
    debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
    debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
    debug2: dh_gen_key: priv key bits set: 125/256
    debug2: bits set: 498/1024
    debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
    debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
    debug3: check_host_in_hostfile: filename /.ssh/known_hosts
    debug3: check_host_in_hostfile: match line 10
    debug3: check_host_in_hostfile: filename /.ssh/known_hosts
    debug3: check_host_in_hostfile: match line 10
    debug1: Host 'mysshserver' is known and matches the RSA host key.
    debug1: Found key in /.ssh/known_hosts:10
    debug2: bits set: 530/1024
    debug1: ssh_rsa_verify: signature correct
    debug2: kex_derive_keys
    debug2: set_newkeys: mode 1
    debug1: SSH2_MSG_NEWKEYS sent
    debug1: expecting SSH2_MSG_NEWKEYS
    debug2: set_newkeys: mode 0
    debug1: SSH2_MSG_NEWKEYS received
    debug1: SSH2_MSG_SERVICE_REQUEST sent
    debug2: service_accept: ssh-userauth
    debug1: SSH2_MSG_SERVICE_ACCEPT received
    debug2: key: /.ssh/identity (0)
    debug2: key: /.ssh/id_rsa (0)
    debug2: key: /.ssh/id_dsa (0)
    debug1: Authentications that can continue: publickey,password,keyboard-
    interactive
    debug3: start over, passed a different list
    publickey,password,keyboard-interactive
    debug3: preferred publickey,keyboard-interactive,password
    debug3: authmethod_lookup publickey
    debug3: remaining preferred: keyboard-interactive,password
    debug3: authmethod_is_enabled publickey
    debug1: Next authentication method: publickey
    debug1: Trying private key: /.ssh/identity
    debug3: no such identity: /.ssh/identity
    debug1: Trying private key: /.ssh/id_rsa
    debug3: no such identity: /.ssh/id_rsa
    debug1: Trying private key: /.ssh/id_dsa
    debug3: no such identity: /.ssh/id_dsa
    debug2: we did not send a packet, disable method
    debug3: authmethod_lookup keyboard-interactive
    debug3: remaining preferred: password
    debug3: authmethod_is_enabled keyboard-interactive
    debug1: Next authentication method: keyboard-interactive
    debug2: userauth_kbdint
    debug2: we sent a keyboard-interactive packet, wait for reply
    debug1: Authentications that can continue: publickey,password,keyboard-
    interactive
    debug3: userauth_kbdint: disable: no info_req_seen
    debug2: we did not send a packet, disable method
    debug3: authmethod_lookup password
    debug3: remaining preferred:
    debug3: authmethod_is_enabled password
    debug1: Next authentication method: password
    root@mysshserver's password:


    Also, part of the truss output (truss -d, to show timestamp) of the
    ssh connection below:

    2.6129: open("/etc/passwd", O_RDONLY) = 5
    2.6138: kioctl(5, 22528, 0x00000000, 0x00000000) Err#25 ENOTTY
    2.6147: kfcntl(5, F_GETFD, 0x00000000) = 0
    2.6157: kfcntl(5, F_SETFD, 0x00000001) = 0
    2.6166: accessx("/etc/security/passwd", 04, 0) = 0
    2.6177: open("/etc/security/passwd", O_RDONLY) = 6
    2.6185: kioctl(6, 22528, 0x00000000, 0x00000000) Err#25 ENOTTY
    2.6193: kfcntl(6, F_GETFD, 0x00000000) = 0
    2.6202: kfcntl(6, F_SETFD, 0x00000001) = 0
    2.6213: accessx("/etc/passwd", 04, 0) = 0
    2.6223: statx("/etc/passwd", 0x2FF220D0, 76, 0) = 0
    2.6233: accessx("/etc/passwd", 04, 0) = 0
    2.6243: statx("/etc/passwd", 0x2FF21BA0, 76, 0) = 0
    2.6251: accessx("/etc/passwd", 04, 0) = 0
    2.6262: statx("/etc/passwd", 0x2FF21C10, 76, 0) = 0
    2.6272: accessx("/etc/passwd", 04, 0) = 0
    2.6281: statx("/etc/passwd", 0x2FF21B90, 76, 0) = 0
    2.6290: accessx("/etc/security/passwd", 04, 0) = 0
    2.6301: statx("/etc/security/passwd", 0x2FF21BF0, 76, 0) = 0
    2.6311: accessx("/etc/passwd", 04, 0) = 0
    2.6321: statx("/etc/passwd", 0x2FF21910, 76, 0) = 0
    2.6330: accessx("/etc/passwd", 04, 0) = 0
    2.6340: statx("/etc/passwd", 0x2FF21980, 76, 0) = 0
    2.6351: close(5) = 0
    2.6359: close(6) = 0
    2.6370: sigprocmask(2, 0xF08A4790, 0x2FF22870) = 0
    2.6377: _sigaction(13, 0x00000000, 0x2FF228E0) = 0
    2.6386: thread_setmymask_fast(0x00000000, 0x00000000,
    0x00000000, 0x1018D039, 0x00000000, 0x00000434, 0x00000000,
    0xAD41AED8) = 0x00000000
    2.6394: sigprocmask(2, 0xF08A4790, 0x2FF22870) = 0
    2.6402: _sigaction(13, 0x2FF228D0, 0x00000000) = 0
    2.6411: thread_setmymask_fast(0x00000000, 0x00000000,
    0x00000000, 0x1018D039, 0x00000000, 0x000003FC, 0x00000000,
    0xAD41AED8) = 0x00000000
    4.6426: kread(4, " ", 1) (sleeping...)
    kread(4, " S", 1) = 1
    kread(4, " S", 1) = 1
    kread(4, " H", 1) = 1
    kread(4, " -", 1) = 1
    kread(4, " 1", 1) = 1
    kread(4, " .", 1) = 1
    kread(4, " 9", 1) = 1
    kread(4, " 9", 1) = 1
    kread(4, " -", 1) = 1
    kread(4, " O", 1) = 1
    kread(4, " p", 1) = 1
    kread(4, " e", 1) = 1
    kread(4, " n", 1) = 1
    kread(4, " S", 1) = 1
    kread(4, " S", 1) = 1
    kread(4, " H", 1) = 1
    kread(4, " _", 1) = 1
    kread(4, " 4", 1) = 1
    kread(4, " .", 1) = 1
    kread(4, " 1", 1) = 1
    kread(4, "\n", 1) = 1
    kwrite(4, " S S H - 2 . 0 - O p e n".., 24) = 24
    28.7363: kioctl(4, -2147195266, 0x2FF227F0, 0x00000000) = 0
    28.7372: kioctl(4, -2147195267, 0x2FF227F0, 0x00000000) = 0
    28.7381: kfcntl(4, F_SETFL, 0x00000004) = 0
    28.7394: _getpid() = 778254
    28.7403: _getpid() = 778254
    28.7413: _getpid() = 778254


    The pause occurs on a kread() operation, which is eventually responded
    to with the SSH version and protocol.

    Any ideas would be welcomed!

    Cheers,
    Neil


  2. Re: SSH connection pause

    In article <1179909344.731327.163870@u30g2000hsc.googlegroups. com>
    theredmini@gmail.com writes:
    >
    >I have a problem with an SSH server we have here, where any SSH
    >connections to it will take around 30 seconds before prompting the
    >user for a password. The most common cause of such pauses from reading
    >other posts would appear to be reverse lookups failing, but that
    >doesn't seem to be the case here.


    Why don't you think so? It seems to match the symptoms perfectly.

    >Everything seems to go ok until the client requests the server's
    >protocol and SSH version. At that point, there is a pause for around
    >20 - 25 secs before it responds with "Remote protocol version 1.99,
    >remote software version OpenSSH_4.1".


    The client doesn't "request" that, it's the first thing the server
    sends, and it does so spontaneously. If it's waiting for a reverse DNS
    lookup of the client's IP address, it won't send it until the lookup
    completes or times out. You can simply telnet to port 22 on the server
    and see the delay - on a properly working server you get the version
    string immediately.

    If not DNS, it could also be a problem with IDENT lookup - I don't think
    OpenSSH's sshd has that builtin, but it's frequently built to use
    libwrap, which may or may not do IDENT lookups depending on compile-
    time settings and/or config (hosts.{allow,deny}). If you're simply
    dropping incoming IDENT connections on the client due to firewall
    config, the lookups will take a potentially long time to fail. It's
    generally better to have the firewall respond with RST, or let the
    connections through and the host stack will respond with RST due to
    nothing listening on port 113.

    --Per Hedeland
    per@hedeland.org

  3. Re: SSH connection pause

    Thanks for your response Per, please see my comments inserted below...

    On May 23, 10:39 pm, p...@hedeland.org (Per Hedeland) wrote:
    > In article <1179909344.731327.163...@u30g2000hsc.googlegroups. com>
    >
    > theredm...@gmail.com writes:
    >
    > >I have a problem with an SSH server we have here, where any SSH
    > >connections to it will take around 30 seconds before prompting the
    > >user for a password. The most common cause of such pauses from reading
    > >other posts would appear to be reverse lookups failing, but that
    > >doesn't seem to be the case here.

    >
    > Why don't you think so? It seems to match the symptoms perfectly.


    Several reasons. DNS was my first port of call when I noticed this
    problem, I spent a while checking that everything was setup correctly
    and confirmed that I can do DNS lookups and reverse lookups either way
    from client to server or vice-versa. Also, from other posts I've read
    about reverse lookups causing the connection to hang, the hang appears
    to occur at a different point in the connection, according to the
    debug output (though I concede that it could potentialy occur at
    various points). I tried an ssh connection from the server to
    127.0.0.1, which also resulted in the connection delay.

    >
    > >Everything seems to go ok until the client requests the server's
    > >protocol and SSH version. At that point, there is a pause for around
    > >20 - 25 secs before it responds with "Remote protocol version 1.99,
    > >remote software version OpenSSH_4.1".

    >
    > The client doesn't "request" that, it's the first thing the server
    > sends, and it does so spontaneously. If it's waiting for a reverse DNS
    > lookup of the client's IP address, it won't send it until the lookup
    > completes or times out. You can simply telnet to port 22 on the server
    > and see the delay - on a properly working server you get the version
    > string immediately.


    Interesting. I'd thought that the string was requested by the client
    due to the kread in the truss output, which hangs for a while,
    followed by the response from the server. I tried your suggestion of
    telneting on port 22, which produced the following output (server
    names changed):

    [root@myclient]:/# telnet mysshserver 22
    Trying...
    Connected to mysshserver.
    Escape character is '^]'.
    SSH-2.0-OpenSSH_4.1

    This confirms your suggestion that the protocol/version string is sent
    by the server un-prompted. The SSH version string does take a similar
    amount of time to appear (around 20-25 secs), suggesting that your
    reverse lookup diagnosis is correct. This puzzles me, as I've checked
    and confirmed that the reverse lookup is working.

    >
    > If not DNS, it could also be a problem with IDENT lookup - I don't think
    > OpenSSH's sshd has that builtin, but it's frequently built to use
    > libwrap, which may or may not do IDENT lookups depending on compile-
    > time settings and/or config (hosts.{allow,deny}). If you're simply
    > dropping incoming IDENT connections on the client due to firewall
    > config, the lookups will take a potentially long time to fail. It's
    > generally better to have the firewall respond with RST, or let the
    > connections through and the host stack will respond with RST due to
    > nothing listening on port 113.
    >


    This isn't something that I've yet considered. The OpenSSH install on
    this server is an out-of-the-box pre-compiled version from IBM and is
    identical to the version that is running without the same problem on
    an apparently identical server. I've no idea whether IDENT would be
    enabled in this build, but it's something for me to look into, so
    thanks for the suggestion. For info, both the client and server are
    behind the firewall so there is no firewall in between the two servers
    and hence nothing should be being blocked. Also, we are not using
    hosts.allow/deny files. For info, a telnet to the server on port 113
    results in a failed connection and netstat shows nothing listening on
    port 113 on the server. The same is the case for the other server that
    is working properly though.

    > --Per Hedeland
    > p...@hedeland.org



    Cheers,
    Neil


  4. Re: SSH connection pause

    In article <1179994341.906284.171180@w5g2000hsg.googlegroups.c om>
    theredmini@gmail.com writes:
    >Several reasons. DNS was my first port of call when I noticed this
    >problem, I spent a while checking that everything was setup correctly
    >and confirmed that I can do DNS lookups and reverse lookups either way
    >from client to server or vice-versa. Also, from other posts I've read
    >about reverse lookups causing the connection to hang, the hang appears
    >to occur at a different point in the connection, according to the
    >debug output (though I concede that it could potentialy occur at
    >various points). I tried an ssh connection from the server to
    >127.0.0.1, which also resulted in the connection delay.


    Well, that last item rules out a lot of things I'd say - neither DNS or
    IDENT are likely causes then.

    >Interesting. I'd thought that the string was requested by the client
    >due to the kread in the truss output, which hangs for a while,
    >followed by the response from the server.


    Yes, the client tries to read from its local socket, but the server
    doesn't get told about that. The client blocks in the read until the
    server decides to send something.

    > For info, a telnet to the server on port 113
    >results in a failed connection and netstat shows nothing listening on
    >port 113 on the server. The same is the case for the other server that
    >is working properly though.


    The IDENT connections go from server to client, which is one reason that
    they occasionally cause "strange" problems. But per above and everything
    else you wrote, this isn't a likely cause. Try running the *server* in
    debug mode, you may get some clues from where the output pauses. And/or
    if there is something like 'strace' or 'truss' on AIX, it can be very a
    useful tool to figure out what is going on.

    --Per Hedeland
    per@hedeland.org

  5. Re: SSH connection pause

    On May 24, 7:51 pm, p...@hedeland.org (Per Hedeland) wrote:



    > The IDENT connections go from server to client, which is one reason that
    > they occasionally cause "strange" problems. But per above and everything
    > else you wrote, this isn't a likely cause. Try running the *server* in
    > debug mode, you may get some clues from where the output pauses. And/or
    > if there is something like 'strace' or 'truss' on AIX, it can be very a
    > useful tool to figure out what is going on.
    >
    > --Per Hedeland
    > p...@hedeland.org


    Per, you suggested I try running the *server* in debug mode
    (previously I've only been running the client in debug mode). This
    sounds like a sensible course of action, so I gave it a go, and got
    some pretty strange results.

    I started the sshd in debug mode, after stopping the currently running
    sshd server. I then tried connecting from the client that I've been
    using all along and.... it connected with no delay. This I found very
    odd, as it appeared that restarting the sshd had fixed the problem,
    but I'd tried this before several times. Further investigation shows
    that the sshd works fine until I attempt to connect to it from a
    client that cannot be resolved via a reverse lookup. In this case, I
    see output like "debug3: Trying to reverse map address "
    and it hangs like previously, which I guess is to be expected.

    Now for the interesting bit ;-) If I then attempt a connection to the
    server from the client who's address *can* be resolved via reverse
    lookup.... it hangs again!?! As far as I can tell, the sshd works fine
    until I attempt a connection from a source who cannot be reverse
    looked up. Any subsequent connections, whether or not their addresses
    can be resolved successfully will experience the pause during the
    lookup. I don't understand why this is happening, but I intend to test
    various scenarios to see if I can find a cause. This will be a little
    difficult, as I can't just stop/start the sshd at any time. I might
    look into starting the sshd in debug mode on a different port, so I
    don't have to stop the currently running daemon.

    Thanks for your help so far, I'll report back with what I find...

    Cheers,
    Neil



  6. Re: SSH connection pause

    In article <1180093707.455457.325910@k79g2000hse.googlegroups. com>
    theredmini@gmail.com writes:
    >
    >Now for the interesting bit ;-) If I then attempt a connection to the
    >server from the client who's address *can* be resolved via reverse
    >lookup.... it hangs again!?! As far as I can tell, the sshd works fine
    >until I attempt a connection from a source who cannot be reverse
    >looked up. Any subsequent connections, whether or not their addresses
    >can be resolved successfully will experience the pause during the
    >lookup. I don't understand why this is happening, but I intend to test
    >various scenarios to see if I can find a cause.


    Well, sounds like something "breaks" in your name service functionality
    when it hits a failure, then. I can't imagine how this could happen with
    "standard" DNS resolver libraries or name servers, but maybe you have
    some evil proprietary proxy/cache in front of it on AIX? I know that at
    least in the past, Solaris had something called the "Name Service Cache
    Daemon" (nscd) that sat in front of all types of lookups (DNS, NIS,
    files...) and caused all kinds of weird problems. At least it was
    configurable as to what things it should "help" with, and you pretty
    quickly learned to disable it at least for "hosts" if you wanted to stay
    sane...

    > This will be a little
    >difficult, as I can't just stop/start the sshd at any time. I might
    >look into starting the sshd in debug mode on a different port, so I
    >don't have to stop the currently running daemon.


    Yes, that's "standard operating procedure" for this kind of debugging -
    no need to stop the regular daemon or even use a separate config file,
    just give the debug instance a different port with -p.

    --Per Hedeland
    per@hedeland.org

  7. Re: SSH connection pause

    On 2007-05-25, Per Hedeland wrote:

    > Well, sounds like something "breaks" in your name service functionality
    > when it hits a failure, then. I can't imagine how this could happen with
    > "standard" DNS resolver libraries or name servers, but maybe you have
    > some evil proprietary proxy/cache in front of it on AIX? I know that at
    > least in the past, Solaris had something called the "Name Service Cache
    > Daemon" (nscd) that sat in front of all types of lookups (DNS, NIS,


    Can this funny resolver behaviour be produced outside of sshd?

    Is a process only impaired by its own earlier lookups (which would make
    it sound more like a problem in the resolver library and less like nscd) ?

    Do you get a problem like this with both forward and reverse lookups?
    Are you doing both in sshd (in the style of -DPARANOID tcp-wrqppers)?

    Are you patched up to date?

    Can truss and tcpdump tell you where these resolution attempts are going wrong?
    (e.g. silly use of a search path, some load-balancer pushed into a an unhelpful
    state by a failure, a rapid series of lookups interfered with by a firewall?)

    --
    Elvis Notargiacomo master AT barefaced DOT cheek
    http://www.notatla.org.uk/goen/

+ Reply to Thread