Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Why does fail2ban not respond immediately to the need for a ban? #3021

Closed
madTeddy opened this issue May 7, 2021 · 4 comments
Closed

Why does fail2ban not respond immediately to the need for a ban? #3021

madTeddy opened this issue May 7, 2021 · 4 comments
Labels
how-to

Comments

@madTeddy
Copy link

madTeddy commented May 7, 2021 •
edited by sebres

I noticed that fail2ban does not immediately respond to the ban, and after the ban, the IP still makes requests. Is this a problem with the speed of reading logs or what?
Here is example log:

within 2 seconds, 20x found, ban, 20x found ... 
2021-05-06 19:42:21,785 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:21
2021-05-06 19:42:21,825 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:21
2021-05-06 19:42:21,844 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:21
2021-05-06 19:42:21,864 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:21
2021-05-06 19:42:21,892 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:21
2021-05-06 19:42:21,914 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:21
2021-05-06 19:42:21,934 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:21
2021-05-06 19:42:21,954 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:21
2021-05-06 19:42:21,977 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:21
2021-05-06 19:42:22,001 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:21
2021-05-06 19:42:22,030 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,054 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,103 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,122 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,160 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,180 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,202 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,225 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,245 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,266 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,286 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,307 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,327 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,341 fail2ban.actions        [237787]: NOTICE  [apache-4xx] Ban 51.75.26.30
2021-05-06 19:42:22,350 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,377 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,411 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,437 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,458 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,489 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,526 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,549 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,571 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,592 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,611 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,631 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,652 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,676 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,699 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,718 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,738 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,759 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,782 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,801 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,822 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,842 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:42:22,878 fail2ban.filter         [237787]: INFO    [apache-4xx] Found 51.75.26.30 - 2021-05-06 19:42:22
2021-05-06 19:57:23,911 fail2ban.actions        [237787]: NOTICE  [apache-4xx] Unban 51.75.26.30

My filter works here, and it should work after 5 attempts. When less fast requests occur, everything works more or less normally.

[apache-4xx]
enabled = true
port = http,https
filter = apache-4xx
logpath = %(apache_access_log)s
bantime = 15m
findtime = 30
maxretry = 5

I even edited the ufw action because of this problem, so that when this IP is blocked, it kills all connections to it. But somehow it doesn't really work, so the only assumption is that either fail2ban is slow to respond to logs, or the logs themselves are added instantly.
Do you have any recommendations about this, or is this a normal situation?
@sebres
Copy link
Contributor

sebres commented May 7, 2021 •
edited

Is this a problem with the speed of reading logs or what?

Yes, it is indeed a timing issue, but not directly related to the speed of reading logs.
First of all it can be simple latencies in chain detect -> reaction -> ban -> intruder unable to connect.
For instance the scenario: the bot made 50 attempts in the time between fail2ban noticed the attempts up to the ban really happened.
But...
It can be also affected by several issues:

  1. since your jail monitoring access log (which is by the way not really suitable for that), it has per definition certain latency, due to operation of web-server access logging:
    • the log entry is not written to the time point of arriving request, but when response is sending (it needs for example the response code in log), so there may be several pending requests of the bot already reached the web-server before fail2ban has even any chance to notice them (they are simply not yet in log);
    • there are probably many other (parasitic in sense of this jail) messages totally not interesting in this jail, but needed to be processed nevertheless (the time of finding a failure grows by factor N*M, where N is count of bypassed messages per every found failure and M is count of failregex you have in the filter or jail).
  2. there was some bottleneck or else a race condition affecting banning by lot of failures (see Why does not bans, but sees fails #2660 for details), this is fixed with release 0.11.2 and 0.10.6 (which version do you actually use?).
  3. because ufw is mentioned, I can imagine that there are some whitelisting rules (e. g. configured in ufw by default), which would ignore already established connections (see Fail2ban says already banned an ip but the ip can still visit webserver #2545 (comment) and below), so if it is for example a keep-alive connection, the ban will not work (it will only affect new connections), so the evildoer is able to continue the attempts in already established connection.
  4. your filter (datepattern, pref- or failregex, etc) can be not optimal, so the detection is indeed a bit slow, try to use optimized, more precise and anchored regex and pattern, to reduce parasite log traffic etc. See wiki :: Best practice for more information.

Or it is simply all that in sum together and the fewer problems you have at end the faster it will become, and it'd change not linear, so after each solved issue it'd be significantly faster than after previous (it is like a snowball, because every small latency let do the intruder more attempts, which would cause more latencies etc).

I even edited the ufw action because of this problem, so that when this IP is blocked, it kills all connections to it...

Well, ufw is a wrapper over native net-filters (via its backend modules), so indirectly the usage of it for banning is exactly vice-versa what one would do (I don't know any pros of usage of ufw actions, but know many cons).
So let's try to describe what happens if the ban occurs: fail2ban will invoke ufw command (basically python application), so starts python, python will load ufw modules and start command line interface of it, then ufw will register the rule inside its own structures and hereafter would invoke its configured backend to create a rule in native net-filter subsystem. All this needs some time to be accomplished.
And hereafter you'll invoke ss, killcx, cutter or whatever else killing established connections, so the latency between generate a ban and ban really occurred can be significant.
I don't use ufw, so I cannot measure how long a ban with ufw action would take.

Do you have any recommendations about this

Try to resolve as many as possible of 4 points mentioned above and probably switch to other banning action using native net-filter i. e. iptables-ipset or nftables depending on your system and kernel.

or is this a normal situation?

No it is definitely not normal. Even on most busy systems I never saw more that 3 - 5 attempts after ban, and even that was rather an exception (mostly it is either nothing or rare one or two fails) such as some very "clever" evildoers trying many attempts over multiple connections at once.

@madTeddy
Copy link
Author

madTeddy commented May 7, 2021

Ok, thank you for the explanation, I'll try your options.
By the way, my fail2ban version is 0.11.1 (atleast latest available on the ubuntu 20)

@madTeddy madTeddy closed this as completed May 7, 2021
@sebres sebres added the how-to label May 7, 2021
@SBK79
Copy link

SBK79 commented May 26, 2022

Ok, thank you for the explanation, I'll try your options. By the way, my fail2ban version is 0.11.1 (atleast latest available on the ubuntu 20)

hi i have the same issue on my server
did you find any solution?!

@madTeddy
Copy link
Author

Ok, thank you for the explanation, I'll try your options. By the way, my fail2ban version is 0.11.1 (atleast latest available on the ubuntu 20)

hi i have the same issue on my server did you find any solution?!

A year later, I don't remember what I did exactly. I did every step that sebres listed + separate file for the errors which filter is waiting. It didn't fixed the problem completely and I just stopped worrying about it 🙃

@sebres sebres mentioned this issue Oct 24, 2022
Closed
3 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
how-to
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@sebres @madTeddy @SBK79