#994725 fail2ban: Fail2ban 0.11.2 exim failregexs don't match logs from Debian's exim 4.94.2

Package:
fail2ban
Source:
fail2ban
Submitter:
Diane Trout
Date:
2021-10-25 12:39:03 UTC
Severity:
normal
Tags:
#994725#5
Date:
2021-09-19 22:16:46 UTC
From:
To:
Dear Maintainer,

After activating the exim jail in fail2ban I noticed many failed login attempts
continuing to clutter up my logs.

Eventually I figured out the current failregex includ a pattern for the %(pid)s
that my current exim logs don't include.

It seems like default configuration of fail2ban should work with the default
configuration of Debian's log files.

I found similar reports of fail2ban not working with exim like:
https://systemadminspro.com/fail2ban-and-exim-on-ubuntu/

#994725#10
Date:
2021-10-23 14:22:12 UTC
From:
To:
Hello

Could you please resend the patch as attachement?

The content is broken as the lines aren't correct formatted.

Thanks

Sylvestre


Le 20/09/2021 à 00:16, Diane Trout a écrit :

#994725#15
Date:
2021-10-24 12:27:37 UTC
From:
To:
Hi Diane and Sylvestre,

Sorry to drop in, but I was also looking into this and am actually not
sure about Diane's patch. I found some completely different reasons for
why some log lines get missed.

I am also using fail2ban 0.11.2 with exim 4.94.2. Yes, I also see it
misses some lines, but I also still see a lot of lines being matched.

None of my log lines contains a `pid`, so I doubt that `%(pid)s` is
the reason for missing some lines.

Also, the `%(pid)s` part is actually defined as optional in
/etc/fail2ban/filter.d/exim-common.conf:

    pid = (?: \[\d+\])?

Also, what happens if someone does log `pid`, because with the patch
the filter will only expect whitespace, not a `pid` anymore.

Perhaps Diane is using a different log format or watching a different
log file than I do? Maybe affected by something like this issue where
the user had two timestamps in the log and was also able to solve it
by using a custom `pid` prefix:
- https://github.com/fail2ban/fail2ban/issues/3060
  (exim logs from journal do not match)

Furthermore, Diane's patch does two more things in addition to removing
the `%(pid)s` that I have doubts about:

First, the line about `SMTP call`: It seems the patch actually reverts
some improvements made between fail2ban 0.10.2 and 0.11.2, such as the
additional matching of `syntax or protocol errors` and
`last command was`. I do not see why this is necessary.

Second, Diane's patch adds a new line to the filter to also match
lines containing `LOGIN authentication mechanism not supported`. I do
not know if this is a good addition, I do not need it myself, but
either way, as far as I can tell this is simply not in the upstream
filter. I wonder if this is not a bit too big of a Debian-specific
deviation from upstream. Perhaps it should better be forwarded or
directly submitted upstream.


Actually, I found some other reasons for why fail2ban misses some log
lines:

Example 1: `SMTP call` in exim 4.94.2 has a new field at the end.

exim 4.92:
    2021-08-28 08:40:29 SMTP call from census9.shodan.io [71.6.167.142] dropped: too many syntax or protocol errors (last command was "?")

exim 4.94.2:
    2021-10-14 17:20:55 SMTP call from census6.shodan.io [66.240.236.119] dropped: too many syntax or protocol errors (last command was "?", NULL)

fail2ban 0.10.2 misses both, because `syntax or protocol errors` was
only added in 0.11.2.

fail2ban 0.11.2 matches the exim 4.92 line, but not the 4.94.2 line,
because it does not expect the last field (`, NULL`).


Example 2: No match on encrypted connections.

Already with the previous fail2ban 0.10.2 + exim 4.92 and now still
with fail2ban 0.11.2 + exim 4.94.2.

exim 4.92 and 4.94.2, connection without TLS:
    2021-10-01 15:27:31 H=(win2012r2RDP) [77.247.110.246] F=<spameri@tiscali.it> rejected RCPT <spameri@tiscali.it>: relay not permitted
    2021-10-20 14:33:00 H=(win2012r2RDP) [77.247.110.115] F=<spameri@tiscali.it> rejected RCPT <spameri@tiscali.it>: relay not permitted
Both match with fail2ban 0.10.2 and 0.11.2.

exim 4.92 and 4.94.2, connection with TLS:
    2021-10-01 15:08:40 H=(xhU9K1I7) [119.91.134.193] X=TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256 CV=no F=<wvqk@edlp.nl> rejected RCPT <726357518@qq.com>: relay not permitted
    2021-10-17 08:52:37 H=(LH5pvsWxa) [36.25.57.206] X=TLS1.2:ECDHE_SECP256R1__RSA_SHA512__AES_256_GCM:256 CV=no F=<wvqk@edlp.nl> rejected RCPT <897855558@qq.com>: relay not permitted
Both missed by fail2ban 0.10.2 and 0.11.2.

I did not finish checking all missed lines, but I suspect there are
more specific causes that need to be addressed and doubt that removing
`%(pid)s` and reverting some parts to 0.10.2 is the right solution.

Best regards,
Peter

#994725#20
Date:
2021-10-25 04:34:01 UTC
From:
To:
Hm.

Those are fair comments I do think I added the LOGIN line because of my
specific installation. And there's are fundamental problems with using
regular expressions for log parsing.


I hadd also found this write up with a similar patch to what I'd
proposed.

https://systemadminspro.com/fail2ban-and-exim-on-ubuntu/

I think the problem with the %(pid)s optional pattern is that it leaves
a unneeded space in the pattern.

from
https://salsa.debian.org/python-team/packages/fail2ban/-/blob/master/config/filter.d/exim.conf#L24
the pattern
"^%(pid)s SMTP protocol error in ..."

Wont match
"2021-10-24 00:28:54 SMTP protocol error in "AUTH LOGIN" H=(User) ...

because after stripping off the timestamp we're left with the pattern
"SMTP protocol..."  not being able to match "^ SMTP protocol..."

Maybe it'd work better if
filter.d/common.conf:24:__pid_re = (?:\[\d+\])

was instead something like:
filter.d/common.conf:24:__pid_re = (?:\[\d+\]) ?

Though maybe it needs to be a __pid_re specific to exim? or the
exim.conf pattern should allow blank spaces?

Something like "^%(pid)s *SMTP protocol..."


Diane

#994725#25
Date:
2021-10-25 12:37:35 UTC
From:
To:
Hi Diane,

Hmm, my log lines look the same and here they do match.

Maybe we can first compare output to find out what is the difference.
What output do you get for the following command:

    $ fail2ban-regex -v "2021-10-24 00:28:54 SMTP protocol error in \"AUTH LOGIN\" H=(user) [192.0.2.1] AUTH command used when not advertised" exim

This is what I get:

    Running tests
    =============

    Use   failregex filter file : exim, basedir: /etc/fail2ban
    Use      single line : 2021-10-24 00:28:54 SMTP protocol error in "AUTH L...


    Results
    =======

    Failregex: 1 total
    |-  #) [# of hits] regular expression
    |   1) [0] ^(?: \[\d+\])? (?:H=([\w.-]+ )?(?:\(\S+\) )?)?\[<HOST>\](?::\d+)?(?: I=\[\S+\](:\d+)?)?(?: U=\S+)?(?: P=e?smtp)?(?: F=(?:<>|[^@]+@\S+))?\ssender verify fail for <\S+>: (?:Unknown user|Unrouteable address|all relevant MX records point to non-existent hosts)\s*$
    |   2) [0] ^(?: \[\d+\])? \w+ authenticator failed for (?:[^\[\( ]* )?(?:\(\S*\) )?\[<HOST>\](?::\d+)?(?: I=\[\S+\](:\d+)?)?: 535 Incorrect authentication data( \(set_id=.*\)|: \d+ Time\(s\))?\s*$
    |   3) [0] ^(?: \[\d+\])? (?:H=([\w.-]+ )?(?:\(\S+\) )?)?\[<HOST>\](?::\d+)?(?: I=\[\S+\](:\d+)?)?(?: U=\S+)?(?: P=e?smtp)?(?: F=(?:<>|[^@]+@\S+))?\srejected RCPT [^@]+@\S+: (?:relay not permitted|Sender verify failed|Unknown user|Unrouteable address)\s*$
    |   4) [0] ^(?: \[\d+\])? SMTP protocol synchronization error \([^)]*\): rejected (?:connection from|"\S+") (?:H=([\w.-]+ )?(?:\(\S+\) )?)?\[<HOST>\](?::\d+)?(?: I=\[\S+\](:\d+)?)?(?: U=\S+)?(?: P=e?smtp)?(?: F=(?:<>|[^@]+@\S+))?\s(?:next )?input=".*"\s*$
    |   5) [0] ^(?: \[\d+\])? SMTP call from (?:[^\[\( ]* )?(?:H=([\w.-]+ )?(?:\(\S+\) )?)?\[<HOST>\](?::\d+)?(?: I=\[\S+\](:\d+)?)?(?: U=\S+)?(?: P=e?smtp)?(?: F=(?:<>|[^@]+@\S+))?\sdropped: too many (?:nonmail commands|syntax or protocol errors) \(last (?:command )?was "[^"]*"\)\s*$
    |   6) [1] ^(?: \[\d+\])? SMTP protocol error in "[^"]+(?:"+[^"]*(?="))*?" (?:H=([\w.-]+ )?(?:\(\S+\) )?)?\[<HOST>\](?::\d+)?(?: I=\[\S+\](:\d+)?)?(?: U=\S+)?(?: P=e?smtp)?(?: F=(?:<>|[^@]+@\S+))?\sAUTH command used when not advertised\s*$
    |      192.0.2.1  Sun Oct 24 00:28:54 2021
    |   7) [0] ^(?: \[\d+\])? no MAIL in SMTP connection from (?:[^\[\( ]* )?(?:\(\S*\) )?(?:H=([\w.-]+ )?(?:\(\S+\) )?)?\[<HOST>\](?::\d+)?(?: I=\[\S+\](:\d+)?)?(?: U=\S+)?(?: P=e?smtp)?(?: F=(?:<>|[^@]+@\S+))?\sD=\d\S*s(?: C=\S*)?\s*$
    |   8) [0] ^(?: \[\d+\])? (?:[\w\-]+ )?SMTP connection from (?:[^\[\( ]* )?(?:\(\S*\) )?(?:H=([\w.-]+ )?(?:\(\S+\) )?)?\[<HOST>\](?::\d+)?(?: I=\[\S+\](:\d+)?)?(?: U=\S+)?(?: P=e?smtp)?(?: F=(?:<>|[^@]+@\S+))?\sclosed by DROP in ACL\s*$
    `-

    Ignoreregex: 0 total

    Date template hits:
    |- [# of hits] date format
    |  [1] {^LN-BEG}ExYear(?P<_sep>[-/.])Month(?P=_sep)Day(?:T|  ?)24hour:Minute:Second(?:[.,]Microseconds)?(?:\s*Zone offset)?
    |  [0] {^LN-BEG}(?:DAY )?MON Day %k:Minute:Second(?:\.Microseconds)?(?: ExYear)?
    |  [0] {^LN-BEG}(?:DAY )?MON Day ExYear %k:Minute:Second(?:\.Microseconds)?
    |  [0] {^LN-BEG}Day(?P<_sep>[-/])Month(?P=_sep)(?:ExYear|ExYear2) %k:Minute:Second
    |  [0] {^LN-BEG}Day(?P<_sep>[-/])MON(?P=_sep)ExYear[ :]?24hour:Minute:Second(?:\.Microseconds)?(?: Zone offset)?
    |  [0] {^LN-BEG}Month/Day/ExYear:24hour:Minute:Second
    |  [0] {^LN-BEG}Month-Day-ExYear %k:Minute:Second(?:\.Microseconds)?
    |  [0] {^LN-BEG}Epoch
    |  [0] {^LN-BEG}ExYear2ExMonthExDay  ?24hour:Minute:Second
    |  [0] {^LN-BEG}MON Day, ExYear 12hour:Minute:Second AMPM
    |  [0] {^LN-BEG}ExYearExMonthExDay(?:T|  ?)Ex24hourExMinuteExSecond(?:[.,]Microseconds)?(?:\s*Zone offset)?
    |  [0] {^LN-BEG}(?:Zone name )?(?:DAY )?MON Day %k:Minute:Second(?:\.Microseconds)?(?: ExYear)?
    |  [0] {^LN-BEG}(?:Zone offset )?(?:DAY )?MON Day %k:Minute:Second(?:\.Microseconds)?(?: ExYear)?
    |  [0] {^LN-BEG}TAI64N
    |  [0] ExYear(?P<_sep>[-/.])Month(?P=_sep)Day(?:T|  ?)24hour:Minute:Second(?:[.,]Microseconds)?(?:\s*Zone offset)?
    |  [0] (?:DAY )?MON Day %k:Minute:Second(?:\.Microseconds)?(?: ExYear)?
    |  [0] (?:DAY )?MON Day ExYear %k:Minute:Second(?:\.Microseconds)?
    |  [0] Day(?P<_sep>[-/])Month(?P=_sep)(?:ExYear|ExYear2) %k:Minute:Second
    |  [0] Day(?P<_sep>[-/])MON(?P=_sep)ExYear[ :]?24hour:Minute:Second(?:\.Microseconds)?(?: Zone offset)?
    |  [0] Month/Day/ExYear:24hour:Minute:Second
    |  [0] Month-Day-ExYear %k:Minute:Second(?:\.Microseconds)?
    |  [0] Epoch
    |  [0] {^LN-BEG}24hour:Minute:Second
    |  [0] ^<Month/Day/ExYear2@24hour:Minute:Second>
    |  [0] ExYear2ExMonthExDay  ?24hour:Minute:Second
    |  [0] MON Day, ExYear 12hour:Minute:Second AMPM
    |  [0] ^MON-Day-ExYear2 %k:Minute:Second
    |  [0] ExYearExMonthExDay(?:T|  ?)Ex24hourExMinuteExSecond(?:[.,]Microseconds)?(?:\s*Zone offset)?
    |  [0] (?:Zone name )?(?:DAY )?MON Day %k:Minute:Second(?:\.Microseconds)?(?: ExYear)?
    |  [0] (?:Zone offset )?(?:DAY )?MON Day %k:Minute:Second(?:\.Microseconds)?(?: ExYear)?
    |  [0] TAI64N
    `-

    Lines: 1 lines, 0 ignored, 1 matched, 0 missed
    [processed in 0.00 sec]

I do not know `__pid_re` of `common.conf` very well. It seems it has
to do with the timestamp.

But you know there is already this definition in `exim-common.conf`,
right? This is the one I am seeing here with fail2ban 0.11.2-2 in
`/etc/fail2ban/filter.d/exim-common.conf`:

    pid = (?: \[\d+\])?

This definition of `pid` in `exim-common.conf` recently changed in the
master development branch, but I tested that as well and still get a
match with the latest definition of `pid` as well.

Btw, I see you are referencing an URL of the master development branch,
but I assume we are still only talking about 0.11.2 here.

Do you have any special customizations in `/etc/fail2ban/jail.d` maybe?

Best,
Peter