fail2ban v0.10.5 does not interact well with rsyslog (centos)

[nlameiras]

Hello,

centos : 7.7.1908
fail2ban : v0.10.5
rsyslogd : 8.24.0-41.el7_7.2

We use SYSLOG to manage logs (send to distant log server and then write to locally to /var/log/fail2ban.log)

Since updating fail2ban, rsyslog is not able to parse fail2ban logs (this is true with dozens of differents installations)

Upon close investigation, we found that the rsyslog expression

if $programname contains 'fail2ban' then /var/log/fail2ban.log

is not working anymore. Where rsyslog should read 'fail2ban', instead the value in log is 'journal' .
This is weird...

If we use the following rsyslog configuration

if $programname contains 'journal' then /var/log/fail2ban.log

everything works as expected, but I'm guessing that 'journal' is not (and should not be) fail2ban programname.

Is this a bug, or am I missing something?

[sebres]

Hmm... I don't see what exactly can cause this... possibly excepting f3dbc9d, but fail2ban main (server) thread was called f2b/server there (by the way it is fixed in 3f48907).

Where the process can obtain name journal is not really clear to me.
It may be also some "configuration" of the unit-file starting fail2ban.

I would like to know how fail2ban-server is started (e. g. service, unit- or init-script) and how the start parameters for logging do look.

[nlameiras]

service file is vanilla from centos 7

/etc/systemd/system/multi-user.target.wants/fail2ban.service

[Unit]
Description=Fail2Ban Service
Documentation=man:fail2ban(1)
After=network.target iptables.service firewalld.service ip6tables.service ipset.service nftables.service
PartOf=firewalld.service
[Service]
Type=simple
ExecStartPre=/bin/mkdir -p /run/fail2ban
ExecStart=/usr/bin/fail2ban-server -xf start
# if should be logged in systemd journal, use following line or set logtarget to sysout in fail2ban.local
# ExecStart=/usr/bin/fail2ban-server -xf --logtarget=sysout start
ExecStop=/usr/bin/fail2ban-client stop
ExecReload=/usr/bin/fail2ban-client reload
PIDFile=/run/fail2ban/fail2ban.pid
Restart=on-failure
RestartPreventExitStatus=0 255

[Install]
WantedBy=multi-user.target

This is our local fail2ban logging configuration

/etc/fail2ban/fail2ban.local

[Definition]
logtarget = SYSLOG
loglevel = NOTICE

edit : sorry for multiples edits...

[sebres]

One thing around SYSLOG that was changed is 1bf6636 (see #1980), and I'm not sure it'd really affect that... and this was released already in 0.10.2.
You meant "Since updating fail2ban, rsyslog is not able to parse fail2ban logs"...
So updating from which version?

I see also ` character at end of ExecStart. Is it really so (or just some edit by your side)?

Since python 3.3 sysloghandler got an attribute (ident) to specify the program logging identifier (which we current still don't use if I remember correctly). Without this it is normally argv[0], so I'd rather expect python as program name (before and now). So I still don't follow what exactly can cause that.

[nlameiras]

` character at end of ExecStart is indeed an edit artifact. sorry about that.

Previous "working" version of fail2ban was fail2ban-0.9.7-1.el7.noarch

Not sure if it helps, but this is the kind of log that we have now :
May 5 17:22:38 XXhostnameXX journal: fail2ban.actions [27434]: NOTICE [apache-scan-robot] Unban XXipXX

where before, when it was working it was :
Mar 15 10:47:09 XXhostnameXX fail2ban.actions[20963]: NOTICE [apache-bad-request] Ban XXipXX

[sebres]

OK.
What I also don't understand in your example log-line ... fail2ban.actions [27434] ..., where is a space between module name and [pid] is coming from.
Because default syslog-format is %(name)s[%(process)d]: %(levelname)s %(message)s.
It looks like it may be an issue of systemd-journal to rsyslog wrapper (at least together with syslog logging handler of python).
Maybe a correct way were to use systemd journal instead of rsyslog (with forwarding to file and a log-server)?

Anyway I cannot reproduce it on my debians.

Here are several possibilities you could try:

1. systemd unit has a parameter SyslogIdentifier. So may be setting of this can help.
   Try to run systemctl edit fail2ban and add this to override config-file:

[Service]
SyslogIdentifier=fail2ban

2. The default facility of syslog handler seems to be LOG_USER and current implementation uses LOG_DAEMON instead.

Could you please check what would happen using this setting:

logtarget = SYSLOG[facility=user]

3. Another variant would be possibly attempting to play with some custom format, but I don't know which exactly may cause that. As already said the default should look like this:

# logtarget = SYSLOG[format="%(name)s[%(process)d]: %(levelname)s %(message)s"]
logtarget = SYSLOG[format="fail2ban %(name)s[%(process)d]: %(levelname)s %(message)s"]

4. Or even to extend "fail2ban/server/server.py" with some ident:

hdlr = logging.handlers.SysLogHandler(
	self.__syslogSocket, facility=facility)
+ hdlr.ident = 'fail2ban'

I don't think it'd help (related to python source code it would be similar to variant 3), but...
Default ident seems to be empty (so it doesn't add something to message in emit method), but I don't know what a logging from systemd unit can cause in this case.
https://github.com/python/cpython/blob/2353e35570ba5432cc1335c3926f8e5118c6404e/Lib/logging/handlers.py#L772

[nlameiras]

• .2 and .4 gave no visible results...

• .3 yeld some errors, not sure I made it correctly

May  6 20:58:48 xxHOSTNAMExx fail2ban: 2020-05-06 20:58:48,837 fail2ban                [5256]: ERROR   Init of command line failed
May  6 20:58:48 xxHOSTNAMExx fail2ban: ERROR: Bad value substitution:
May  6 20:58:48 xxHOSTNAMExx fail2ban: section: [Definition]
May  6 20:58:48 xxHOSTNAMExx fail2ban: option : logtarget
May  6 20:58:48 xxHOSTNAMExx fail2ban: key    : name
May  6 20:58:48 xxHOSTNAMExx fail2ban: rawval : [%(process)d]: %(levelname)s %(message)s"]

• while implementing .1, I found some interesting results :

Before change this is the content from 'journalctl' :

May  6 20:48:51 xxHOSTNAMExx fail2ban-server: Server ready
May  6 20:49:19 xxHOSTNAMExx fail2ban-client: Shutdown successful
May 06 20:52:29 xxHOSTNAMExx f2b/server[4291]: fail2ban.actions [4291]: NOTICE [apache-ddos] Flush ticket(s) with iptables-multiport
May 06 20:52:29 xxHOSTNAMExx f2b/server[4291]: fail2ban.actions [4291]: NOTICE [apache-bad-request] Flush ticket(s) with iptables-multiport

After change this is the content from 'journalctl' :

May  6 20:47:24 xxHOSTNAMExx fail2ban: Server ready
May  6 20:47:27 xxHOSTNAMExx fail2ban: Shutdown 
May 06 20:52:29 xxHOSTNAMExx f2b/server[4291]: fail2ban.actions [4291]: NOTICE [apache-ddos] Flush ticket(s) with iptables-multiport
May 06 20:52:29 xxHOSTNAMExx f2b/server[4291]: fail2ban.actions [4291]: NOTICE [apache-bad-request] Flush ticket(s) with iptables-multiport

In both cases, the 2 last lines containing fail2ban.actions will be logged on /var/log/messages with 'f2b/server' tag replaced by 'journal':

May  6 20:52:29 xxHOSTNAMExx journal: fail2ban.actions [4291]: NOTICE [apache-ddos] Flush ticket(s) with iptables-multiport
May  6 20:52:29 xxHOSTNAMExx journal: fail2ban.actions [4291]: NOTICE [apache-bad-request] Flush ticket(s) with iptables-multiport

These are my conclusions, fell free to correct me if I'm wrong :

1. There are at least 3 different programnames in journalctl concerning fail2ban before change : fail2ban-client, fail2ban-server, f2b/server.

2. When setting SyslogIdentifier=fail2ban, fail2ban-client AND fail2ban-server both become fail2ban (as expected). On the other hand, f2b/server[4291]: fail2ban.actions[4291] remains inchanged (why?)

3. In both cases, when logs are directed to /var/log/messages, f2b/server gets replaced by journal which leads me to believe that something strange occurs. maybe the '/' causes confusion ?

My supposition :
'f2b/server' was introduced recently. This messes with rsyslog internal parsing, and a weird behaviour occurs, ie. programname is not well identified, and it gets confused with 'journal:'

is this plausible?

[sebres]

There are at least 3 different programnames in journalctl concerning fail2ban before change : fail2ban-client, fail2ban-server, f2b/server.

Yes, because fail2ban-client & fail2ban-server are the caller inside systemd unit, so the output of them is logged from systemd in journal with the process name.

On the other hand, f2b/server[4291]: fail2ban.actions[4291] remains unchanged (why?)

It looks like SyslogIdentifier would affect the stdout/stderr only.
In this case setting logtarget to sysout (a bit cutoff variant of stdout without timestamp in log-line) could help.
This is also normally recommended setting for systemd-unit if one want to log from fail2ban to systemd journal (see the comment below ExecStart in your fail2ban.service).

In both cases, when logs are directed to /var/log/messages, f2b/server gets replaced by journal which leads me to believe that something strange occurs. maybe the '/' causes confusion ?

I don't know, looks indeed strange (at least I did not find that in journal docu's).

Since the fix 3f48907, it is reverted to fail2ban-server back and it is possible to set the process name in fail2ban unit by yourself (using --pname <NAME> parameters). Possibly you can apply this as patch and test that on some of your system?

Also I don't know how your supposition is plausible, because I cannot reproduce it at all (and don't have centos ready to hand to test that there).

[sebres]

So I assume it is solved (looks anyway as 3rd party issue to me).
And either 3f48907, or a switch to sysout (by journal logging) would do the job ultimately.