Topic: Fail2ban dying

[DanB35]

I'm noticing occasionally that fail2ban stops running on my SME 9 server (installed following http://wiki.contribs.org/Fail2ban).  Usually, I notice that I haven't gotten any ban messages for a while, and when I run "service fail2ban status", it reports that it isn't running.  So today, I thought I'd investigate.

Looking at the log, I'm seeing repeated error messages that /var/log/httpd/error_log and /var/log/secure are missing:

Code: [Select]

[root@e-smith fail2ban]# tail -150 daemon.log
2014-10-22 01:12:02,067 fail2ban.filter [11679]: ERROR   Unable to open /var/log/httpd/error_log
2014-10-22 01:12:02,067 fail2ban.filter [11679]: ERROR   [Errno 2] No such file or directory: '/var/log/secure'
Traceback (most recent call last):
  File "/usr/share/fail2ban/server/filter.py", line 556, in getFailures
    has_content = container.open()
  File "/usr/share/fail2ban/server/filter.py", line 637, in open
    self.__handler = open(self.__filename)
IOError: [Errno 2] No such file or directory: '/var/log/secure'
2014-10-22 01:12:02,068 fail2ban.filter [11679]: ERROR   [Errno 2] No such file or directory: '/var/log/httpd/error_log'
Traceback (most recent call last):
  File "/usr/share/fail2ban/server/filter.py", line 556, in getFailures
    has_content = container.open()
  File "/usr/share/fail2ban/server/filter.py", line 637, in open
    self.__handler = open(self.__filename)
IOError: [Errno 2] No such file or directory: '/var/log/httpd/error_log'
2014-10-22 01:12:02,068 fail2ban.filter [11679]: ERROR   Unable to open /var/log/secure
2014-10-22 01:12:02,068 fail2ban.filter [11679]: ERROR   Unable to open /var/log/httpd/error_log
2014-10-22 01:12:02,068 fail2ban.filter [11679]: ERROR   [Errno 2] No such file or directory: '/var/log/httpd/error_log'
Traceback (most recent call last):
  File "/usr/share/fail2ban/server/filter.py", line 556, in getFailures
    has_content = container.open()
  File "/usr/share/fail2ban/server/filter.py", line 637, in open
    self.__handler = open(self.__filename)
IOError: [Errno 2] No such file or directory: '/var/log/httpd/error_log'
2014-10-22 01:12:02,068 fail2ban.filter [11679]: ERROR   [Errno 2] No such file or directory: '/var/log/httpd/error_log'
Traceback (most recent call last):
  File "/usr/share/fail2ban/server/filter.py", line 556, in getFailures
    has_content = container.open()
  File "/usr/share/fail2ban/server/filter.py", line 637, in open
    self.__handler = open(self.__filename)
IOError: [Errno 2] No such file or directory: '/var/log/httpd/error_log'
2014-10-22 01:12:02,131 fail2ban.filter [11679]: ERROR   [Errno 2] No such file or directory: '/var/log/secure'
Traceback (most recent call last):
  File "/usr/share/fail2ban/server/filter.py", line 556, in getFailures
    has_content = container.open()
  File "/usr/share/fail2ban/server/filter.py", line 637, in open
    self.__handler = open(self.__filename)
IOError: [Errno 2] No such file or directory: '/var/log/secure'
2014-10-22 01:12:02,131 fail2ban.filter [11679]: ERROR   [Errno 2] No such file or directory: '/var/log/httpd/error_log'
Traceback (most recent call last):
  File "/usr/share/fail2ban/server/filter.py", line 556, in getFailures
    has_content = container.open()
  File "/usr/share/fail2ban/server/filter.py", line 637, in open
    self.__handler = open(self.__filename)
IOError: [Errno 2] No such file or directory: '/var/log/httpd/error_log'
2014-10-22 01:12:03,233 fail2ban.server [11679]: INFO    Stopping all jails
2014-10-22 01:12:04,200 fail2ban.jail   [11679]: INFO    Jail 'http-overflows' stopped
2014-10-22 01:12:04,612 fail2ban.jail   [11679]: INFO    Jail 'http-noscript' stopped
2014-10-22 01:12:04,719 fail2ban.jail   [11679]: INFO    Jail 'http-auth' stopped
2014-10-22 01:12:04,872 fail2ban.jail   [11679]: INFO    Jail 'pam-generic' stopped
2014-10-22 01:12:05,751 fail2ban.jail   [11679]: INFO    Jail 'ftp' stopped
2014-10-22 01:12:06,705 fail2ban.jail   [11679]: INFO    Jail 'ssh-ddos' stopped
2014-10-22 01:12:07,203 fail2ban.jail   [11679]: INFO    Jail 'http-scan' stopped
2014-10-22 01:12:07,745 fail2ban.jail   [11679]: INFO    Jail 'ssh' stopped
2014-10-22 01:12:08,204 fail2ban.jail   [11679]: INFO    Jail 'qpsmtpd' stopped
2014-10-22 01:12:08,747 fail2ban.jail   [11679]: INFO    Jail 'imap' stopped
2014-10-22 01:12:09,707 fail2ban.actions[11679]: WARNING [recidive] Unban 192.126.120.82
2014-10-22 01:12:10,212 fail2ban.jail   [11679]: INFO    Jail 'recidive' stopped
2014-10-22 01:12:10,233 fail2ban.server [11679]: INFO    Exiting Fail2ban

Those files do exist, but looking at the timestamp of these log entries, they seem to correspond exactly to when logrotate runs (because when I look at the log files, the last previous file is dated today at 1:12 am).  I speculate what's happening is that logrotate is ever so briefly removing the log file, and during the brief time it's gone, fail2ban dies because there's nothing for it to monitor.  How would I best avoid this?

[Stefano]

create 2 scripts in /etc/e-smith/events/actions, the first to stop fail2ban, the second to start it again.. then link them into /etc/e-smith/events/logrotate

this is the first idea that comes in mind.. I'm pretty sure there's something better

[Daniel B.]

Which version of smeserver-fail2ban are you running ?

[DanB35]

Code: [Select]

[user@e-smith ~]$ rpm -q smeserver-fail2ban
smeserver-fail2ban-0.1.8-1.el6.fws.noarch

[Daniel B.]

Ok, you're running the latest version. The warnings are "expected". You're right that during the logrotate event, log files monitored by fail2ban briefly becomes "invalid" (f2b monitor a symlink which points to a non existing file), but right after that, fail2Ban should be restarted. In your log, we can see fail2ban being stopped, but not started after that. I don't see this behavior on the servers I manage. Is the fail2ban service correctly enabled ?

Code: [Select]

db configuration show fail2ban


[DanB35]

Code: [Select]

[root@e-smith ~]# db configuration show fail2ban
fail2ban=service
    Mail=enabled
    status=enabled


[Daniel B.]

If you run

Code: [Select]

signal-event logrotate

Does fail2ban restart normally or does it stays stopped ?

[DanB35]

Code: [Select]

[root@e-smith ~]# signal-event logrotate
[root@e-smith ~]# service fail2ban status
fail2ban-server is stopped
[root@e-smith ~]# service fail2ban start
Starting fail2ban: WARNING 'ignoreregex' not defined in 'Definition'. Using default one: ''
                                                           [  OK  ]


Code: [Select]

[user@e-smith ~]$ ls -l /etc/e-smith/events/logrotate/*
lrwxrwxrwx 1 root root   38 Jul 29 09:47 /etc/e-smith/events/logrotate/S05rotate_timestamped_logfiles -> ../actions/rotate_timestamped_logfiles
lrwxrwxrwx 1 root root   25 Jul 29 09:47 /etc/e-smith/events/logrotate/S75purge-old-logs -> ../actions/purge-old-logs

/etc/e-smith/events/logrotate/logfiles2timestamp:
total 4
drwxr-xr-x 3 root root 4096 Jul 29 11:28 var

/etc/e-smith/events/logrotate/services2adjust:
total 0
lrwxrwxrwx 1 root root 7 Sep 21 14:06 fail2ban -> restart
lrwxrwxrwx 1 root root 7 Jul 29 09:47 httpd-admin -> sigusr1
lrwxrwxrwx 1 root root 7 Sep 16 09:49 httpd-e-smith -> sigusr1
lrwxrwxrwx 1 root root 7 Jul 29 09:47 rsyslog -> restart

/etc/e-smith/events/logrotate/templates2expand:
total 4
drwxr-xr-x 5 root root 4096 Jul 29 09:47 etc


[Daniel B.]

Try to increase loglevel (edit directly /etc/fail2ban/fail2ban.conf), run signal-event logrotate again, and check if there's anything interesting in /var/log/fail2ban/daemon.log

[DanB35]

OK, set the log level to 5, restarted the fail2ban service, did tail -f daemon.log, and it immediately filled my screen with date detector messages.  Did signal-event logrotate, and the messages stopped.  Then did:

Code: [Select]

[root@e-smith fail2ban]# tail -5000 daemon.log > log_excerpt.txt
[root@e-smith fail2ban]# grep -v datedetector log_excerpt.txt
2014-10-23 16:23:03,858 fail2ban.actions[3901]: DEBUG   Flush ban list
2014-10-23 16:23:03,859 fail2ban.actions.action[3901]: DEBUG   
2014-10-23 16:23:03,859 fail2ban.actions.action[3901]: DEBUG   Nothing to do
2014-10-23 16:23:03,859 fail2ban.actions.action[3901]: DEBUG   
2014-10-23 16:23:03,859 fail2ban.actions.action[3901]: DEBUG   Nothing to do
2014-10-23 16:23:03,860 fail2ban.actions[3901]: DEBUG   imap: action terminated
2014-10-23 16:23:03,860 fail2ban.jail   [3901]: INFO    Jail 'imap' stopped
2014-10-23 16:23:03,860 fail2ban.server [3901]: DEBUG   Stopping jail recidive
2014-10-23 16:23:04,861 fail2ban.actions[3901]: DEBUG   Flush ban list
2014-10-23 16:23:04,861 fail2ban.actions.action[3901]: DEBUG   
2014-10-23 16:23:04,861 fail2ban.actions.action[3901]: DEBUG   Nothing to do
2014-10-23 16:23:04,861 fail2ban.actions.action[3901]: DEBUG   
2014-10-23 16:23:04,861 fail2ban.actions.action[3901]: DEBUG   Nothing to do
2014-10-23 16:23:04,861 fail2ban.actions[3901]: DEBUG   recidive: action terminated
2014-10-23 16:23:04,862 fail2ban.filter [3901]: DEBUG   recidive filter terminated
2014-10-23 16:23:04,862 fail2ban.jail   [3901]: INFO    Jail 'recidive' stopped
2014-10-23 16:23:04,862 fail2ban.server [3901]: DEBUG   Remove PID file /var/run/fail2ban/fail2ban.pid
2014-10-23 16:23:04,862 fail2ban.server [3901]: INFO    Exiting Fail2ban
[root@e-smith fail2ban]# service fail2ban status
fail2ban-server is stopped

The tail -5000 returned under two seconds' worth of the log--the DEBUG log level is truly verbose.  For the time being, I've set the log level back to 3 and restarted fail2ban.

[DanB35]

http://bugs.contribs.org/show_bug.cgi?id=8708 Seems to be a related bug.

[jibe]

Hi,

So, version 1.0.11-1 is working. But there is still SME 8 running, and they have the same problem !

Daniel, could you update also your repo for SME 8, please ?

Thanks.

[Daniel B.]

The fix has already been backported on the SME8 branch, where the latest version is 0.1.10-1

[jibe]

I just checked better... In fact, the problem is not exactly the same : fail2ban is running after logrotate or server reboot. But it has lost all previous bans...

Seems to work correctly, but I wondered why I have sometimes the same IP banned 2 times during the BanTime, and never anything in the recidive jail... In fact, this happens after a logrotate or a server reboot. Today, the log shows a banned IP just before a logrotate, and the same IP banned again just after. Verifying what I have in the jails, I find only this IP, when I had 2 others banned this morning with a BannedTime of 3 days...

Should I open a new bug for that ? (I have no SME9 with fail2ban installed, so I don't know if there is the same problem...)

[Daniel B.]

I'm not sure I understand your problem