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.

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

[BR]: fail2ban.filterpyinotify: WARNING Unable to retrieve Watch object messages on service shutdown #3496

Open
3 tasks done
opoplawski opened this issue Apr 14, 2023 · 5 comments
Assignees
Labels

Comments

@opoplawski
Copy link
Contributor

Environment:

  • Fail2Ban version : 1.0.2-3.el8
  • OS, including release name/version : AlmaLinux 8.7
  • Fail2Ban installed via OS/distribution mechanisms
  • You have not applied any additional foreign patches to the codebase
  • Some customizations were done to the configuration (provide details below is so)

The issue:

On service/machine shutdown we see this message in the logs. Similar to #2256 but not related to logrotate. I know it's just a warning but it shows up in logwatch and it seems like during normal operation this shouldn't be generated.

Steps to reproduce

I suspect the use of the recidive jail monitoring /var/log/fail2ban.log may be the trigger, but hard to say. It doesn't happen with every shutdown.

Expected behavior

No WARNINGs

Observed behavior

2023-04-14 14:44:29,677 fail2ban.jail           [70000]: DEBUG   Stopping jail 'recidive'
2023-04-14 14:44:29,678 fail2ban.filterpyinotify[70000]: DEBUG   Event queue size: 16
2023-04-14 14:44:29,678 fail2ban.filterpyinotify[70000]: DEBUG   <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2023-04-14 14:44:29,678 fail2ban.filterpyinotify[70000]: DEBUG   Event queue size: 16
2023-04-14 14:44:29,679 fail2ban.filterpyinotify[70000]: DEBUG   <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2023-04-14 14:44:29,679 fail2ban.filterpyinotify[70000]: DEBUG   Event queue size: 16
2023-04-14 14:44:29,679 fail2ban.filterpyinotify[70000]: DEBUG   <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2023-04-14 14:44:29,680 fail2ban.filterpyinotify[70000]: DEBUG   Event queue size: 16
2023-04-14 14:44:29,680 fail2ban.filterpyinotify[70000]: DEBUG   <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2023-04-14 14:44:29,680 fail2ban.filter         [70000]: INFO    Removed logfile: '/var/log/fail2ban.log'
2023-04-14 14:44:29,680 fail2ban.filterpyinotify[70000]: DEBUG   Event queue size: 16
2023-04-14 14:44:29,681 fail2ban.filterpyinotify[70000]: DEBUG   <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2023-04-14 14:44:29,681 fail2ban.filterpyinotify[70000]: DEBUG   Watch WD=2 (None) removed
2023-04-14 14:44:29,681 fail2ban.filterpyinotify[70000]: WARNING Unable to retrieve Watch object associated to <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2023-04-14 14:44:29,681 fail2ban.filterpyinotify[70000]: DEBUG   Removed file watcher for /var/log/fail2ban.log
2023-04-14 14:44:29,682 fail2ban.filterpyinotify[70000]: DEBUG   Event queue size: 32
2023-04-14 14:44:29,682 fail2ban.filterpyinotify[70000]: DEBUG   Watch WD=1 (None) removed
2023-04-14 14:44:29,682 fail2ban.filterpyinotify[70000]: DEBUG   <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2023-04-14 14:44:29,682 fail2ban.filterpyinotify[70000]: DEBUG   Removed monitor for the parent directory /var/log
2023-04-14 14:44:29,682 fail2ban.filterpyinotify[70000]: DEBUG   <_RawEvent cookie=0 mask=0x8000 name='' wd=2 >
2023-04-14 14:44:29,683 fail2ban.filterpyinotify[70000]: DEBUG   [recidive] filter exited (pyinotifier)
@opoplawski opoplawski added the bug label Apr 14, 2023
@sebres sebres self-assigned this Apr 24, 2023
@sebres
Copy link
Contributor

sebres commented Apr 24, 2023

In #2256 (comment) I asked about 3 ways how it would "fixable".
Well, not quite correct - #3027 (comment) could be another one.
Which one would you prefer?

@opoplawski
Copy link
Contributor Author

Hmm, I was thinking that perhaps there was something wrong with the way the fail2ban was removing the watch. But perhaps it is really an issue in pyinotify. Though hard to tell at this point. Does this seem like a possibility:

  • an event comes into the queue for /var/log/fail2ban.log
  • we delete the watch on /var/log/fail2ban.log
  • process_events() gets run, pulls the event for which there is no longer a watcher?

If so, is there some way we can make sure all of the events are processed before deleting the watch?

@sebres
Copy link
Contributor

sebres commented Apr 26, 2023

If so, is there some way we can make sure all of the events are processed before deleting the watch?

Sure, one can retard watch deletion a bit. Just I'm unsure it'd help, because then the handler will be closed earlier and a WatchManager work asynchronously, so after all it should not introduce vice versa situation.
I'll check whether it is somehow possible to unregister watch object without to pause WatchManager (to avoid misses).

@PVasileff
Copy link

PVasileff commented Jun 20, 2023

Same here.

Fail2ban version 1.1.0.1, AlmaLinux 8.

Installed with:

python3 setup.py install

In fail2ban.log I see that after logrotate:

2023-06-20 03:29:01,581 fail2ban.server         [1129011]: INFO    rollover performed on /var/log/fail2ban.log
2023-06-20 03:29:04,198 fail2ban.filterpyinotify[1129011]: WARNING Unable to retrieve Watch object associated to <_RawEvent cookie=0 mask=0x2 name='' wd=9 >
2023-06-20 03:29:06,054 fail2ban.filterpyinotify[1129011]: WARNING Unable to retrieve Watch object associated to <_RawEvent cookie=0 mask=0x2 name='' wd=9 >
2023-06-20 03:29:11,543 fail2ban.filterpyinotify[1129011]: WARNING Unable to retrieve Watch object associated to <_RawEvent cookie=0 mask=0x2 name='' wd=9 >
2023-06-20 03:29:44,477 fail2ban.filterpyinotify[1129011]: WARNING Unable to retrieve Watch object associated to <_RawEvent cookie=0 mask=0x2 name='' wd=9 >

and random times before and after that has no fail2ban actions:

2023-06-20 07:00:37,222 fail2ban.filterpyinotify[1129011]: WARNING Unable to retrieve Watch object associated to <_RawEvent cookie=0 mask=0x2 name='' wd=10 >
2023-06-20 07:00:38,422 fail2ban.filterpyinotify[1129011]: WARNING Unable to retrieve Watch object associated to <_RawEvent cookie=0 mask=0x2 name='' wd=10 >
2023-06-20 07:00:44,499 fail2ban.filterpyinotify[1129011]: WARNING Unable to retrieve Watch object associated to <_RawEvent cookie=0 mask=0x2 name='' wd=10 >
2023-06-20 07:00:56,059 fail2ban.filterpyinotify[1129011]: WARNING Unable to retrieve Watch object associated to <_RawEvent cookie=0 mask=0x2 name='' wd=10 >

And one more thing - when I copy systemctl service file with:

cp /opt/fail2ban/build/fail2ban.service /etc/systemd/system/

in service file contain line:

Environment="PYTHONNOUSERSITE=1"

and reloading or restart fail2ban via systemctl - fail2ban doesn't start.
When I remove the line abow with Environment - its ok.

@sebres
Copy link
Contributor

sebres commented Jun 20, 2023

Same here.

The "issue" is already confirmed... And as one can see still open (since there is no simple solution for that, because the warning is throwing from pyinotify module itself (after we allowed to log from there).
Your comment seems not provide new info, did it?

Environment="PYTHONNOUSERSITE=1"
fail2ban doesn't start.
When I remove the line abow with Environment - its ok.

It has nothing to do with the issue here.
It looks like something (fail2ban modules or some dependencies) got installed as user modules.
Then it's clear that disabling them would cause erroneous start of fail2ban.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

3 participants