Koozali.org: home of the SME Server
Obsolete Releases => SME 9.x Contribs => Topic started by: DanB35 on October 22, 2014, 09:51:02 PM
-
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:
[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?
-
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
-
Which version of smeserver-fail2ban are you running ?
-
[user@e-smith ~]$ rpm -q smeserver-fail2ban
smeserver-fail2ban-0.1.8-1.el6.fws.noarch
-
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 ?
db configuration show fail2ban
-
[root@e-smith ~]# db configuration show fail2ban
fail2ban=service
Mail=enabled
status=enabled
-
If you run
signal-event logrotate
Does fail2ban restart normally or does it stays stopped ?
-
[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 ]
[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
-
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
-
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:
[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.
-
http://bugs.contribs.org/show_bug.cgi?id=8708 Seems to be a related bug.
-
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.
-
The fix has already been backported on the SME8 branch, where the latest version is 0.1.10-1
-
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...)
-
I'm not sure I understand your problem
-
Mmm... I'm afraid that I have another problem on this server.... I'll investigate more on this one, and see on another if fail2ban is working well...
Sorry, I could have posted too early. I'll come back later if necessary.
-
I can reproduce the problem on another server when I reboot it (sorry that I did not try signal-event logrotate... I don't want to renew all my logs on this server) :
~/# ./checklist_ban
http-overflows 0
http-noscript 0
http-auth 0
pam-generic 0
ssh-ddos 0
http-scan 1
ssh 0
qpsmtpd 0
recidive 0
~/# reboot
And after the reboot :
~/# ./checklist_ban
http-overflows 0
http-noscript 0
http-auth 0
pam-generic 0
ssh-ddos 0
http-scan 0
ssh 0
qpsmtpd 0
recidive 0
~/# config show fail2ban
fail2ban=service
BanTime=260000
FindTime=10800
Mail=enabled
status=enabled
~/# rpm -qa fail2ban smeserver-fail2ban
fail2ban-0.8.14-1.el5
smeserver-fail2ban-0.1.10-1.el5.fws
The banned IP is lost... This explains why I noticed that the same IP is sometimes banned 2 times when the BanTime is not expired...
The log shows that the IP is unbanned during the reboot :
2015-06-18 12:04:05,645 fail2ban.actions[5606]: WARNING [http-scan] Ban 103.39.77.8
2015-06-18 18:57:48,752 fail2ban.server [5606]: INFO Stopping all jails
2015-06-18 18:57:49,678 fail2ban.jail [5606]: INFO Jail 'http-overflows' stopped
2015-06-18 18:57:50,677 fail2ban.jail [5606]: INFO Jail 'http-noscript' stopped
2015-06-18 18:57:50,679 fail2ban.jail [5606]: INFO Jail 'http-auth' stopped
2015-06-18 18:57:51,676 fail2ban.jail [5606]: INFO Jail 'pam-generic' stopped
2015-06-18 18:57:52,674 fail2ban.jail [5606]: INFO Jail 'ssh-ddos' stopped
2015-06-18 18:57:53,080 fail2ban.actions[5606]: WARNING [http-scan] Unban 103.39.77.8
2015-06-18 18:57:56,295 fail2ban.jail [5606]: INFO Jail 'http-scan' stopped
2015-06-18 18:57:56,675 fail2ban.jail [5606]: INFO Jail 'ssh' stopped
2015-06-18 18:57:56,679 fail2ban.jail [5606]: INFO Jail 'qpsmtpd' stopped
2015-06-18 18:57:57,082 fail2ban.jail [5606]: INFO Jail 'recidive' stopped
2015-06-18 19:00:44,741 fail2ban.server [3655]: INFO Changed logging target to /var/log/fail2ban/daemon.log for Fail2ban v0.8.14
2015-06-18 19:00:44,802 fail2ban.jail [3655]: INFO Creating new jail 'http-overflows'
2015-06-18 19:00:47,149 fail2ban.jail [3655]: INFO Jail 'http-overflows' uses pyinotify
2015-06-18 19:00:47,776 fail2ban.jail [3655]: INFO Initiated 'pyinotify' backend
2015-06-18 19:00:47,845 fail2ban.filter [3655]: INFO Added logfile = /var/log/httpd/error_log
2015-06-18 19:00:47,850 fail2ban.filter [3655]: INFO Set maxRetry = 3
2015-06-18 19:00:47,859 fail2ban.filter [3655]: INFO Set findtime = 10800
2015-06-18 19:00:47,861 fail2ban.actions[3655]: INFO Set banTime = 260000
2015-06-18 19:00:47,926 fail2ban.jail [3655]: INFO Creating new jail 'http-noscript'
2015-06-18 19:00:47,927 fail2ban.jail [3655]: INFO Jail 'http-noscript' uses pyinotify
2015-06-18 19:00:47,929 fail2ban.jail [3655]: INFO Initiated 'pyinotify' backend
2015-06-18 19:00:47,934 fail2ban.filter [3655]: INFO Added logfile = /var/log/httpd/error_log
2015-06-18 19:00:47,938 fail2ban.filter [3655]: INFO Set maxRetry = 3
2015-06-18 19:00:47,945 fail2ban.filter [3655]: INFO Set findtime = 10800
2015-06-18 19:00:47,948 fail2ban.actions[3655]: INFO Set banTime = 260000
2015-06-18 19:00:48,012 fail2ban.jail [3655]: INFO Creating new jail 'http-auth'
2015-06-18 19:00:48,013 fail2ban.jail [3655]: INFO Jail 'http-auth' uses pyinotify
2015-06-18 19:00:48,016 fail2ban.jail [3655]: INFO Initiated 'pyinotify' backend
2015-06-18 19:00:48,020 fail2ban.filter [3655]: INFO Added logfile = /var/log/httpd/error_log
2015-06-18 19:00:48,024 fail2ban.filter [3655]: INFO Set maxRetry = 3
2015-06-18 19:00:48,031 fail2ban.filter [3655]: INFO Set findtime = 10800
2015-06-18 19:00:48,033 fail2ban.actions[3655]: INFO Set banTime = 260000
2015-06-18 19:00:48,278 fail2ban.jail [3655]: INFO Creating new jail 'pam-generic'
2015-06-18 19:00:48,279 fail2ban.jail [3655]: INFO Jail 'pam-generic' uses pyinotify
2015-06-18 19:00:48,282 fail2ban.jail [3655]: INFO Initiated 'pyinotify' backend
2015-06-18 19:00:48,334 fail2ban.filter [3655]: INFO Added logfile = /var/log/secure
2015-06-18 19:00:48,338 fail2ban.filter [3655]: INFO Set maxRetry = 6
2015-06-18 19:00:48,347 fail2ban.filter [3655]: INFO Set findtime = 10800
2015-06-18 19:00:48,350 fail2ban.actions[3655]: INFO Set banTime = 260000
2015-06-18 19:00:48,414 fail2ban.jail [3655]: INFO Creating new jail 'ssh-ddos'
2015-06-18 19:00:48,415 fail2ban.jail [3655]: INFO Jail 'ssh-ddos' uses pyinotify
2015-06-18 19:00:48,417 fail2ban.jail [3655]: INFO Initiated 'pyinotify' backend
2015-06-18 19:00:48,422 fail2ban.filter [3655]: INFO Added logfile = /var/log/sshd/current
2015-06-18 19:00:48,427 fail2ban.filter [3655]: INFO Set maxRetry = 3
2015-06-18 19:00:48,437 fail2ban.filter [3655]: INFO Set findtime = 10800
2015-06-18 19:00:48,439 fail2ban.actions[3655]: INFO Set banTime = 260000
2015-06-18 19:00:48,498 fail2ban.jail [3655]: INFO Creating new jail 'http-scan'
2015-06-18 19:00:48,499 fail2ban.jail [3655]: INFO Jail 'http-scan' uses pyinotify
2015-06-18 19:00:48,501 fail2ban.jail [3655]: INFO Initiated 'pyinotify' backend
2015-06-18 19:00:48,506 fail2ban.filter [3655]: INFO Added logfile = /var/log/httpd/error_log
2015-06-18 19:00:48,510 fail2ban.filter [3655]: INFO Set maxRetry = 3
2015-06-18 19:00:48,519 fail2ban.filter [3655]: INFO Set findtime = 10800
2015-06-18 19:00:48,522 fail2ban.actions[3655]: INFO Set banTime = 260000
2015-06-18 19:00:48,629 fail2ban.jail [3655]: INFO Creating new jail 'ssh'
2015-06-18 19:00:48,629 fail2ban.jail [3655]: INFO Jail 'ssh' uses pyinotify
2015-06-18 19:00:48,632 fail2ban.jail [3655]: INFO Initiated 'pyinotify' backend
2015-06-18 19:00:48,637 fail2ban.filter [3655]: INFO Added logfile = /var/log/sshd/current
2015-06-18 19:00:48,641 fail2ban.filter [3655]: INFO Set maxRetry = 3
2015-06-18 19:00:48,650 fail2ban.filter [3655]: INFO Set findtime = 10800
2015-06-18 19:00:48,653 fail2ban.actions[3655]: INFO Set banTime = 260000
2015-06-18 19:00:49,025 fail2ban.jail [3655]: INFO Creating new jail 'qpsmtpd'
2015-06-18 19:00:49,026 fail2ban.jail [3655]: INFO Jail 'qpsmtpd' uses pyinotify
2015-06-18 19:00:49,029 fail2ban.jail [3655]: INFO Initiated 'pyinotify' backend
2015-06-18 19:00:49,072 fail2ban.filter [3655]: INFO Added logfile = /var/log/qpsmtpd/current
2015-06-18 19:00:49,278 fail2ban.filter [3655]: INFO Added logfile = /var/log/sqpsmtpd/current
2015-06-18 19:00:49,282 fail2ban.filter [3655]: INFO Set maxRetry = 9
2015-06-18 19:00:49,291 fail2ban.filter [3655]: INFO Set findtime = 10800
2015-06-18 19:00:49,294 fail2ban.actions[3655]: INFO Set banTime = 260000
2015-06-18 19:00:49,338 fail2ban.jail [3655]: INFO Creating new jail 'recidive'
2015-06-18 19:00:49,339 fail2ban.jail [3655]: INFO Jail 'recidive' uses poller
2015-06-18 19:00:49,476 fail2ban.jail [3655]: INFO Initiated 'polling' backend
2015-06-18 19:00:49,581 fail2ban.filter [3655]: INFO Added logfile = /var/log/fail2ban/daemon.log
2015-06-18 19:00:49,584 fail2ban.filter [3655]: INFO Set maxRetry = 5
2015-06-18 19:00:49,593 fail2ban.filter [3655]: INFO Set findtime = 86400
2015-06-18 19:00:49,595 fail2ban.actions[3655]: INFO Set banTime = 604800
2015-06-18 19:00:49,657 fail2ban.jail [3655]: INFO Jail 'http-overflows' started
2015-06-18 19:00:49,663 fail2ban.jail [3655]: INFO Jail 'http-noscript' started
2015-06-18 19:00:49,668 fail2ban.jail [3655]: INFO Jail 'http-auth' started
2015-06-18 19:00:49,672 fail2ban.jail [3655]: INFO Jail 'pam-generic' started
2015-06-18 19:00:49,677 fail2ban.jail [3655]: INFO Jail 'ssh-ddos' started
2015-06-18 19:00:49,681 fail2ban.jail [3655]: INFO Jail 'http-scan' started
2015-06-18 19:00:49,687 fail2ban.jail [3655]: INFO Jail 'ssh' started
2015-06-18 19:00:49,692 fail2ban.jail [3655]: INFO Jail 'qpsmtpd' started
2015-06-18 19:00:49,697 fail2ban.jail [3655]: INFO Jail 'recidive' started
-
Yes, the ban are lost when you reboot your server (or when you restart fail2ban), that's expected. But as fail2ban isn't restarted anymore during a logrotate event, you do not loose your ban automatically, only after a manual server reboot (which shouldn't be that often) or a service restart
-
Ok, thank you for this explanation.
Donc, ce n'est pas la fin du monde ! :wink: