命令提示符在ssh连接后显示时间过长

我有一个很奇怪的服务器,希望你能帮我找出正在发生的事情。 这里是事实:

  • 该服务器有2个用户: rootmyuser
  • 服务器只接受使用pubkey的ssh连接
  • 如果我从Putty(在Windows上)以myuser的身份连接到服务器,则连接需要几秒钟,并立即显示cmd提示符
  • 如果我从Cygwin(在Windows上)以myuser的身份连接到服务器,则连接需要几秒钟,但是需要40秒才能显示cmd提示符。 从PHP脚本连接,甚至在同一个networking中的另一台linux服务器的ssh连接时也是如此
  • 在Cygwing我使用OpenSSH_7.2p1, OpenSSL 1.0.2g ,在PHP的phpseclib库和其他的Linux服务器OpenSSH_5.3p1, OpenSSL 1.0.1e-fips
  • root尝试相同的过程会产生相同的结果

所以,在这两种情况下( session opened for user myuser sshd日志写session opened for user myuser ),ssh连接都能正确build立,但是在一种情况下,cmd提示会立即出现,另一种情况则会花费太长时间(60秒)。

任何想法可能会促成这个问题? 如果您需要一些关于日志消息或configuration文件的更多信息,请在评论中告知我。

更新1

运行strace ssh [email protected]输出以下内容:

 **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** 

更新2

知道我意识到,在上次login后,挂起等待时,可以按Ctrl + C ,它会立即显示命令提示符。 所以,看起来有一个过程,在启动时间太长。

更新3

我增加了服务器端的debugging级别,这里是挂起和等待之前的输出:

 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 [email protected] 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 

然后过了一会,出现提示符,同时打印出:

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

在那里你可以看到它花了60秒。 总是需要60秒。

以下是使用Putty连接时输出的相同日志(请记住使用Putty使得提示立即显示)。

 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 

更新4

我发现这个过程挂在系统调用上:

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

这是strace -p $PID的输出,其中$PID是执行连接时ssh程序的pid。

当您遇到长时间login延迟时,sshd的反向DNS查找始终是候选人。 你可以尝试如果设置

 UseDNS no 

在/etc/ssh/sshd.conf(并在之后重新启动sshd)修复了这个问题。

尝试调高服务器端的debugging级别,而不是客户端。

这听起来像也许在PAM堆栈中的东西需要一段时间(可能这就是做慢查找等,而不是sshd本身)。 在ssh服务器端的详细日志logging应该告诉你哪个pam模块(如果有的话)会减慢速度,通常有选项来启用这些模块的详细日志logging。

利用BeerSerc的回答,在UBUNTU LTS 14.05.5上使用以下方法,在提供SSH用户名和密码凭证以及对我的Linux系统进行以下更改后,我实现了更快的命令提示符:

 ...become root using su or preface the next two (2) lines with the sudo command... #cd /etc/ssh #vi sshd_config ...navigate to end of file, add following text... # GL 2017-02-25 Turn off DNS lookups to speed up the appearance # of the command prompt after SSH username and # password have been supplied UseDNS no ...save file and exit editor... #/etc/init.d/ssh restart