PyInotify fails after log rotation #184

jafcobend · 2013-04-22T18:46:53Z

Sorry to be a pest but I'd surely like to see this work. This is basically the same thing as reported in bug 44. I see that several others complained about it after the bug was closed as fixed so I thought it best if this was put in a new bug report.The software I'm running:
fail2ban: head branch checked out 4/11/2013
pyinotify: 0.8.9
python: 2.5.2
Linux: 2.6.30
Libc: 2.7
Distro: Debian 5 (lenny).

Testcases:

Testing using /usr/bin/python2.5
Fail2ban 0.8.8 test suite. Python 2.5.2 (r252:60911, Jan 24 2010, 14:53:14) [GCC 4.3.2]. Please wait...
I: Skipping gamin backend testing. Got exception 'No module named gamin'
...................................................F................FFFFF.....warning: unhandled exception
..
======================================================================
FAIL: testNewChangeViaIsModified (testcases.filtertestcase.LogFileMonitor)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/srv/home/jon/fail2ban-0.8.8+20130411/testcases/filtertestcase.py", line 245, in testNewChangeViaIsModified
    self.assertTrue(self.isModified())
AssertionError

======================================================================
FAIL: test_delLogPath (testcases.filtertestcase.MonitorFailures<FilterPoll>(/tmp/monitorfailures_FilterPollXgtt-cfail2ban))
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/srv/home/jon/fail2ban-0.8.8+20130411/testcases/filtertestcase.py", line 496, in test_delLogPath
    self.assert_correct_last_attempt(GetFailures.FAILURES_01)
  File "/srv/home/jon/fail2ban-0.8.8+20130411/testcases/filtertestcase.py", line 408, in assert_correct_last_attempt
    self.assertTrue(self.isFilled(20)) # give Filter a chance to react
AssertionError

======================================================================
FAIL: test_grow_file (testcases.filtertestcase.MonitorFailures<FilterPoll>(/tmp/monitorfailures_FilterPollXgtt-cfail2ban))
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/srv/home/jon/fail2ban-0.8.8+20130411/testcases/filtertestcase.py", line 424, in test_grow_file
    self.assertTrue(self.isFilled(6))
AssertionError

======================================================================
FAIL: test_move_file (testcases.filtertestcase.MonitorFailures<FilterPoll>(/tmp/monitorfailures_FilterPollXgtt-cfail2ban))
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/srv/home/jon/fail2ban-0.8.8+20130411/testcases/filtertestcase.py", line 463, in test_move_file
    self.assertEqual(self.filter.failManager.getFailTotal(), 2)
AssertionError: 0 != 2

======================================================================
FAIL: test_new_bogus_file (testcases.filtertestcase.MonitorFailures<FilterPoll>(/tmp/monitorfailures_FilterPollXgtt-cfail2ban))
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/srv/home/jon/fail2ban-0.8.8+20130411/testcases/filtertestcase.py", line 481, in test_new_bogus_file
    self.assert_correct_last_attempt(GetFailures.FAILURES_01)
  File "/srv/home/jon/fail2ban-0.8.8+20130411/testcases/filtertestcase.py", line 408, in assert_correct_last_attempt
    self.assertTrue(self.isFilled(20)) # give Filter a chance to react
AssertionError

======================================================================
FAIL: test_rewrite_file (testcases.filtertestcase.MonitorFailures<FilterPoll>(/tmp/monitorfailures_FilterPollXgtt-cfail2ban))
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/srv/home/jon/fail2ban-0.8.8+20130411/testcases/filtertestcase.py", line 445, in test_rewrite_file
    self.assert_correct_last_attempt(GetFailures.FAILURES_01)
  File "/srv/home/jon/fail2ban-0.8.8+20130411/testcases/filtertestcase.py", line 408, in assert_correct_last_attempt
    self.assertTrue(self.isFilled(20)) # give Filter a chance to react
AssertionError

----------------------------------------------------------------------
Ran 80 tests in 101.366s

FAILED (failures=6)
E: Failed with  /usr/bin/python2.5

----

I'm gathering debug logs.

The text was updated successfully, but these errors were encountered:

yarikoptic · 2013-04-22T18:49:43Z

so "fail2ban-0.8.8+20130411" means that you grabbed GIT snapshot few
days back?

I guess the best solution for you on lenny would be to switch to polling
for now

Yaroslav O. Halchenko, Ph.D.
http://neuro.debian.net http://www.pymvpa.org http://www.fail2ban.org
Senior Research Associate, Psychological and Brain Sciences Dept.
Dartmouth College, 419 Moore Hall, Hinman Box 6207, Hanover, NH 03755
Phone: +1 (603) 646-9834 Fax: +1 (603) 646-1419
WWW: http://www.linkedin.com/in/yarik

jafcobend · 2013-04-22T19:03:41Z

Yes, I grabbed it from git a few days ago. Here is the logrotate config:

/var/log/auth.log
{
        create
        rotate 4
        weekly
        missingok
        notifempty
        compress
        delaycompress
        sharedscripts
        postrotate
                invoke-rc.d rsyslog reload > /dev/null
        endscript
}

And jail.conf:

[DEFAULT]
ignoreip  = 127.0.0.1/8
backend   = pyinotify
bantime   = 3600
findtime  = 3600
maxretry  = 5
destemail = root@localhost
banaction = iptables-multiport
mta       = sendmail
protocol  = tcp
chain     = INPUT
action = %(banaction)s[name=%(__name__)s, port="%(port)s", protocol="%(protocol)s", chain="%(chain)s"]

[vsftpd]
enabled = true
port = ftp,ftp-data
filter = vsftpd
logpath = /var/log/auth.log
bantime = 604800
maxretry = 3
findtime = 86400

I'll be switching all servers back to polling as soon as I get the debug log from the next rotation.

kwirk · 2013-04-22T19:05:08Z

@jafcobend @yarikoptic Looking at the test failures above, it appears that poll is failing, not pyinotify...

jafcobend · 2013-04-22T19:07:41Z

@kwirk but, go figure, polling works and PyInotify works until the log rolls.

yarikoptic · 2013-04-22T19:43:21Z

heh -- I was a good boy and upgraded all of them from lenny (it is not
supported by Debian project for some time already) to squeeze -- so
would not be able to reproduce :-/

is there any particular about that box when you run tests? e.g. busy
with CPU or IO?

On Mon, 22 Apr 2013, Yaroslav Halchenko wrote:

[1]@jafcobend [2]@yarikoptic Looking at the test failures above, it
appears that poll is failing, not pyinotify...

doh -- indeed! I got biased by the subject ;)

So it is weird/bad that it fails there -- I will also check on

some elderly box I have available

Yaroslav O. Halchenko, Ph.D.
http://neuro.debian.net http://www.pymvpa.org http://www.fail2ban.org
Senior Research Associate, Psychological and Brain Sciences Dept.
Dartmouth College, 419 Moore Hall, Hinman Box 6207, Hanover, NH 03755
Phone: +1 (603) 646-9834 Fax: +1 (603) 646-1419
WWW: http://www.linkedin.com/in/yarik

jafcobend · 2013-04-22T19:56:24Z

Yaroslav Halchenko wrote:

[...]
is there any particular about that box when you run tests? e.g. busy
with CPU or IO?
[...]
Not really. I have two boxes that I rely on fail2ban the most. Both have
the same issue. The software specs are the same across both machines.
One is a dual Mac G5 PowerPC 2.5GHz w/ 2GB of RAM. The other is a dual
Xeon 2.0GHz with 6GB of RAM running Debian's "bigmem" kernel. Neither of
them spend much time busy. They average less then a load of 0.50. One is
a mail server (smtp, imap, pop3). The other is a web / ftp server.

The tests were run on the Intel box.

Sent from my Debian Linux laptop -- http://www.debian.org/intro/about

Jon Foster
JF Possibilities, Inc.
jon@jfpossibilities.com
541-410-2760
Making computers work for you!

jafcobend · 2013-04-29T16:41:01Z

First off I should mention that I tried a patch similar to what was proposed in bug 44. Here it is:

--- filterpyinotify.py~ 2013-04-16 11:20:22.000000000 -0700
+++ filterpyinotify.py  2013-04-16 11:20:22.000000000 -0700
@@ -103,7 +103,7 @@


        def _addFileWatcher(self, path):
-               wd = self.__monitor.add_watch(path, pyinotify.IN_MODIFY)
+               wd = self.__monitor.add_watch(path, pyinotify.IN_MODIFY | pyinotify.IN_CREATE)
               self.__watches.update(wd)
                logSys.debug("Added file watcher for %s", path)
                # process the file since we did get even

Anyhow this resulted in the following pyinotify events in the log, after Sunday morning's rotation:

2013-04-28 04:29:01,842 fail2ban.filter : DEBUG  Default Callback for Event: <Event dir=False mask=0x2 maskname=IN_MODIFY name='' path=/var/log/auth.log pathname=/var/log/auth.log wd=2 >
2013-04-28 04:29:01,842 fail2ban.filter : DEBUG  Default Callback for Event: <Event dir=False mask=0x2 maskname=IN_MODIFY name='' path=/var/log/auth.log pathname=/var/log/auth.log wd=2 >
2013-04-28 04:29:04,081 fail2ban.filter : DEBUG  Default Callback for Event: <Event dir=False mask=0x100 maskname=IN_CREATE name=auth.log.0.gz path=/var/log pathname=/var/log/auth.log.0.gz wd=1 >
2013-04-28 04:29:04,081 fail2ban.filter : DEBUG  Default Callback for Event: <Event dir=False mask=0x100 maskname=IN_CREATE name=auth.log.0.gz path=/var/log pathname=/var/log/auth.log.0.gz wd=1 >
2013-04-28 04:29:04,081 fail2ban.filter : DEBUG  Ignoring creation of /var/log/auth.log.0.gz we do not monitor
2013-04-28 04:29:04,082 fail2ban.filter : DEBUG  Ignoring creation of /var/log/auth.log.0.gz we do not monitor
2013-04-28 04:29:04,148 fail2ban.filter : DEBUG  Default Callback for Event: <Event dir=False mask=0x100 maskname=IN_CREATE name=auth.log.new path=/var/log pathname=/var/log/auth.log.new wd=1 >
2013-04-28 04:29:04,149 fail2ban.filter : DEBUG  Default Callback for Event: <Event dir=False mask=0x100 maskname=IN_CREATE name=auth.log.new path=/var/log pathname=/var/log/auth.log.new wd=1 >
2013-04-28 04:29:04,149 fail2ban.filter : DEBUG  Ignoring creation of /var/log/auth.log.new we do not monitor
2013-04-28 04:29:04,149 fail2ban.filter : DEBUG  Ignoring creation of /var/log/auth.log.new we do not monitor
2013-04-28 04:29:04,152 fail2ban.filter : DEBUG  Default Callback for Event: <Event dir=False mask=0x100 maskname=IN_CREATE name=auth.log.0 path=/var/log pathname=/var/log/auth.log.0 wd=1 >
2013-04-28 04:29:04,152 fail2ban.filter : DEBUG  Default Callback for Event: <Event dir=False mask=0x100 maskname=IN_CREATE name=auth.log.0 path=/var/log pathname=/var/log/auth.log.0 wd=1 >
2013-04-28 04:29:04,153 fail2ban.filter : DEBUG  Ignoring creation of /var/log/auth.log.0 we do not monitor
2013-04-28 04:29:04,153 fail2ban.filter : DEBUG  Ignoring creation of /var/log/auth.log.0 we do not monitor

I think this shows that logrotate is creating the new file first as "auth.log.new", which is ignored since its not monitored. Then moving it to auth.log, later, which isn't triggering any events. I have not worked with pyinotify but I'm going to add the IN_MOVED_TO and IN_MOVED_FROM specifications to the watch list and see what gets logged next Sunday. I'm guessing that the IN_MOVED_TO might give me what I want... not sure if the existing fail2ban code can swallow it but one thing at a time.

yarikoptic · 2013-04-29T17:12:56Z

wholly molly -- indeed we must monitor both IN_MOVED_(TO|FROM) .... let me craft the unittest and probably the fix... thanks!

yarikoptic · 2013-04-29T17:56:54Z

@jafcobend could you give a try to this one?
yarikoptic@f215660

jafcobend · 2013-04-29T18:35:30Z

I grabbed a copy and will get this installed today. I'll let you know how it rolls next Monday.

yarikoptic · 2013-05-03T04:14:49Z

Ok -- I will think positive and consider it closed with f215660 which I have just pushed into master and 0.9

jafcobend · 2013-05-06T20:41:53Z

Gee! Whenever I think "positive" thinks go kaboom! However in your case it appears that the log rotation was detected as expected. It continued to ban IP addresses after the rotation. Thanks for fixing this!

yarikoptic · 2013-05-06T20:57:13Z

Great -- thanks for the confirmation!

On Mon, 06 May 2013, Jon Foster wrote:

Gee! Whenever I think "positive" thinks go kaboom! However in your case it
appears that the log rotation was detected as expected. It continued to
ban IP addresses after the rotation. Thanks for fixing this!

—
Reply to this email directly or [1]view it on GitHub.

References

Visible links

PyInotify fails after log rotation #184 (comment)

Yaroslav O. Halchenko, Ph.D.
http://neuro.debian.net http://www.pymvpa.org http://www.fail2ban.org
Senior Research Associate, Psychological and Brain Sciences Dept.
Dartmouth College, 419 Moore Hall, Hinman Box 6207, Hanover, NH 03755
Phone: +1 (603) 646-9834 Fax: +1 (603) 646-1419
WWW: http://www.linkedin.com/in/yarik

yarikoptic closed this as completed May 3, 2013

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

PyInotify fails after log rotation #184

PyInotify fails after log rotation #184

jafcobend commented Apr 22, 2013

yarikoptic commented Apr 22, 2013

jafcobend commented Apr 22, 2013

kwirk commented Apr 22, 2013

jafcobend commented Apr 22, 2013

yarikoptic commented Apr 22, 2013

some elderly box I have available

jafcobend commented Apr 22, 2013

jafcobend commented Apr 29, 2013

yarikoptic commented Apr 29, 2013

yarikoptic commented Apr 29, 2013

jafcobend commented Apr 29, 2013

yarikoptic commented May 3, 2013

jafcobend commented May 6, 2013

yarikoptic commented May 6, 2013

PyInotify fails after log rotation #184

PyInotify fails after log rotation #184

Comments

jafcobend commented Apr 22, 2013

yarikoptic commented Apr 22, 2013

jafcobend commented Apr 22, 2013

kwirk commented Apr 22, 2013

jafcobend commented Apr 22, 2013

yarikoptic commented Apr 22, 2013

some elderly box I have available

jafcobend commented Apr 22, 2013

jafcobend commented Apr 29, 2013

yarikoptic commented Apr 29, 2013

yarikoptic commented Apr 29, 2013

jafcobend commented Apr 29, 2013

yarikoptic commented May 3, 2013

jafcobend commented May 6, 2013

yarikoptic commented May 6, 2013