Ubuntu – What are fail2ban’s log iptables “returned NNN” entries? (Fail2ban is failing to ban)

fail2baniptables

In my fail2ban.log there are some entries the meaning of which I don't understand (and haven't found searching around)…
I have several "jails", and I have created one particular one that bans IP's when they try to connect to web server searching for scripts, I guess…. These are some entries from a given IP (sorry about the long log):

user@computer:/var/log$ cat apache2/access.log.1 |grep 58.218.199.147
58.218.199.147 - - [27/Mar/2011:09:03:37 +0200] "GET http://www.mtajp.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [27/Mar/2011:11:32:16 +0200] "GET http://ppcfinder.net/judge.php HTTP/1.1" 404 432 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [27/Mar/2011:11:34:57 +0200] "GET http://98.126.15.13/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [27/Mar/2011:14:04:08 +0200] "GET http://58.218.199.147:7182/judge.php HTTP/1.1" 404 432 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [27/Mar/2011:19:02:37 +0200] "GET http://www.shopsline.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [27/Mar/2011:21:33:17 +0200] "GET http://98.126.64.106/judge123.php HTTP/1.1" 404 435 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [28/Mar/2011:14:59:49 +0200] "GET http://www.racross.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [28/Mar/2011:17:28:32 +0200] "GET http://98.126.64.106/judge123.php HTTP/1.1" 404 435 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [29/Mar/2011:00:58:17 +0200] "GET http://www.racross.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [29/Mar/2011:05:00:53 +0200] "GET http://www.mtajp.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [29/Mar/2011:09:57:48 +0200] "GET http://www.shopsline.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [29/Mar/2011:12:40:06 +0200] "GET http://www.mtajp.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [29/Mar/2011:15:01:01 +0200] "GET http://www.infodownload.info/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.204.110 - - [29/Mar/2011:15:28:42 +0200] "GET http://58.218.199.147:7182/judge.php HTTP/1.1" 404 432 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [29/Mar/2011:20:01:14 +0200] "GET http://www.cjpjp.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [29/Mar/2011:22:31:50 +0200] "GET http://www.travelimgusa.com/ip.php HTTP/1.1" 404 429 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [30/Mar/2011:01:00:05 +0200] "GET http://98.126.15.13/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [30/Mar/2011:03:31:05 +0200] "GET http://www.infodownload.info/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [30/Mar/2011:11:02:43 +0200] "GET http://piceducation.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [30/Mar/2011:13:33:24 +0200] "GET http://ppcfinder.net/judge.php HTTP/1.1" 404 432 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [30/Mar/2011:16:01:04 +0200] "GET http://www.shopsline.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [30/Mar/2011:21:04:31 +0200] "GET http://www.racross.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [31/Mar/2011:04:35:55 +0200] "GET http://www.racross.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [31/Mar/2011:12:03:43 +0200] "GET http://www.mtajp.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [31/Mar/2011:14:34:40 +0200] "GET http://www.eduju.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [31/Mar/2011:19:36:04 +0200] "GET http://58.218.204.110:7182/judge.php HTTP/1.1" 404 432 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [31/Mar/2011:22:05:48 +0200] "GET http://ppcfinder.net/judge.php HTTP/1.1" 404 432 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [01/Apr/2011:03:11:14 +0200] "GET http://58.218.199.147:7182/judge.php HTTP/1.1" 404 432 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [01/Apr/2011:09:52:09 +0200] "GET http://www.travelimgusa.com/ip.php HTTP/1.1" 404 429 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [01/Apr/2011:12:15:59 +0200] "GET http://www.racross.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [01/Apr/2011:14:39:47 +0200] "GET http://piceducation.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [01/Apr/2011:17:06:09 +0200] "GET http://www.shopsline.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [01/Apr/2011:20:45:50 +0200] "GET http://www.cjpjp.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [01/Apr/2011:23:11:21 +0200] "GET http://www.seektwo.com/proxy-1.php HTTP/1.1" 404 434 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [02/Apr/2011:01:37:16 +0200] "GET http://www.infodownload.info/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [02/Apr/2011:10:25:15 +0200] "GET http://98.126.64.106/judge123.php HTTP/1.1" 404 435 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [02/Apr/2011:12:51:45 +0200] "GET http://58.218.204.110:7182/judge.php HTTP/1.1" 404 432 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [02/Apr/2011:15:18:07 +0200] "GET http://www.racross.com/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [02/Apr/2011:17:43:43 +0200] "GET http://www.travelimgusa.com/ip.php HTTP/1.1" 404 429 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
58.218.199.147 - - [02/Apr/2011:22:35:49 +0200] "GET http://www.infodownload.info/proxyheader.php HTTP/1.1" 404 438 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"

To prevent this, I have set up a custom jail in /etc/fail2ban/jail.local:

[apache-404-slowattackers]
enabled = true
port = http,https
filter = apache-404-slowattackers
logpath = /var/log/apache*/*access.log
bantime = 344000
findtime = 172800
maxretry = 12

And this is /etc/fail2ban/filter.d/apache-404-slowattackers.conf 

[Definition]
failregex = (?P<host>[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}) .+ 404 [0-9]+ "
ignoreregex =

(same as the default /etc/fail2ban/filter.d/apache-404.conf filter)

Fail2ban does ban some IP's when they work against some filters, but not against my custom one. Some lines from /var/log/fail2ban.log:

2011-03-31 20:46:29,982 fail2ban.jail   : INFO   Jail 'apache-404' started
[...]
2011-03-31 20:46:30,922 fail2ban.jail   : INFO   Jail 'courierauth' started
2011-03-31 20:46:31,026 fail2ban.jail   : INFO   Jail 'apache-404-slowattackers' started
2011-03-31 20:46:31,038 fail2ban.actions.action: ERROR  iptables -N fail2ban-apache-404-slowattackers
iptables -A fail2ban-apache-404-slowattackers -j RETURN
iptables -I INPUT -p tcp -m multiport --dports http,https -j fail2ban-apache-404-slowattackers returned 200
2011-04-01 21:39:16,558 fail2ban.actions: WARNING [apache-404] Ban 211.75.185.152
2011-04-01 22:09:17,245 fail2ban.actions: WARNING [apache-404] Unban 211.75.185.152
2011-04-02 15:18:08,544 fail2ban.actions: WARNING [apache-404-slowattackers] Ban 58.218.199.147
2011-04-02 15:18:08,684 fail2ban.actions.action: ERROR  iptables -n -L INPUT | grep -q fail2ban-apache-404-slowattackers returned 100
2011-04-02 15:18:08,685 fail2ban.actions.action: ERROR  Invariant check failed. Trying to restore a sane environment
2011-04-02 15:18:08,698 fail2ban.actions.action: ERROR  iptables -D INPUT -p tcp -m multiport --dports http,https -j fail2ban-apache-404-slowattackers
iptables -F fail2ban-apache-404-slowattackers
iptables -X fail2ban-apache-404-slowattackers returned 200
2011-04-02 15:18:08,712 fail2ban.actions.action: ERROR  iptables -N fail2ban-apache-404-slowattackers
iptables -A fail2ban-apache-404-slowattackers -j RETURN
iptables -I INPUT -p tcp -m multiport --dports http,https -j fail2ban-apache-404-slowattackers returned 200
2011-04-02 15:18:08,721 fail2ban.actions.action: ERROR  iptables -n -L INPUT | grep -q fail2ban-apache-404-slowattackers returned 100
2011-04-02 15:18:08,722 fail2ban.actions.action: CRITICAL Unable to restore environment
2011-04-02 23:20:50,480 fail2ban.actions: WARNING [courierauth] Ban 84.225.81.193
2011-04-02 23:50:50,777 fail2ban.actions: WARNING [courierauth] Unban 84.225.81.193
2011-04-03 03:23:58,876 fail2ban.actions: WARNING [courierauth] Ban 74.143.34.38
2011-04-03 03:53:59,155 fail2ban.actions: WARNING [courierauth] Unban 74.143.34.38

As you can see, something fails when trying to ban an attack against my custom filter (so such attacks are detected, but not correctly banned, I don't know why)

So my questions would be:

  • Are those errors a fail2ban problem or an iptables one?
  • What do those errors mean?… and… how can they be avoided?
  • What am I doing wrong, or how could I correct this behaviour?

EDIT:

Maybe this is useful to answer the question (or not), but iptables -L shows no trace of my apache-404-slowattackers, while other jails are present:

user@computer:~$ sudo iptables -L
Chain INPUT (policy ACCEPT)
target     prot opt source               destination         
fail2ban-courierauth  tcp  --  anywhere             anywhere            multiport dports smtp,ssmtp,imap2,imap3,imaps,pop3,pop3s 
fail2ban-apache  tcp  --  anywhere             anywhere            multiport dports www,https 
fail2ban-sasl  tcp  --  anywhere             anywhere            multiport dports smtp,ssmtp,imap2,imap3,imaps,pop3,pop3s 
fail2ban-postfix  tcp  --  anywhere             anywhere            multiport dports smtp,ssmtp 
fail2ban-ssh  tcp  --  anywhere             anywhere            multiport dports ssh 
fail2ban-couriersmtp  tcp  --  anywhere             anywhere            multiport dports smtp,ssmtp 
fail2ban-apache-overflows  tcp  --  anywhere             anywhere            multiport dports www,https 
fail2ban-apache-multiport  tcp  --  anywhere             anywhere            multiport dports www,https 
fail2ban-ssh-ddos  tcp  --  anywhere             anywhere            multiport dports ssh 
fail2ban-apache-404  tcp  --  anywhere             anywhere            multiport dports www,https 
fail2ban-pam-generic  tcp  --  anywhere             anywhere            
fail2ban-apache-noscript  tcp  --  anywhere             anywhere            multiport dports www,https 

Chain FORWARD (policy ACCEPT)
target     prot opt source               destination         

Chain OUTPUT (policy ACCEPT)
target     prot opt source               destination         

Chain fail2ban-apache (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-apache-404 (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-apache-multiport (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-apache-noscript (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-apache-overflows (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-courierauth (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-couriersmtp (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-pam-generic (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-postfix (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-sasl (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-ssh (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere            

Chain fail2ban-ssh-ddos (1 references)
target     prot opt source               destination         
RETURN     all  --  anywhere             anywhere

Does this give any further clue?

Best Answer

I think I found why it is failing, but, as a bounty has been set, I'll wait for it to finish before writing down the answer, thus offering other users to try and answer the question... (@Moderators: Is this OK? What should I do otherwise?)

Edit:

As nobody answered, I'll jot down what I discovered. Two things were wrong about my setup (actually one about my setup and one about fail2ban itself):

1.- If I try

sudo iptables -N fail2ban-apache-404-slowattackers

which is the command fail2ban issues, I get the following message:

iptables v1.4.4: chain name `fail2ban-apache-404-slowattackers' too long (must be under 30 chars)

If this had been logged to fail2ban.log, I would have known what wass going wrong (but it wasn't logged). So, changing the name of my custom filter to something shorter (for instance apache-404-slowatt) did the trick, as iptable chain name becomes below 30 characters.

2.- There's a (seemingly) faulty fail2ban script that apparently 'runs too quickly', so I found a workaround.

Quoting: I had multiple fail2ban.action.action ERROR on startup/restart. It seems there was a "race" condition with iptables. I solved the problem completely on my system by editing /usr/bin/fail2ban-client and adding a time.sleep(0.1):

def __processCmd(self, cmd, showRet = True):
    beautifier = Beautifier()
    for c in cmd:
        time.sleep(0.1)
        beautifier.setInputCmd(c)
Related Question