Fail2ban: postfix-failedauth - new proposed filter

[dominicraf]

This is an enhancement suggestion - for a new filter which I have been using for many months with great success. I call it 'postfix-failedauth' and it is effective in blocking bots that attempt smtp authentication under postfix.

Tested under fail2ban 0.9.x and 0.10.2

postfix-failedauth.conf.txt

[sebres]

Can you provide a complete log-excerpt of such connect try (I meant all messages of single attempt from begin to end)...
Just to see difference resp. to check why the default postfix-filter doesn't catch the auth-failure.

[dominicraf]

sure, here is a very recent one that led to a postfix-failedauth ban:

2018-08-14 15:04:55 streamingbats postfix/smtpd[13942]: connect from 25.53.99.138.yukanet.com.br[138.99.53.25]
2018-08-14 15:04:56 streamingbats postfix/smtpd[13942]: disconnect from 25.53.99.138.yukanet.com.br[138.99.53.25] helo=1 auth=0/1 quit=1 commands=2/3

[dominicraf]

I admit I am not using the default postfix.conf ban (which seems to have changed a lot since 0.9), but from what I can see it would not pick this up.

You will see in the file a commented-out version of the ban which aligns precisely with what Wietse wrote in the postfix announcement (quoted at top of file), but in practice the more aggressive regex is much more effective.

[sebres]

it is effective in blocking bots that attempt smtp authentication under postfix.

It is possible, that this bots don't try to authenticate at all. If you take a look attentive to the disconnect log-message helo=1 auth=0/1 quit=1 commands=2/3 you'll see 2 from 3 commands executed, so 1 helo, and 1 quit (and 0 from 1 authentication attempts).
In this case it looks like the bots doing something DDOS-similar (or rather something like a port scanning), so no failures in normal sense of fail2ban occur.

We have different modes in newer version of fail2ban (also ddos and aggressive), so indeed we can extend our standard filter with this regex to capture it if jail configured using mode like this.

But I'm really confused about the documentation:

Per-session command profiles, logged at the end of each inbound SMTP session. For example, a password-guessing bot is logged as "disconnect from name[addr] ehlo=1 auth=0/1 commands=1/2", meaning that the client sent one EHLO command that worked, one AUTH command that failed, and hung up without sending a QUIT command. This information is always logged, and can help to solve puzzles without verbose logging or network sniffers.

The question is - why postfix does not log another messages (like authentication failed) in this case.

Which log-file do you observed (possibly just wrong log-file)? Or it is systemd-journal with all messages from postfix server?
And do you really not see any other message of 138.99.53.25?

[dominicraf]

From the documentation I think that auth=0/1 means 'authentication succeeded x 0 and was attempted x 1'. On my server, smtp authentication at port 25 will always fail because authentication is only allowed on ports 587 or 465. I guess this is why postfix doesn't log a separate message saying authentication failed. I see that where authentication is tried on port 587 there is such a message:

2018-08-14 14:13:39 streamingbats postfix/submission/smtpd[24409]: warning: hostname bilink-131-bgp99.bilink.com.br does not resolve to address 177.221.99.131: Name or service not known
2018-08-14 14:13:39 streamingbats postfix/submission/smtpd[24409]: connect from unknown[177.221.99.131]
2018-08-14 14:13:42 streamingbats postfix/submission/smtpd[24409]: Anonymous TLS connection established from unknown[177.221.99.131]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
2018-08-14 14:13:45 streamingbats postfix/submission/smtpd[24409]: warning: unknown[177.221.99.131]: SASL PLAIN authentication failed:
2018-08-14 14:13:51 streamingbats postfix/submission/smtpd[24409]: warning: unknown[177.221.99.131]: SASL LOGIN authentication failed: VXNlcm5hbWU6
2018-08-14 14:13:51 streamingbats postfix/submission/smtpd[24409]: lost connection after AUTH from unknown[177.221.99.131]
2018-08-14 14:13:51 streamingbats postfix/submission/smtpd[24409]: disconnect from unknown[177.221.99.131] ehlo=2 starttls=1 auth=0/2 commands=3/5

I am monitoring file /var/log/mail.log (where all my mail-related messages are placed). The only entries in this file with this IP 138.99.53.25 are identical to the two I posted before, but at different times over the last two days (it happens a few times, it gets banned, it gets unbanned, it happens again...)

[sebres]

because authentication is only allowed on ports 587 or 465. I guess this is why postfix doesn't log a separate message

Hmm... This is confusing, one expects nevertheless something like authentication disallowed, unexpected authentication or any similar message.

I see that where authentication is tried on port 587 there is such a message

Well this is also not good, because if this new rule going enabled in default fail2ban postfix-filter, in this case one will get 2 failures captured for exactly 1 attempt (one match for authentication failed and another for disconnect from), what leads to unexpected overflow of max attempts count configured for jail (because maxretry is reached sooner)...

I don't know right now what we should do here or for which mode it should be enabled per default...

[dominicraf]

Checking my logs I am clear that auth=0 message is always logged at the end of a connection when there is a failed authentication (or more than one), but only once for each connection, whereas authentication failed is only logged where authentication is permitted, but is logged for each authentication attempt (often there are several per connection).

I agree we need to consider the possibility to count 2 failures for one attempt. The best way to avoid this IMO is to have two different filters/jails, one [postfix-failedauth] picks up auth=0 and the other [postfix] picks up authentication failed.

[sebres]

The best way to avoid this IMO is to have two different filters/jails...

Don't like it because at the moment the second jail just produces more (almost dual) load.
The athentication does not happen ('cause disallowed), so it is just to ban rude bots (or to shorten the log-overhead a bit)...
I have a newer version (heavy nightly, WiP), where it does not matter how many jails one have to observe the same log-file (or journal), so maybe there...

/me needs a time to reflect in silence.

[dominicraf]

np I will let you have the silence and wish you success - thanks for all your great work on fail2ban...

[BlackWiCKED]

My mail.log is also full with such entries. The common part is _auth=0/1_.

Jan  2 22:54:52 server postfix/smtpd[3703]: connect from unknown[196.203.149.25]
Jan  2 22:54:53 server postfix/smtpd[3703]: disconnect from unknown[196.203.149.25] helo=1 auth=0/1 quit=1 commands=2/3
Jan  2 22:56:02 server postfix/smtpd[3703]: connect from unknown[190.213.10.158]
Jan  2 22:56:02 server postfix/smtpd[3703]: disconnect from unknown[190.213.10.158] helo=1 auth=0/1 quit=1 commands=2/3
Jan  2 23:03:08 server postfix/smtpd[3720]: connect from 220-134-195-68.HINET-IP.hinet.net[220.134.195.68]
Jan  2 23:03:10 server postfix/smtpd[3720]: disconnect from 220-134-195-68.HINET-IP.hinet.net[220.134.195.68] helo=1 auth=0/1 quit=1 commands=2/3

Any solutions or suggestions you can recommend?

[dominicraf]

@BlackWiCKED did you try the filter I posted at the top of this thread?

[BlackWiCKED]

@dominicraf I have not yet, but it seems to be some kind of solution. Will give it a try, but to be honest an official solution would be more desirable. I don't know much about smtpd error messages, or why these entries are appearing in the log without an actual error thrown, but I do see that it happens very often, and I'm getting like 20 individual attempts every hour. Also not sure how common the issue is, or how many of us have their own email servers up and running, but I guess the number is not too high.

[BlackWiCKED]

It works pretty well so far, was not sure about port, etc... but I hope it did not break anything important. At least no signs of that yet. Will keep a close eye on it for a few more days, or until an official solution comes out. Thanks for the regex @dominicraf .

By the way, I'm using the following jail config:

[postfix-failedauth]

enabled  = true
port     = smtp,ssmtp,submission
filter   = postfix-failedauth
logpath  = /var/log/mail.log
bantime = 604800  ; 1 week
findtime = 86400  ; 1 day
maxretry = 2

[kryptus36]

I just implemented this and immediately eliminated attempts being missed by the default postfix filter.

In my case I do see an auth failed message as I allow auth on port 25, but it's different enough that it's missed.

Nov  7 17:26:21 marvin postfix/smtpd[2548]: connect from unknown[92.118.38.54]
Nov  7 17:26:32 marvin postfix/smtpd[2548]: warning: unknown[92.118.38.54]: SASL LOGIN authentication failed: authentication failure
Nov  7 17:26:34 marvin postfix/smtpd[2548]: disconnect from unknown[92.118.38.54] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4

I'm not sure of the correct way to implement this as part of the postfix filter, but for right now, having this as a separate jail will save me headaches.

[ghost]

I add the problem and this filter solved it! Thank you.

[andresanz]

is it "filter = postfix-failedauth" or "filter = postfix.failedauth"?

[dominicraf]

"filter = postfix-failedauth

On Sat, 8 Feb 2020, 21:48 André Sanz, [e-mail] wrote:

is it "filter = postfix-failedauth" or "filter = postfix.failedauth"?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/fail2ban/fail2ban/issues/2200?email_source=notifications&email_token=AABLOCVU3CVL3RRGQJXF2T3RB4R5RA5CNFSM4FPSFMYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOELF4N7I#issuecomment-583780093,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AABLOCUWXP5NVRMG27LDSGLRB4R5RANCNFSM4FPSFMYA
.

[payapony]

I created the file postfix-failedauth.conf at /etc/fail2ban/filter.d/
and at jail.local I have this config:

[postfix-failedauth]
enabled = true
port = smtp,ssmtp,submission
filter = postfix-failedauth
logpath = /var/log/syslog
bantime = -1
findtime = 1800
maxretry = 1
banaction = iptables-multiport

But checking the fail2ban.log I receive errors.

                                    fail2ban.transmitter    [31376]: WARNING Command ['set', 'postfix-failedauth', 'maxlines', 'None'] has failed. Received ValueError("invalid literal for int() with base 10: 'None'")

2021-01-21 23:13:02,699 fail2ban [31376]: ERROR NOK: ("invalid literal for int() with base 10: 'None'",)
2021-01-21 23:13:02,701 fail2ban.datedetector [31376]: INFO date pattern 'None': None
2021-01-21 23:13:02,702 fail2ban.server [31376]: INFO Jail postfix-failedauth is not a JournalFilter instance
2021-01-21 23:13:02,703 fail2ban.filter [31376]: INFO Added logfile: '/var/log/syslog' (pos = 1249877, hash = 7ed247925c7903526faefeef2b703756dea71e4c)
2021-01-21 23:13:02,707 fail2ban.filter [31376]: INFO encoding: UTF-8
2021-01-21 23:13:02,708 fail2ban.filter [31376]: INFO maxRetry: 1
2021-01-21 23:13:02,708 fail2ban.filter [31376]: INFO findtime: 1800
2021-01-21 23:13:02,709 fail2ban.actions [31376]: INFO banTime: -1

[sebres]

invalid literal for int() with base 10: 'None'

This has probably nothing with the filter, see #2849 or #2214 for same issues.