Resolved How my server shoot in its feets (thanks to fail2ban and myself)

[Sergio Manzi]

This evening I was about going out to have my drink (there was a time it was a real drink, but now it is just plain sparkling water, ouch!), when all the hell broke lose: Amazon health checks galore, all sites down on one of my new Plesk servers. Not bad for the second day of official operations, I guess...

I checked all the sites and indeed all of them were giving "503 Bad Gateway".

Check list:

• Access Plesk: it works, good!
• ssh to the host: OK!
  
• Restart nginx: nein, same thing
  
• Restart Apache: no... doesn't change a thing...
  
• /usr/local/psa/admin/sbin/httpdmng --reconfigure-all, and restart the servers again: negative
• PANIC!

I switched to "panic mode", reconfigured all DNS to the backup server (thanks God I have it!), all was good and I took my time to figure out what it could be, after making a snapshot of my failing server, just in case.

Well, after examining my proxy_error_log files it was clear that nginx was unable to talk to Apache: "Connection refused". Connection refused??? Why? The proverbial light bulb (10W, nothing more...) lit on my head: check fail2ban, Sergio...

Sure enough, my server IP address was banned, and the reason was the "apache-badbots" jail!

Apparently that jail bans the downstream nginx server instead of the original culprit, but here I leave the word to official Plesk persons, to verify if this is indeed the case, as I think.

In the meantime I:

• Disabled that jail
• Added my server IP address to the trusted ones (good practice, I think, that I didn't followed, although 127.0.0.1 was in there...)

Can someone please confirm that that jail is broken and suggest a way to fix it?

TIA,

Sergio

P.S.: CentOS Linux 7.2.1511 (Core)‬, Plesk 12.5.30 Update #42

 

[IgorG]

Probably that there was something wrong with mod_rpaf/remoteip Apache module. If it was not loaded for some reasons, all requests in Apache log became local and autoban happened.

 

[Sergio Manzi]

Hi, IgorG!

Can you please point me to the log file to examine for determining if there was indeed an mod_rpaf / mod_remoteip hiccup?
Are you sure the rule for plesk-apache-badbots is correct and it should take into account the client IP address?

Thanks,

Sergio

 

[IgorG]

You can check that module is loaded with

# apachectl -t -D DUMP_MODULES | grep rpaf
Syntax OK
rpaf_module (shared)

# httpd -v
Server version: Apache/2.2.15 (Unix)

 

[Sergio Manzi]

Apparently I don't have mod_rpaf, but I have mod_remoteip:

# apachectl -t -D DUMP_MODULES | grep rpaf
# apachectl -t -D DUMP_MODULES | grep remoteip
remoteip_module (shared)
# httpd -v
Server version: Apache/2.4.6 (CentOS)
Server built: Jul 18 2016 15:30:14
#

Now I would like to investigate why, at the time of the incident, it let the server IP slip at the place of the client IP. My concern is if this could had been a deliberate action from "the outside". Could it be that somebody from the outside had made a request spoofing my IP address with the deliberate intent of "poisoning" my fail2ban?

Thanks for your help,

Sergio

P.S.: I suppose that the fact that I have mod_remoteip instead of mod_rpaf is due to my original server OS configuration (CentOS 7.2) before installing Plesk, right? Would it be better for me switching to mod_rpaf?

 

[Sergio Manzi]

Some more information:

I noticed that the jail that triggered my issue (plesk-apache-badbot) is based on the following log files: /var/www/vhosts/system/*/logs/*access*log

So I "grepped" all those files in search of my server public ip address (say 123.123.123.123...) and, amazingly, there was none in there, apart few expected accesses due to a scheduled "wget" that has the purpose of triggering an automatic backup of a particular site (and none of those was around the time and not even on the day of the incident).

So, you'll forgive me for being insistent, but I think something went wrong with the jail itself...

Is there somewhere a fail2ban log where I can look for detail about the triggering of that jail at the time of the incident?

Thanks!

Sergio

P.S.: Don't worry: I found the fail2ban logs (in /var/log of course... ), and I'm going to examine them (after my evening drink! )

 

[Sergio Manzi]

Here it is what I found:

Apparently fail2ban has found my IP address "somewhere" and decided to ban it, but few minutes later changed its mind and tried to "unban". That, unhappily, failed.
After that I have a looooooooooooooooooooooong list of errors (pages in the log, of which I report here only the first few)

Then, some minutes later, the situation seems to have "normalized" and I don't have any more errors in the log.

Here is a snippet of the log starting from where that jali "triggered" (I have changed my public IP address with "123.123.123.123" and another unknown one with "xxx.yyy.46.51"):

2016-08-02 16:41:34,026 fail2ban.filter  [22509]: INFO  [plesk-apache-badbot] Found 123.123.123.123
2016-08-02 16:41:34,694 fail2ban.actions  [22509]: NOTICE  [plesk-apache-badbot] Ban 123.123.123.123
2016-08-02 16:41:35,642 fail2ban.filter  [22509]: INFO  [recidive] Found 123.123.123.123
2016-08-02 16:43:03,012 fail2ban.filter  [22509]: INFO  [ssh] Found xxx.yyy.46.51
2016-08-02 16:43:05,023 fail2ban.filter  [22509]: INFO  [ssh] Found xxx.yyy.46.51
2016-08-02 16:45:57,229 fail2ban.filter  [22509]: INFO  [ssh] Found xxx.yyy.46.51
2016-08-02 16:45:59,251 fail2ban.filter  [22509]: INFO  [ssh] Found xxx.yyy.46.51
2016-08-02 16:47:14,431 fail2ban.server  [22509]: INFO  Stopping all jails
2016-08-02 16:47:15,283 fail2ban.actions  [22509]: NOTICE  [plesk-apache-badbot] Unban 123.123.123.123
2016-08-02 16:47:15,389 fail2ban.action  [22509]: ERROR  iptables -n -L INPUT | grep -q 'f2b-BadBots[ \t]' -- stdout: ''
2016-08-02 16:47:15,390 fail2ban.action  [22509]: ERROR  iptables -n -L INPUT | grep -q 'f2b-BadBots[ \t]' -- stderr: ''
2016-08-02 16:47:15,390 fail2ban.action  [22509]: ERROR  iptables -n -L INPUT | grep -q 'f2b-BadBots[ \t]' -- returned 1
2016-08-02 16:47:15,390 fail2ban.CommandAction  [22509]: ERROR  Invariant check failed. Trying to restore a sane environment
2016-08-02 16:47:15,495 fail2ban.action  [22509]: ERROR  iptables -D INPUT -p tcp -m multiport --dports http,https,7080,7081 -j f2b-BadBots
iptables -F f2b-BadBots
iptables -X f2b-BadBots -- stdout: ''
2016-08-02 16:47:15,496 fail2ban.action  [22509]: ERROR  iptables -D INPUT -p tcp -m multiport --dports http,https,7080,7081 -j f2b-BadBots
iptables -F f2b-BadBots
iptables -X f2b-BadBots -- stderr: "iptables v1.4.21: Couldn't load target `f2b-BadBots':No such file or directory\n\nTry `iptables -h' or 'iptables --help' for more information.\niptables: No chain/target/match by that name.\niptables: No chain/target/match by that name.\n"
2016-08-02 16:47:15,496 fail2ban.action  [22509]: ERROR  iptables -D INPUT -p tcp -m multiport --dports http,https,7080,7081 -j f2b-BadBots
iptables -F f2b-BadBots
iptables -X f2b-BadBots -- returned 1
2016-08-02 16:47:15,496 fail2ban.actions  [22509]: ERROR  Failed to execute unban jail 'plesk-apache-badbot' action 'iptables-multiport' info '{'matches': u'123.123.123.123 - - [02/Aug/2016:16:41:32 +0000] "GET /manager/html HTTP/1.0" 404 210 "-" "Mozilla/3.0 (compatible; Indy Library)"', 'ip': '123.123.123.123', 'time': 1470156094.694597, 'failures': 1}': Error stopping action

... pages and pages of further errors, then:

iptables -X f2b-plesk-wordpress -- stderr: "iptables v1.4.21: Couldn't load target `f2b-plesk-wordpress':No such file or directory\n\nTry `iptables -h' or 'iptables --help' for more information.\niptables: No chain/target/match by that name.\niptables: No chain/target/match by that name.\n"
2016-08-02 16:48:00,675 fail2ban.action  [22509]: ERROR  iptables -D INPUT -p tcp -m multiport --dports http,https,7080,7081 -j f2b-plesk-wordpress
iptables -F f2b-plesk-wordpress
iptables -X f2b-plesk-wordpress -- returned 1
2016-08-02 16:48:00,675 fail2ban.actions  [22509]: ERROR  Failed to stop jail 'plesk-wordpress' action 'iptables-multiport': Error stopping action
2016-08-02 16:48:00,675 fail2ban.jail  [22509]: INFO  Jail 'plesk-wordpress' stopped
2016-08-02 16:48:00,680 fail2ban.server  [22509]: INFO  Exiting Fail2ban
2016-08-02 16:48:14,536 fail2ban.server  [1224]: INFO  Changed logging target to /var/log/fail2ban.log for Fail2ban v0.9.2
2016-08-02 16:48:14,539 fail2ban.database  [1224]: INFO  Connected to fail2ban persistent database '/var/lib/fail2ban/fail2ban.sqlite3'
2016-08-02 16:48:14,554 fail2ban.jail  [1224]: INFO  Creating new jail 'ssh'
2016-08-02 16:48:14,565 fail2ban.jail  [1224]: INFO  Jail 'ssh' uses Gamin
2016-08-02 16:48:14,603 fail2ban.filter  [1224]: INFO  Set jail log file encoding to UTF-8
2016-08-02 16:48:14,677 fail2ban.jail  [1224]: INFO  Initiated 'gamin' backend
2016-08-02 16:48:14,760 fail2ban.filter  [1224]: INFO  Added logfile = /var/log/secure
2016-08-02 16:48:14,761 fail2ban.filter  [1224]: INFO  Set maxRetry = 5
2016-08-02 16:48:14,763 fail2ban.filter  [1224]: INFO  Set findtime = 600
2016-08-02 16:48:14,763 fail2ban.actions  [1224]: INFO  Set banTime = 604800
2016-08-02 16:48:14,764 fail2ban.filter  [1224]: INFO  Set maxlines = 10
2016-08-02 16:48:14,829 fail2ban.server  [1224]: INFO  Jail ssh is not a JournalFilter instance
2016-08-02 16:48:14,837 fail2ban.jail  [1224]: INFO  Creating new jail 'recidive'
2016-08-02 16:48:14,838 fail2ban.jail  [1224]: INFO  Jail 'recidive' uses Gamin
2016-08-02 16:48:14,839 fail2ban.filter  [1224]: INFO  Set jail log file encoding to UTF-8
2016-08-02 16:48:14,839 fail2ban.jail  [1224]: INFO  Initiated 'gamin' backend
2016-08-02 16:48:14,860 fail2ban.filter  [1224]: INFO  Added logfile = /var/log/fail2ban.log
2016-08-02 16:48:14,861 fail2ban.filter  [1224]: INFO  Set maxRetry = 5
2016-08-02 16:48:14,862 fail2ban.filter  [1224]: INFO  Set findtime = 86400
2016-08-02 16:48:14,863 fail2ban.actions  [1224]: INFO  Set banTime = 604800
2016-08-02 16:48:14,867 fail2ban.server  [1224]: INFO  Jail recidive is not a JournalFilter instance
2016-08-02 16:48:14,877 fail2ban.jail  [1224]: INFO  Creating new jail 'plesk-proftpd'
2016-08-02 16:48:14,877 fail2ban.jail  [1224]: INFO  Jail 'plesk-proftpd' uses Gamin
2016-08-02 16:48:14,878 fail2ban.filter  [1224]: INFO  Set jail log file encoding to UTF-8
2016-08-02 16:48:14,878 fail2ban.jail  [1224]: INFO  Initiated 'gamin' backend
2016-08-02 16:48:14,905 fail2ban.filter  [1224]: INFO  Added logfile = /var/log/secure
2016-08-02 16:48:14,907 fail2ban.filter  [1224]: INFO  Set maxRetry = 5
2016-08-02 16:48:14,919 fail2ban.filter  [1224]: INFO  Set findtime = 600
2016-08-02 16:48:14,920 fail2ban.actions  [1224]: INFO  Set banTime = 604800

... and from here on everything seems to be ok....

Any clue?

Thanks!

 

[IgorG]

I would suggest you reinstall fail2ban with Plesk autoinstaller.

 

[Sergio Manzi]

Yeah... I think that's a good idea in any case... Will do!

Thanks!

 

[trialotto]

@Sergio Manzi

There should be no need to reinstall Fail2Ban.

In your first post, you stated

In the meantime I:

• Disabled that jail
• Added my server IP address to the trusted ones (good practice, I think, that I didn't followed, although 127.0.0.1 was in there...)

and whitelisting the server IP is the proper action, but note that you should not disable the "badbots" jail.

Finally, if you really want to force Fail2Ban to set iptables properly, just do the following:

a) first restart the Fail2Ban server with a separate stop/start sequence

- run: systemctl stop fail2ban
- run: systemctl start fail2ban

and wait a couple of minutes, this can take some time,

b) inspect the fail2ban.log file and check to no iptables related are reported and note that:

- you can reload Fail2Ban with the command: fail2ban-client reload (this can again force Fail2Ban to create a proper set of iptables entries)
- you have to check any limits on the number of firewall rules: on VPSes, there is a limit (often to be found in the variable numiptent, run: cat /proc/user_beancounters)

and I it is very likely that you have to reload Fail2Ban one time. But check first, before doing any reloading, since it (again) will take some time to reload.


Anyway, just give it a try.

Hope the above helps a bit.

Regards.....

 

[Sergio Manzi]

Hello @trialotto, thanks for your suggestions, which I followed.

After performing the steps you indicated I examined my fail2ban.log and everything seems to be OK in it.

I also dumped my iptables (iptables -S > my-iptables.txt) and compared to what is listed in Plesk control panel under "IP Address Banning": perfect coincidence (+ firewall rules, of course...)

Thanks, that really helped and I've learned something new!

Sergio

P.S.: I've re-enabled the plesk-apache-badbots jail and so far no IP address has been banned because of it. I'll keep an eye on that...

P.S. (2): Im my VPS (Centos 7.2 at DigitalOcean) I don't have /proc/user_beancounters. I also googled around about iptables limits at DO, but couldn't find anything. They probably don't impose any limit...

 

[trialotto]

@Sergio Manzi

A small tip: watch the mail.log, since it is very likely that your Fail2Ban does not block "mail related attacks" properly.

In essence, these "attacks" involve a lot of attempts to log in, which attempts bypass the default configuration of Fail2Ban.

Just send me a PM if you encounter this behaviour in your mail.logs, so I can share some tips to block specific bad IPs.

Regards.......

 

[Sergio Manzi]

@trialotto

Thank-you very much for that too! Will surely do...

Regards

 

[Fabio_Hansen]

Hi.
How did you solve it?
I am with the same situation, in the logs appears the ip of my server and not the real ip.
I'm using the Plesk Onyx version 17.0.7 and the remoteip module is loaded.

 

[Sergio Manzi]

Fabio, I'm afraid I'm not understanding you when you state that "...in the logs appears the ip of my server and not the real ip"; what's the difference between the twos?

Anyway, if your case is similar to mine, the solution was whitelisting my server IP address in fail2ban.

Hope this can help...

Cheers!

 

[UFHH01]

Hi Sergio Manzi,

Anyway, if your case is similar to mine, the solution was whitelisting my server IP address in fail2ban.

Pls. note, that this is not a solution, but a normal setup procedure, when you use Fail2Ban on your server. The official Fail2Ban documentations states clear to whitelist "localhost" and all "IPv4" - addresses configured for your server.

 

[Sergio Manzi]

Hi Sergio Manzi,


Pls. note, that this is not a solution, but a normal setup procedure, when you use Fail2Ban on your server. The official Fail2Ban documentations states clear to whitelist "localhost" and all "IPv4" - addresses configured for your server.

Agreed, and I think Plesk should automatically take care of that!