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>