2

I've got an Ubuntu 20.04 server that's receiving hundreds of SMTP AUTH requests on my postfix server every day from the same IP. I have fail2ban installed, but ironically, it is failing to ban the IP.

My /etc/fail2ban/jail.local file is (<snip>'d bits are personal and business IPs):

[postfix-flood-attack]
enabled  = true
bantime  = 1h
filter   = postfix-flood-attack
action   = iptables-multiport[name=postfix, port="http,https,smtp,submission,pop3,pop3s,imap,imaps,sieve", protocol=tcp]
logpath  = /var/log/mail.log
ignoreip = <snip> 127.0.0.1/8
maxretry = 3

[postfix]
enabled = true
maxretry = 3
bantime = 1h
filter = postfix[mode=aggressive]
logpath = /var/log/mail.log
ignoreip = <snip> 127.0.0.1/8

[dovecot]
enabled = true
port = pop3,pop3s,imap,imaps
filter = dovecot
logpath = /var/log/mail.log
maxretry  = 3
ignoreip = <snip> 127.0.01/8

The jail in question is postfix-flood-attack, taken from the bottom of this tutorial. The /etc/fail2ban/filter.d/postfix-flood-attack.conf file is:

[Definition]
failregex = lost connection after AUTH from (.*)\[<HOST>\]
ignoreregex =

My log messages look like

Aug 15 13:54:45 ikana postfix/smtps/smtpd[268729]: connect from unknown[193.35.48.18]
Aug 15 13:54:46 ikana postfix/smtps/smtpd[268729]: Anonymous TLS connection established from unknown[193.35.48.18]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Aug 15 13:54:50 ikana postfix/smtps/smtpd[268729]: warning: unknown[193.35.48.18]: SASL PLAIN authentication failed:
Aug 15 13:54:50 ikana postfix/smtps/smtpd[268729]: lost connection after AUTH from unknown[193.35.48.18]
Aug 15 13:54:50 ikana postfix/smtps/smtpd[268729]: disconnect from unknown[193.35.48.18] ehlo=1 auth=0/1 commands=1/2
Aug 15 13:54:50 ikana postfix/smtps/smtpd[268729]: connect from unknown[193.35.48.18]
Aug 15 13:54:51 ikana postfix/smtps/smtpd[268729]: Anonymous TLS connection established from unknown[193.35.48.18]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Aug 15 13:54:57 ikana postfix/smtps/smtpd[268729]: lost connection after AUTH from unknown[193.35.48.18]
Aug 15 13:54:57 ikana postfix/smtps/smtpd[268729]: disconnect from unknown[193.35.48.18] ehlo=1 auth=0/1 commands=1/2
Aug 15 13:54:57 ikana postfix/smtps/smtpd[268729]: connect from unknown[193.35.48.18]
Aug 15 13:54:58 ikana postfix/smtps/smtpd[268729]: Anonymous TLS connection established from unknown[193.35.48.18]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Aug 15 13:55:04 ikana postfix/smtps/smtpd[268729]: lost connection after AUTH from unknown[193.35.48.18]
Aug 15 13:55:04 ikana postfix/smtps/smtpd[268729]: disconnect from unknown[193.35.48.18] ehlo=1 auth=0/1 commands=1/2
Aug 15 13:55:04 ikana postfix/smtps/smtpd[268734]: connect from unknown[193.35.48.18]
Aug 15 13:55:05 ikana postfix/smtps/smtpd[268734]: Anonymous TLS connection established from unknown[193.35.48.18]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Aug 15 13:55:09 ikana postfix/smtps/smtpd[268734]: warning: unknown[193.35.48.18]: SASL PLAIN authentication failed:
Aug 15 13:55:09 ikana postfix/smtps/smtpd[268734]: lost connection after AUTH from unknown[193.35.48.18]
Aug 15 13:55:09 ikana postfix/smtps/smtpd[268734]: disconnect from unknown[193.35.48.18] ehlo=1 auth=0/1 commands=1/2

According to fail2ban-regex, this should work, but the IP is not being banned. The output of the command fail2ban-regex /var/log/mail.log /etc/fail2ban/filter.d/postfix-flood-attack.conf is:

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

Use   failregex filter file : postfix-flood-attack, basedir: /etc/fail2ban
Use         log file : /var/log/mail.log
Use         encoding : UTF-8


Results
=======

Failregex: 5356 total
|-  #) [# of hits] regular expression
|   1) [5356] lost connection after AUTH from (.*)\[<HOST>\]
`-

Ignoreregex: 0 total

Date template hits:
|- [# of hits] date format
|  [37949] {^LN-BEG}(?:DAY )?MON Day %k:Minute:Second(?:\.Microseconds)?(?: ExYear)?
`-

Lines: 37949 lines, 0 ignored, 5356 matched, 32593 missed
[processed in 1.43 sec]

Missed line(s): too many to print.  Use --print-all-missed to print all 32593 lines

So it finds a match for 5,356 logs, and never bans any. There are usually 8 attempts within the default 10 minute lookup time. A snippet of using the -v option with fail2ban-regex shows the following matches with timestamps:

...
193.35.48.18  Thu Aug 15 13:50:55 2019
193.35.48.18  Thu Aug 15 13:51:02 2019
193.35.48.18  Thu Aug 15 13:51:10 2019
193.35.48.18  Thu Aug 15 13:51:15 2019
193.35.48.18  Thu Aug 15 13:54:50 2019
193.35.48.18  Thu Aug 15 13:54:57 2019
193.35.48.18  Thu Aug 15 13:55:04 2019
193.35.48.18  Thu Aug 15 13:55:09 2019
193.35.48.18  Thu Aug 15 13:58:40 2019
193.35.48.18  Thu Aug 15 13:58:48 2019
193.35.48.18  Thu Aug 15 13:58:54 2019
193.35.48.18  Thu Aug 15 13:58:59 2019
...
anx
  • 6,875
  • 4
  • 22
  • 45
Zalerinian
  • 111
  • 1
  • 5
  • In my experience the fault doesn't always lie with Fail2ban and one has to look at the upstream firewall. In your case in curious about the `action =` line. Are you sure your firewall is getting the message from Fail2ban? – Eugene van der Merwe Jun 28 '22 at 16:49
  • As stated in my answer below, in my case the issue was related to changing the timezone used for the system/services, and not restarting the server. – Zalerinian Jun 29 '22 at 17:22

2 Answers2

2

The configuration looks good, but there's one important detail to notice with the output of fail2ban-regex: It decided that the dates are from 2019. Given what the logs look like in the question, this seemed rather stupid at first. Turns out that this is somewhat of a known problem with fail2ban, something they reference as the TZ-issue. After configuring your server to use a specific timezone, you need to either restart a bunch of services, or restart the whole system for it to take effect properly. Though I can't remember how long it's been, I guess I never restarted my server since configuring the timezone on it.

After restarting the syslog service via systemctl restart syslog, fail2ban recognized log lines in the correct time zone.

Fail2ban immediately recognized log messages in the configured find time, and banned the IP that has been plaguing my server for days. I guess Fail2ban asks syslog for the timezone information instead of using what was set on the machine since the fail2ban-server was started.

I hope this is able to help someone else with a similar issue.

Zalerinian
  • 111
  • 1
  • 5
  • 1
    `uptime -s` will report the time of your last system start.. expressed in your currently active timezone. – anx Aug 16 '20 at 13:18
0

The ambiguity that caused fail2ban to assume those dates were in 2019 can not occur when you use standard date formatting. You can avoid the issue completely issues by using ISO 8601 - you might not have any good reason left to stick with backwards-compatible log formatting in 2020.

Also, in Ubuntu, you likely can skip the date formatting/parsing completely, by instructing fail2ban to consume systemd journal directly, which provides plain offsets from epoch without timezone information (try backend = systemd in the [DEFAULT] block in local jail configuration).

anx
  • 6,875
  • 4
  • 22
  • 45
  • My `fail2ban.conf` doesn't have a `backend` parameter, and I don't see one documented anywhere. I don't think the issue was really that the timezone was formatted wrong - the logs are still formatted exactly the same. The issue was that fail2ban interpreted log dates wrong, presumably because it got the old time zone setting from syslog, and therefore every date was well outside the `findtime` setting. I suppose changing the date format would have helped with it, but I don't expect to need to change the timezone anymore. Thank you, though. – Zalerinian Aug 16 '20 at 16:17