Ssh – Command prompt taking too long to appear after ssh connection

bashssh

I have a server that is acting really weird and hopefully you will help me find out what is happening. Here are the facts:

  • The server has 2 users: root and myuser
  • The server accepts only ssh connections using pubkey
  • If I connect to the server as myuser from Putty (on Windows) the connection take a few seconds and the cmd prompt appears right away
  • If I connect to the server as myuser from Cygwin (on Windows) the connection take a few seconds but it takes like 40 seconds for the cmd prompt to appear. The same occurs when connecting from a PHP script or even with ssh from another linux server in the same network
  • On Cygwing I'm using OpenSSH_7.2p1, OpenSSL 1.0.2g, on PHP the phpseclib library and on the other linux server OpenSSH_5.3p1, OpenSSL 1.0.1e-fips
  • Trying the same procedure with root produces the same results

So, the ssh connection is stablished correctly in both cases (the sshd logs write session opened for user myuser) but in one case the cmd prompts appears right away and in the other it takes way too long (60 seconds).

Any ideas what might couse the problem? If you need some more info about logs messages or config files let me know in the comments.

UPDATE 1

Running strace ssh myuser@1.2.3.4 outputs the following:

**lot of stuff**

18:20:10 read(3, "Dq\340\342\5\16\7+\367\366r\315\241\272\35\23\2225\344\366\332D\36\217\254$
18:20:10 ioctl(0, TIOCGWINSZ, {ws_row=60, ws_col=237, ws_xpixel=0, ws_ypixel=0}) = 0
18:20:10 getsockopt(3, SOL_TCP, TCP_NODELAY, [0], [4]) = 0
18:20:10 setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0
18:20:10 getsockname(3, {sa_family=AF_INET, sin_port=htons(40713), sin_addr=inet_addr("190.9$
18:20:10 setsockopt(3, SOL_IP, IP_TOS, [16], 4) = 0
18:20:10 select(7, [3], [3], NULL, NULL) = 1 (out [3])
18:20:10 write(3, "?32\275\177\356\212x\177\334>\352K\226\225)\225\3507\361Zu,I\7!\273Hv1\31$
18:20:10 select(7, [3], [], NULL, NULL) = 1 (in [3])
18:20:10 read(3, "\37\347\207\273\236\244\22\314\222\305\23\270\206zl\270X\225i0\30\207\343f$
18:20:10 select(7, [3 4], [], NULL, NULL) = 1 (in [3])
18:20:10 read(3, "J2\345\334\336\350\364\225<D\t\305Y\23\366\341!_\351\310\357C\252I\322|\3\$
18:20:10 select(7, [3 4], [5], NULL, NULL) = 1 (out [5])
18:20:10 write(5, "Last login: Fri Mar  4 18:19:33 "..., 58) = 58
18:20:10 select(7, [3 4], [], NULL, NULL) = 1 (in [3])

# Here is where it waits 60 seconds

18:21:10 read(3, ":\233\225\377P\216.\2u&\275\372\257\203\261\236\322aN\263\313\203\315\373\$
18:21:10 select(7, [3 4], [5], NULL, NULL) = 1 (out [5])
18:21:10 write(5, "\33[?1034h[securitybox@wordpress10"..., 41) = 41
18:21:10 select(7, [3 4], [], NULL, NULL) = 1 (in [4])
18:21:14 read(4, "e", 16384)            = 1
18:21:14 select(7, [3 4], [3], NULL, NULL) = 1 (out [3])
18:21:14 write(3, ":\24\266\315J\202w+\213i\320\314\251\vc\17\230\372\344\237\341\341o\256\3$
18:21:14 select(7, [3 4], [], NULL, NULL) = 1 (in [3])
18:21:14 read(3, "eS\362U<\346\345f\245\27\21\323<\30J\20\261%1hx&\7k\323 \240\n^-\1P"..., 8$
18:21:14 select(7, [3 4], [5], NULL, NULL) = 1 (out [5])
18:21:14 write(5, "e", 1)               = 1
18:21:14 select(7, [3 4], [], NULL, NULL) = 1 (in [4])
18:21:14 read(4, "x", 16384)            = 1

**more stuff**

UPDATE 2

Know I realized that after the Last login:, when it hangs up waiting, you can press Ctrl + C and it will show the command prompt right away. So, it looks like there is a process that is taking too long at the startup.

UPDATE 3

I increased the debug level on the server side and here is the lates outputs before hanging and waiting:

Mar  4 17:15:31 thisserver.hostname sshd[2279]: debug3: PAM: opening session
Mar  4 17:15:32 thisserver.hostname sshd[2279]: pam_unix(sshd:session): session opened for user securitybox by (uid=0)
Mar  4 17:15:32 thisserver.hostname sshd[2279]: User child is on pid 2301
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug3: mm_request_receive entering
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: PAM: establishing credentials
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: permanently_set_uid: 10037/10037
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug2: set_newkeys: mode 0
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug2: set_newkeys: mode 1
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: Entering interactive session for SSH2.
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug2: fd 4 setting O_NONBLOCK
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug2: fd 6 setting O_NONBLOCK
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_init_dispatch_20
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: input_session_request
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: channel 0: new [server-session]
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug2: session_new: allocate (allocated 0 max 10)
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug3: session_unused: session id 0 unused
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_new: session 0
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_open: channel 0
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_open: session 0: link with channel 0
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_input_channel_open: confirm session
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_input_global_request: rtype no-more-sessions@openssh.com want_reply 0
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug3: Wrote 40 bytes for a total of 2701
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_input_channel_req: channel 0 request pty-req reply 1
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_by_channel: session 0 channel 0
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_input_channel_req: session 0 req pty-req
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: Allocating pty.
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug3: mm_request_send entering: type 26
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug3: mm_pty_allocate: waiting for MONITOR_ANS_PTY
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug3: mm_request_receive_expect entering: type 27
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug3: mm_request_receive entering
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug3: monitor_read: checking request 26
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug3: mm_answer_pty entering
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug2: session_new: allocate (allocated 0 max 10)
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug3: session_unused: session id 0 unused
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug1: session_new: session 0
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug3: ssh_selinux_setup_pty: setting TTY context on /dev/pts/6
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug3: ssh_selinux_setup_pty: done
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug3: mm_request_send entering: type 27
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug3: mm_answer_pty: tty /dev/pts/6 ptyfd 4
Mar  4 17:15:32 thisserver.hostname sshd[2279]: debug3: mm_request_receive entering
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_pty_req: session 0 alloc /dev/pts/6
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_input_channel_req: channel 0 request shell reply 1
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_by_channel: session 0 channel 0
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_input_channel_req: session 0 req shell
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug2: fd 3 setting TCP_NODELAY
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug2: channel 0: rfd 9 isatty
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug2: fd 9 setting O_NONBLOCK
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug3: fd 7 is O_NONBLOCK
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug3: Wrote 88 bytes for a total of 2789
Mar  4 17:15:32 thisserver.hostname sshd[2302]: debug1: Setting controlling tty using TIOCSCTTY.
Mar  4 17:15:32 thisserver.hostname sshd[2301]: debug3: Wrote 88 bytes for a total of 2877
Mar  4 17:15:32 thisserver.hostname sshd[2302]: debug3: Copy environment: SELINUX_ROLE_REQUESTED=
Mar  4 17:15:32 thisserver.hostname sshd[2302]: debug3: Copy environment: SELINUX_LEVEL_REQUESTED=
Mar  4 17:15:32 thisserver.hostname sshd[2302]: debug3: Copy environment: SELINUX_USE_CURRENT_RANGE=
Mar  4 17:15:32 thisserver.hostname sshd[2302]: debug3: channel 0: close_fds r -1 w -1 e -1

Then after a while, at the same time the prompt appears, it prints:

Mar  4 17:16:32 thisserver.hostname sshd[2301]: debug3: Wrote 72 bytes for a total of 2949

There you can see that it took 60 seconds. It always takes exactly 60 seconds.

Here is the output of the same log when connecting using Putty (remember that using Putty makes the prompt appear right away).

Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug3: PAM: opening session
Mar  4 17:44:45 thisserver.hostname sshd[5505]: pam_unix(sshd:session): session opened for user root by (uid=0)
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug2: set_newkeys: mode 0
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug2: cipher_init: set keylen (16 -> 32)
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug2: set_newkeys: mode 1
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug2: cipher_init: set keylen (16 -> 32)
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: Entering interactive session for SSH2.
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug2: fd 4 setting O_NONBLOCK
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug2: fd 5 setting O_NONBLOCK
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: server_init_dispatch_20
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: server_input_channel_open: ctype session rchan 256 win 16384 max 16384
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: input_session_request
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: channel 0: new [server-session]
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug2: session_new: allocate (allocated 0 max 10)
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug3: session_unused: session id 0 unused
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_new: session 0
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_open: channel 0
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_open: session 0: link with channel 0
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: server_input_channel_open: confirm session
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug3: Wrote 52 bytes for a total of 3185
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: server_input_channel_req: channel 0 request pty-req reply 1
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_by_channel: session 0 channel 0
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_input_channel_req: session 0 req pty-req
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: Allocating pty.
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_pty_req: session 0 alloc /dev/pts/7
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug3: ssh_selinux_setup_pty: setting TTY context on /dev/pts/7
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug3: ssh_selinux_setup_pty: done
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug3: Wrote 36 bytes for a total of 3221
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: server_input_channel_req: channel 0 request shell reply 1
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_by_channel: session 0 channel 0
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_input_channel_req: session 0 req shell
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug2: fd 3 setting TCP_NODELAY
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug2: channel 0: rfd 8 isatty
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug2: fd 8 setting O_NONBLOCK
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug3: fd 6 is O_NONBLOCK
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug3: Wrote 88 bytes for a total of 3309
Mar  4 17:44:45 thisserver.hostname sshd[5508]: debug1: Setting controlling tty using TIOCSCTTY.
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug3: Wrote 100 bytes for a total of 3409
Mar  4 17:44:45 thisserver.hostname sshd[5508]: debug1: PAM: reinitializing credentials
Mar  4 17:44:45 thisserver.hostname sshd[5508]: debug1: permanently_set_uid: 0/0
Mar  4 17:44:45 thisserver.hostname sshd[5508]: debug3: Copy environment: SELINUX_ROLE_REQUESTED=
Mar  4 17:44:45 thisserver.hostname sshd[5508]: debug3: Copy environment: SELINUX_LEVEL_REQUESTED=
Mar  4 17:44:45 thisserver.hostname sshd[5508]: debug3: Copy environment: SELINUX_USE_CURRENT_RANGE=
Mar  4 17:44:45 thisserver.hostname sshd[5508]: debug3: channel 0: close_fds r -1 w -1 e -1
Mar  4 17:44:45 thisserver.hostname sshd[5505]: debug3: Wrote 84 bytes for a total of 3493

UPDATE 4

I found out that the process is hanging on the system call:

select(7, [3 4], [], NULL, NULL

This was the output of strace -p $PID where $PID is the pid of the ssh program while permforming the connection.

Best Answer

sshd's reverse DNS lookup is always a candidate when you experience long login delays. You could try if setting

UseDNS no

in /etc/ssh/sshd.conf (and restarting sshd afterwards) fixes the issue.