Topic: Slow blocking of IP addresses by fail2ban

[holck]

Yesterday I encountered this attack (/var/log/qpsmtpd):

Code: [Select]

2017-10-12 13:41:24.441863500 19067 (deny) logging::logterse: ` 151.182.89.1    151-182-89-1.red-acceso.airtel.net                              earlytalker     901     Connecting host started transmitting before SMTP greeting       msg denied before queued
This repeats itself >200 times, until a minute later, where qpsmtpd now denies the messages because of high load:

Code: [Select]

2017-10-12 13:42:51.143934500 20110 (deny) logging::logterse: ` 151.182.89.1    151-182-89-1.red-acceso.airtel.net                              earlytalker     901     Connecting host started transmitting before SMTP greeting       msg denied before queued2017-10-12 13:42:51.164670500 20136 (connect) loadcheck: local load too high: 32.60
2017-10-12 13:42:51.166148500 20136 (deny) logging::logterse: ` 151.182.89.1    151-182-89-1.red-acceso.airtel.net                              loadcheck       902     Server load too high, please try again later.   msg denied before queued
Which is repeated around 50 times for the next few seconds:

Code: [Select]

2017-10-12 13:42:55.249495500 20191 (connect) loadcheck: local load too high: 32.60
2017-10-12 13:42:55.250962500 20191 (deny) logging::logterse: ` 151.182.89.1    151-182-89-1.red-acceso.airtel.net                              loadcheck       902     Server load too high, please try again later.   msg denied before queued
And thankfully, at this time, the attack is finally stopped.

Fail2ban reacts quickly (/var/log/fail2ban/daemon.log):

Code: [Select]

2017-10-12 13:41:25,895 fail2ban.actions        [2859]: NOTICE  [qpsmtpd] Ban 151.182.89.1
2017-10-12 13:42:00,061 fail2ban.actions        [2859]: NOTICE  [qpsmtpd] 151.182.89.1 already banned
2017-10-12 13:42:01,063 fail2ban.actions        [2859]: NOTICE  [qpsmtpd] 151.182.89.1 already banned
And the ban should start a few seconds later (/var/log/messages):

Code: [Select]

Oct 12 13:41:33 karoline /sbin/e-smith/smeserver-fail2ban[19144]: /home/e-smith/db/fail2ban: OLD 0wgm1nkrpi57dhl=(undefined)
Oct 12 13:41:33 karoline /sbin/e-smith/smeserver-fail2ban[19144]: /home/e-smith/db/fail2ban: NEW 0wgm1nkrpi57dhl=ban|BanTimestamp|1507808493|Host|151.182.89.1|Port|25,465|Protocol|tcp|UnbanTimestamp|1507810293
Oct 12 13:41:36 karoline esmith::event[19212]: Processing event: fail2ban-update
Oct 12 13:41:36 karoline esmith::event[19212]: Running event handler: /etc/e-smith/events/actions/generic_template_expand
Oct 12 13:41:38 karoline esmith::event[19212]: expanding /etc/rc.d/init.d/masq
Oct 12 13:41:44 karoline esmith::event[19212]: generic_template_expand=action|Event|fail2ban-update|Action|generic_template_expand|Start|1507808496 12327|End|1507808504 153104|Elapsed|8.140777
Oct 12 13:41:44 karoline esmith::event[19212]: Running event handler: /etc/e-smith/events/actions/adjust-services
Oct 12 13:41:46 karoline esmith::event[19212]: adjusting non-supervised masq (adjust)
Oct 12 13:41:59 karoline esmith::event[19212]: adjust-services=action|Event|fail2ban-update|Action|adjust-services|Start|1507808504 153492|End|1507808519 991769|Elapsed|15.838277
But as can be seen from qpsmtpd's logs, the IP address in question keeps getting access for a minute more. Why?

Jesper H,
Denmark

[mmccarn]

My guess would be that the delay is due to the 'loadcheck' / 's
erver load too high' errors:

2017-10-12 13:42:55.249495500 20191 (connect) loadcheck: local load too high: 32.60

Perhaps the qpsmtpd connections were initiated before iptables was updated, and took 60 seconds to clear out due to server load issues.

Were there any connections from this IP that did not fail with check_earlytalker or loadcheck errors?  If so, I would look at adjusting the rules for that earlier failure.

On my server delayed blocks like this were being caused by the configuration of of the 'helo' plugin, which I adjusted as described here:
https://forums.contribs.org/index.php?topic=53223.0