我有一个非常奇怪的服务器,希望你能帮我找出发生的事情.以下是事实:
>服务器有2个用户:root和myuser
>服务器仅接受使用pubkey的ssh连接
>如果我从Putty(在Windows上)以myuser身份连接到服务器,则连接需要几秒钟,并且会立即显示cmd提示符
>如果我从Cygwin(在Windows上)以myuser身份连接到服务器,但cmd提示符出现需要40秒.从PHP脚本连接,甚至从同一网络中的另一个Linux服务器连接ssh时,也会出现同样的情况
> On Cygwing我正在使用OpenSSH_7.2p1,OpenSSL 1.0.2g,PHP上的PHPseclib库和另一个Linux服务器OpenSSH_5.3p1,OpenSSL 1.0.1e-fips
>使用root尝试相同的过程会产生相同的结果
因此,在两种情况下都正确建立了ssh连接(为用户myuser打开了sshd日志写入会话),但在一种情况下,cmd提示立即出现,而在另一种情况下,它会占用太长时间(60秒).
有什么想法可以解决问题吗?如果您需要有关日志消息或配置文件的更多信息,请在评论中告诉我.
更新1
运行strace ssh myuser@1.2.3.4输出以下内容:
**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,[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],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,[],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],"J2\345\334\336\350\364\225<D\t\305Y\23\366\341!_\351\310\357C\252I\322|\3\$ 18:20:10 select(7,[5],NULL) = 1 (out [5]) 18:20:10 write(5,"Last login: Fri Mar 4 18:19:33 "...,58) = 58 18:20:10 select(7,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,NULL) = 1 (out [5]) 18:21:10 write(5,"\33[?1034h[securityBox@wordpress10"...,41) = 41 18:21:10 select(7,NULL) = 1 (in [4]) 18:21:14 read(4,"e",16384) = 1 18:21:14 select(7,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,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,NULL) = 1 (out [5]) 18:21:14 write(5,1) = 1 18:21:14 select(7,"x",16384) = 1 **more stuff**
更新2
知道我意识到在上次登录后:,当它挂断等待时,你可以按下Ctrl C,它会立即显示命令提示符.因此,看起来有一个过程在启动时花了太长时间.
更新3
我增加了服务器端的调试级别,这里是挂起和等待之前的lates输出:
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
然后过了一会儿,同时出现提示,它会打印:
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,NULL
这是strace -p $PID的输出,其中$PID是ssh程序的pid,同时使连接成为可能.