Date: Sun, 20 Jun 2010 22:55:23 -0400 From: Jerry Bell <jerry@nrdx.com> To: freebsd-questions@freebsd.org Subject: Ssh attack appears to be hanging ssh Message-ID: <4C1ED49B.2000709@nrdx.com>
next in thread | raw e-mail | index | archive | help
I am running 8.1 BETA. My server started getting hammered with brute force ssh login attacks recently. One thing I have noticed is that I see lots of these: Jun 18 23:26:47 www3 sshd[33171]: error: ssh_msg_send: write Jun 18 23:26:47 www3 sshd[33169]: error: ssh_msg_send: write Jun 18 23:26:47 www3 sshd[33172]: error: ssh_msg_send: write Jun 18 23:26:47 www3 sshd[33176]: error: ssh_msg_send: write Jun 18 23:26:47 www3 sshd[33175]: error: ssh_msg_send: write Jun 18 23:26:47 www3 sshd[33170]: error: ssh_msg_send: write Jun 18 23:26:47 www3 sshd[33174]: error: ssh_msg_send: write Jun 18 23:28:30 www3 sshd[33254]: error: ssh_msg_send: write Jun 18 23:28:30 www3 sshd[33255]: error: ssh_msg_send: write in my logs, which roughly correlates to when the problems start. I have sshguard running, so I am thinking that the above messages are happening because ipf has cut off communication with the host. Anyhow, at some point, and for some reason, ssshd stops processing new requests. The sshed process continues to run, but simply does not work. From a the side of a system trying to log in, I see this (logging set to DEBUG in sshd_config: > ssh -v user@www3.stelesys.com OpenSSH_5.2p1 FreeBSD-20090522, OpenSSL 0.9.8k 25 Mar 2009 debug1: Reading configuration data /etc/ssh/ssh_config debug1: Connecting to www3.stelesys.com [69.61.23.66] port 22. debug1: Connection established. debug1: identity file /home/user/.ssh/identity type -1 debug1: identity file /home/user/.ssh/id_rsa type -1 debug1: identity file /home/user/.ssh/id_dsa type -1 ssh_exchange_identification: Connection closed by remote host On the server side, I see this in the debug logs: Jun 20 22:43:11 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 22:43:11 www3 sshd[76171]: debug1: drop connection #10 I happened to catch one in the act... This log snipped starts with sshd being started, is "attacked" by one host and ends with the sshd server locking up: Jun 20 21:44:18 www3 sshd[76171]: debug1: Bind to port 22 on ::. Jun 20 21:44:18 www3 sshd[76171]: debug1: Bind to port 22 on 0.0.0.0. Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: Forked child 76179. Jun 20 21:44:53 www3 sshd[76179]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8 Jun 20 21:44:53 www3 sshd[76179]: debug1: inetd sockets after dupping: 3, 3 Jun 20 21:44:53 www3 sshd[76179]: debug1: res_init() Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: Forked child 76180. Jun 20 21:44:53 www3 sshd[76180]: debug1: rexec start in 5 out 5 newsock 5 pipe 8 sock 9 Jun 20 21:44:53 www3 sshd[76180]: debug1: inetd sockets after dupping: 3, 3 Jun 20 21:44:53 www3 sshd[76180]: debug1: res_init() Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: Forked child 76181. Jun 20 21:44:53 www3 sshd[76181]: debug1: rexec start in 5 out 5 newsock 5 pipe 9 sock 10 Jun 20 21:44:53 www3 sshd[76181]: debug1: inetd sockets after dupping: 3, 3 Jun 20 21:44:53 www3 sshd[76181]: debug1: res_init() Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: Forked child 76182. Jun 20 21:44:53 www3 sshd[76182]: debug1: rexec start in 5 out 5 newsock 5 pipe 10 sock 11 Jun 20 21:44:53 www3 sshd[76182]: debug1: inetd sockets after dupping: 3, 3 Jun 20 21:44:53 www3 sshd[76182]: debug1: res_init() Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: Forked child 76183. Jun 20 21:44:53 www3 sshd[76183]: debug1: rexec start in 5 out 5 newsock 5 pipe 11 sock 12 Jun 20 21:44:53 www3 sshd[76183]: debug1: inetd sockets after dupping: 3, 3 Jun 20 21:44:53 www3 sshd[76183]: debug1: res_init() Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: Forked child 76184. Jun 20 21:44:53 www3 sshd[76184]: debug1: rexec start in 5 out 5 newsock 5 pipe 12 sock 13 Jun 20 21:44:53 www3 sshd[76184]: debug1: inetd sockets after dupping: 3, 3 Jun 20 21:44:53 www3 sshd[76184]: debug1: res_init() Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: Forked child 76185. Jun 20 21:44:53 www3 sshd[76185]: debug1: rexec start in 5 out 5 newsock 5 pipe 13 sock 14 Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: Forked child 76186. Jun 20 21:44:53 www3 sshd[76186]: debug1: rexec start in 5 out 5 newsock 5 pipe 14 sock 15 Jun 20 21:44:53 www3 sshd[76185]: debug1: inetd sockets after dupping: 3, 3 Jun 20 21:44:53 www3 sshd[76185]: debug1: res_init() Jun 20 21:44:53 www3 sshd[76186]: debug1: inetd sockets after dupping: 3, 3 Jun 20 21:44:53 www3 sshd[76186]: debug1: res_init() Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: Forked child 76187. Jun 20 21:44:53 www3 sshd[76187]: debug1: rexec start in 5 out 5 newsock 5 pipe 15 sock 16 Jun 20 21:44:53 www3 sshd[76187]: debug1: inetd sockets after dupping: 3, 3 Jun 20 21:44:53 www3 sshd[76187]: debug1: res_init() Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: Forked child 76188. Jun 20 21:44:53 www3 sshd[76188]: debug1: rexec start in 5 out 5 newsock 5 pipe 16 sock 17 Jun 20 21:44:53 www3 sshd[76188]: debug1: inetd sockets after dupping: 3, 3 Jun 20 21:44:53 www3 sshd[76188]: debug1: res_init() Jun 20 21:44:53 www3 sshd[76183]: debug1: Client protocol version 2.0; client software version libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76183]: debug1: no match: libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76183]: debug1: Enabling compatibility mode for protocol 2.0 Jun 20 21:44:53 www3 sshd[76183]: debug1: Local version string SSH-2.0-OpenSSH_5.4p1 FreeBSD-20100308 Jun 20 21:44:53 www3 sshd[76179]: debug1: Client protocol version 2.0; client software version libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76179]: debug1: no match: libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76179]: debug1: Enabling compatibility mode for protocol 2.0 Jun 20 21:44:53 www3 sshd[76179]: debug1: Local version string SSH-2.0-OpenSSH_5.4p1 FreeBSD-20100308 Jun 20 21:44:53 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:44:53 www3 sshd[76171]: debug1: drop connection #10 Jun 20 21:44:53 www3 sshd[76182]: debug1: Client protocol version 2.0; client software version libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76182]: debug1: no match: libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76182]: debug1: Enabling compatibility mode for protocol 2.0 Jun 20 21:44:53 www3 sshd[76182]: debug1: Local version string SSH-2.0-OpenSSH_5.4p1 FreeBSD-20100308 Jun 20 21:44:53 www3 sshd[76181]: debug1: Client protocol version 2.0; client software version libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76181]: debug1: no match: libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76181]: debug1: Enabling compatibility mode for protocol 2.0 Jun 20 21:44:53 www3 sshd[76181]: debug1: Local version string SSH-2.0-OpenSSH_5.4p1 FreeBSD-20100308 Jun 20 21:44:53 www3 sshd[76185]: debug1: Client protocol version 2.0; client software version libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76185]: debug1: no match: libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76185]: debug1: Enabling compatibility mode for protocol 2.0 Jun 20 21:44:53 www3 sshd[76185]: debug1: Local version string SSH-2.0-OpenSSH_5.4p1 FreeBSD-20100308 Jun 20 21:44:53 www3 sshd[76184]: debug1: Client protocol version 2.0; client software version libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76184]: debug1: no match: libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76184]: debug1: Enabling compatibility mode for protocol 2.0 Jun 20 21:44:53 www3 sshd[76184]: debug1: Local version string SSH-2.0-OpenSSH_5.4p1 FreeBSD-20100308 Jun 20 21:44:53 www3 sshd[76186]: debug1: Client protocol version 2.0; client software version libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76186]: debug1: no match: libssh-0.4.3 Jun 20 21:44:53 www3 sshd[76186]: debug1: Enabling compatibility mode for protocol 2.0 Jun 20 21:44:53 www3 sshd[76186]: debug1: Local version string SSH-2.0-OpenSSH_5.4p1 FreeBSD-20100308 Jun 20 21:44:54 www3 sshd[76188]: debug1: Client protocol version 2.0; client software version libssh-0.4.3 Jun 20 21:44:54 www3 sshd[76188]: debug1: no match: libssh-0.4.3 Jun 20 21:44:54 www3 sshd[76188]: debug1: Enabling compatibility mode for protocol 2.0 Jun 20 21:44:54 www3 sshd[76188]: debug1: Local version string SSH-2.0-OpenSSH_5.4p1 FreeBSD-20100308 Jun 20 21:44:54 www3 sshd[76187]: debug1: Client protocol version 2.0; client software version libssh-0.4.3 Jun 20 21:44:54 www3 sshd[76187]: debug1: no match: libssh-0.4.3 Jun 20 21:44:54 www3 sshd[76187]: debug1: Enabling compatibility mode for protocol 2.0 Jun 20 21:44:54 www3 sshd[76187]: debug1: Local version string SSH-2.0-OpenSSH_5.4p1 FreeBSD-20100308 Jun 20 21:44:56 www3 sshguard[71398]: Matched address 222.177.24.35:4 attacking service 100 Jun 20 21:44:56 www3 last message repeated 3 times Jun 20 21:44:56 www3 sshguard[71398]: First sight of offender '222.177.24.35:4', adding to offenders list. Jun 20 21:44:56 www3 sshguard[71398]: Setting environment: SSHG_ADDR=222.177.24.35;SSHG_ADDRKIND=4;SSHG_SERVICE=100. Jun 20 21:44:56 www3 sshd[76184]: debug1: PAM: initializing for "ircd" Jun 20 21:44:56 www3 sshd[76185]: debug1: PAM: initializing for "ircd" Jun 20 21:44:56 www3 sshd[76186]: debug1: PAM: initializing for "ircd" Jun 20 21:44:56 www3 sshd[76183]: debug1: PAM: initializing for "ircd" Jun 20 21:44:56 www3 sshd[76179]: debug1: PAM: initializing for "ircd" Jun 20 21:44:56 www3 sshd[76184]: debug1: PAM: setting PAM_RHOST to "222.177.24.35" Jun 20 21:44:56 www3 sshd[76181]: debug1: PAM: initializing for "ircd" Jun 20 21:44:56 www3 sshd[76182]: debug1: PAM: initializing for "ircd" Jun 20 21:44:56 www3 sshd[76186]: debug1: PAM: setting PAM_RHOST to "222.177.24.35" Jun 20 21:44:56 www3 sshd[76185]: debug1: PAM: setting PAM_RHOST to "222.177.24.35" Jun 20 21:44:56 www3 sshd[76183]: debug1: PAM: setting PAM_RHOST to "222.177.24.35" Jun 20 21:44:56 www3 sshd[76179]: debug1: PAM: setting PAM_RHOST to "222.177.24.35" Jun 20 21:44:56 www3 sshd[76181]: debug1: PAM: setting PAM_RHOST to "222.177.24.35" Jun 20 21:44:56 www3 sshd[76182]: debug1: PAM: setting PAM_RHOST to "222.177.24.35" Jun 20 21:44:56 www3 sshguard[71398]: Run command "if test $SSHG_ADDRKIND != 4; then exit 1 ; fi ; TMP=`mktemp /tmp/ipfconf.XX` && awk '1 ; /^##sshguard-begin##$/ { print "block in quick proto tcp from '"$SSHG_ADDR"' to any" }' </etc/ipf.rules > $TMP && mv $TMP /etc/ipf.rules && /sbin/ipf -Fa && /sbin/ipf -f /etc/ipf.rules": exited 0. Jun 20 21:44:56 www3 sshguard[71398]: Matched address 222.177.24.35:4 attacking service 100 Jun 20 21:44:56 www3 last message repeated 3 times Jun 20 21:44:56 www3 sshguard[71398]: Setting environment: SSHG_ADDR=222.177.24.35;SSHG_ADDRKIND=4;SSHG_SERVICE=100. Jun 20 21:44:56 www3 sshguard[71398]: Run command "if test $SSHG_ADDRKIND != 4; then exit 1 ; fi ; TMP=`mktemp /tmp/ipfconf.XX` && awk '1 ; /^##sshguard-begin##$/ { print "block in quick proto tcp from '"$SSHG_ADDR"' to any" }' </etc/ipf.rules > $TMP && mv $TMP /etc/ipf.rules && /sbin/ipf -Fa && /sbin/ipf -f /etc/ipf.rules": exited 0. Jun 20 21:44:56 www3 sshguard[71398]: Matched address 222.177.24.35:4 attacking service 100 Jun 20 21:44:56 www3 last message repeated 3 times Jun 20 21:44:56 www3 sshguard[71398]: Setting environment: SSHG_ADDR=222.177.24.35;SSHG_ADDRKIND=4;SSHG_SERVICE=100. Jun 20 21:44:56 www3 sshguard[71398]: Run command "if test $SSHG_ADDRKIND != 4; then exit 1 ; fi ; TMP=`mktemp /tmp/ipfconf.XX` && awk '1 ; /^##sshguard-begin##$/ { print "block in quick proto tcp from '"$SSHG_ADDR"' to any" }' </etc/ipf.rules > $TMP && mv $TMP /etc/ipf.rules && /sbin/ipf -Fa && /sbin/ipf -f /etc/ipf.rules": exited 0. Jun 20 21:44:56 www3 sshguard[71398]: Matched address 222.177.24.35:4 attacking service 100 Jun 20 21:44:56 www3 sshguard[71398]: Matched address 222.177.24.35:4 attacking service 100 Jun 20 21:45:33 www3 sshd[76171]: debug1: fd 5 clearing O_NONBLOCK Jun 20 21:45:33 www3 sshd[76171]: debug1: drop connection #10 After some period of time, it *sometimes* starts accepting connections again. Any ideas what is happening here? Thanks, Jerry
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?4C1ED49B.2000709>