Understanding fail2ban mechanisms

Question

• Apache 2.4

• Fail2ban 0.9.6

  Jail.local

[with_ip_only]
Maxretry = 3
Findtime = 600
Bantime= 60000
Banaction = iptables-allports

I have this guy [46.xxx] scanning my server and I’m wondering why fail2ban is reporting already ban for the last 3 occurrences.

Apache logs

   91.196.50.33 - - [10/Jan/2018:01:09:57 +0100] "GET http://testp3.pospr.waw.pl/testproxy.php HTTP/1.1" 302 508 "-" "Mozilla/5.0 (Windows NT 5.1; rv:32.0) Gecko/20100101 Firefox/31.0"
   141.8.132.40 - - [10/Jan/2018:01:40:05 +0100] "GET /robots.txt HTTP/1.1" 302 572 "-" "Mozilla/5.0 (compatible; YandexBot/3.0; +http://yandex.com/bots)"
   141.8.132.19 - - [10/Jan/2018:01:40:09 +0100] "GET / HTTP/1.1" 302 572 "-" "Mozilla/5.0 (compatible; YandexBot/3.0; +http://yandex.com/bots)"
   5.188.87.7 - - [10/Jan/2018:01:49:50 +0100] "GET / HTTP/1.0" 302 528 "-" "Mozilla/5.0"
   91.194.91.20 - - [10/Jan/2018:02:10:46 +0100] "GET /.well-known/pki-validation/3DAD39418D3F24D0A6FF8D853123CD9A.txt HTTP/1.1" 404 507 "-" "COMODO DCV"
   209.126.136.4 - - [10/Jan/2018:05:15:06 +0100] "GET / HTTP/1.1" 302 501 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.133 Safari/537.36"
   46.234.217.87 - - [10/Jan/2018:07:00:09 +0100] "HEAD http://m.y.i.p:80/mysql/admin/ HTTP/1.1" 302 239 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:10 +0100] "HEAD http://m.y.i.p:80/mysql/dbadmin/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:10 +0100] "HEAD http://m.y.i.p:80/mysql/sqlmanager/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:10 +0100] "HEAD http://m.y.i.p:80/mysql/mysqlmanager/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:10 +0100] "HEAD http://m.y.i.p:80/phpmyadmin/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:10 +0100] "HEAD http://m.y.i.p:80/phpMyadmin/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:10 +0100] "HEAD http://m.y.i.p:80/phpMyAdmin/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:10 +0100] "HEAD http://m.y.i.p:80/phpmyAdmin/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:10 +0100] "HEAD http://m.y.i.p:80/phpmyadmin2/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:11 +0100] "HEAD http://m.y.i.p:80/phpmyadmin3/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:11 +0100] "HEAD http://m.y.i.p:80/phpmyadmin4/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   46.234.217.87 - - [10/Jan/2018:07:00:11 +0100] "HEAD http://m.y.i.p:80/2phpmyadmin/ HTTP/1.1" 302 238 "-" "Mozilla/5.0 Jorgee"
   52.41.211.72 - - [10/Jan/2018:07:21:08 +0100] "GET / HTTP/1.1" 302 522 "http://www.google.com/search?hl=fr&q=dictionary+english" "Magic Browser"
   192.95.50.93 - - [10/Jan/2018:08:17:16 +0100] "GET /w00tw00t.at.ISC.SANS.DFind:) HTTP/1.1" 400 0 "-" "-"

Fail2ban log

2018-01-10 07:00:09,900 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:10,109 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:10,513 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:10,585 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:10,688 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:10,755 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:10,820 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:10,883 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:10,966 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:11,005 fail2ban.actions        [5138]: NOTICE  [with_ip_only] Ban 46.234.217.87
2018-01-10 07:00:11,012 fail2ban.filter         [5138]: INFO    [f2b-loop1] Found 46.234.217.87
2018-01-10 07:00:11,014 fail2ban.filter         [5138]: INFO    [f2b-loop2] Found 46.234.217.87
2018-01-10 07:00:11,023 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:11,086 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:11,169 fail2ban.filter         [5138]: INFO    [with_ip_only] Found 46.234.217.87
2018-01-10 07:00:11,333 fail2ban.actions        [5138]: NOTICE  [with_ip_only] 46.234.217.87 already banned
2018-01-10 07:00:12,337 fail2ban.actions        [5138]: NOTICE  [with_ip_only] 46.234.217.87 already banned
2018-01-10 07:00:13,339 fail2ban.actions        [5138]: NOTICE  [with_ip_only] 46.234.217.87 already banned

My guesses are:

• timing is too short to have the iptables rule created and reject this ip.
• All those requests reside inside the same tcp session so even if the iptables rule is created already opened tcp sessions won’t be cut(rejected) by iptables
• anything else ?

Thanks for any input. Matth

Answer 1

From Fail2ban team:

You can ignore the message already banned if they occurred inside short time after the ban, because filter can still catch failures, that were made in LOG-file before IP was banned (iptables entry not yet applied);
The latency of v.0.9 is relative large (up to several seconds), for example in the v.0.10 you should see it very rarely.

But if you'll get this message later again (e. g. minute after ban), that something is wrong in your action-config (IP is not really banned and can connect again).

Source: Understanding fail2ban mechanisms with iptables