Fail2Ban – Detects Attacker IP but Doesn’t Ban and Slow Log Reading

debianfail2bannginx

From a few days I'm receiving attacks from some IP addresses to my nginx. I have decided to use fail2ban to ban it automatically, but I have noticed that is not working very well. I can see in logs that is detecting the IP addressess, but is not banning as expected.

My jail file is:

[nginx-40x-req]
enabled  = true
bantime.rndtime = 2800
bantime.increment = true
port     = http,https
filter   = nginx-40x-req
logpath  = /var/log/nginx/access.log
maxretry = 5

and my filter looks like this:

[Definition]
failregex = ^{"status": (400|401|403), "request_time": [0-9\.]+,\s+"remote_addr": "<HOST>",

On my nginx I have added a map to detect its requests and returns 403 when detected. The the logs looks like this:

{"status": 403, "request_time": 0.000,  "remote_addr": "xx.xx.xx.xx", "@timestamp": "2021-09-03T18:32:34+02:00", "type": "nginx", "hostname": "vps-e642f340", "host": "d.itsyjd.com", "uri": "/v2/speed_test", "request": "GET https://d.itsyjd.com/v2/speed_test HTTP/1.1", "request_method": "GET", "request_proto": "http", "request_proto_proxy": "-", "request_uri": "/v2/speed_test", "request_args": "-", "server_proto": "HTTP/1.1", "body_bytes_sent": 552, "http_referer": "-", "http_user_agent": "Mozilla/5.0 (Linux; Android 8.0; MHA-AL00 Build/HUAWEIMHA-AL00; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/57.0.2987.132 MQQBrowser/6.2 TBS/044304 Mobile Safari/537.36 (compatible; Baiduspider/2.0;+http://www.baidu.com/search/spider.html)", "msec": 1630686754.923, "upstream_connect_time": -, "upstream_header_time": -, "upstream_response": -, "pipe": "p", "gzip_ratio": "-", "brotli_ratio": "-", "remote_user": "-", "bad_request": "1"}

On my fail2ban I can see a lot of messages saying that IP address was detected:

2021-09-03 18:34:31,494 fail2ban.filter         [32586]: INFO    [nginx-40x-req] Found xx.xx.xx.xx - 2021-09-03 18:29:33

But it still no banning those IP addresses.

One thing I have noticed is that fail2ban read speed is slower than log speed, so I have started to think that maybe that is the problem, because when those IP are banned and fail2ban reads at real time, then another IP addresses are banned without problem. Max_retry is 5 and all the IP addressess has been detected more than 5 times, so they must be banned.

Anyone knows what I can be doing wrong (because for sure is something that I am not seeing).

Best regards.

EDIT: After writting this message I have seen that is banning, but is working very slow. In about 15 minutes has banned about 4 IP addressess from about 11, when every second they are being detected a lot of times.

EDIT2: Clearing the log with a simple echo "" > <logfile> has triggered the bans.

My fail2ban version is 0.10.2

With the problematic attacker banned and receiving just a few requests, fail2ban is reading in real time and is banning:

2021-09-03 18:46:13,759 fail2ban.filter         [32586]: INFO    [nginx-40x-req] Found XX.XX.XX.XX - 2021-09-03 18:46:13
2021-09-03 18:46:13,909 fail2ban.actions        [32586]: NOTICE  [nginx-40x-req] Ban XX.XX.XX.XX
2021-09-03 18:46:18,855 fail2ban.filter         [32586]: INFO    [nginx-40x-req] Found XX.XX.XX.XX - 2021-09-03 18:46:18
2021-09-03 18:47:07,004 fail2ban.filter         [32586]: INFO    [nginx-40x-req] Found XX.XX.XX.XX - 2021-09-03 18:47:06
2021-09-03 18:48:34,390 fail2ban.filter         [32586]: INFO    [nginx-40x-req] Found XX.XX.XX.XX - 2021-09-03 18:48:34
2021-09-03 18:48:54,230 fail2ban.filter         [32586]: INFO    [nginx-40x-req] Found XX.XX.XX.XX - 2021-09-03 18:48:54
2021-09-03 18:48:54,231 fail2ban.filter         [32586]: INFO    [nginx-40x-req] Found XX.XX.XX.XX - 2021-09-03 18:48:54
2021-09-03 18:48:54,231 fail2ban.filter         [32586]: INFO    [nginx-40x-req] Found XX.XX.XX.XX - 2021-09-03 18:48:54
2021-09-03 18:48:54,335 fail2ban.actions        [32586]: NOTICE  [nginx-40x-req] Ban XX.XX.XX.XX
2021-09-03 18:50:08,488 fail2ban.filter         [32586]: INFO    [nginx-40x-req] Found XX.XX.XX.XX - 2021-09-03 18:50:08

So I still thinking that the problem maybe is the read speed.

EDIT3:

Finally I have upgraded the fail2ban version to 0.11.2, I have added a datepattern and I have changed the address detector. Now seems to read the nginx file a lot faster.

[Definition]
failregex = ^{"status": (400|401|403), "request_time": [0-9\.]+,\s+"remote_addr": "<ADDR>",
datepattern = "@timestamp": "%%Y-%%m-%%dT%%H:%%M:%%S%%z"

Best Answer

  1. It is not advisable to monitor access-log, see fail2ban/wiki :: Best practice especially the part "Reduce parasitic log-traffic".
  2. Inappropriate regexs can also cause that fail2bans "read speed may be slower than log speed", just I don't see your RE is not good. But it can be made faster, just you'd need to change logging format for that. Also specifying of single and precise datepattern may help to speed up the processing.
  3. All in one it could create the known race condition, fail2ban was affected up to v.0.10.5, see https://github.com/fail2ban/fail2ban/issues/2660 for details (the fix was released within v.0.10.6 / v.0.11.2)

Also note the answers to similar issues, for instance https://github.com/fail2ban/fail2ban/issues/3021#issuecomment-834287295.

Related Topic