On 2012-09-28 at 19:02 -0700, list2 wrote:
> Could somebody tell me what is going on based on the cross section of
> log below? Is something stuck in my customer's outbox? It doesn't
> actually send out anything yet the rate quota is engaged. I can't block
> the IP as it is a legit wi-fi for an officefull of Macs that uses this
> email server. This goes on and on and on in my log. How can I stop it?
>
> My rate section in my config looks like this:
>
> warn ratelimit = 100 / 1h / strict
> log_message = Sender rate $sender_rate / $sender_rate_period
You don't say _where_ that is. I'm going to guess that it's at a
connection level, rather than a mail level? The evidence below suggests
that you have it on EHLO, when you probably want to have it on MAIL.
What appears to be happening is that one of your mail clients has a
misconfigured password, so is repeatedly connecting, failing to
authenticate, then connecting again, in a tight loop.
> 2012-09-28 18:39:53 [24593] plain_login authenticator failed for
> ([10.0.1.11]) [75.71.106.148]:36512 I=[216.240.133.65]:587: 535
> Incorrect authentication data
That's the authentication failing.
> 2012-09-28 18:39:53 [24593] SMTP connection from ([10.0.1.11])
> [75.71.106.148]:36512 I=[216.240.133.65]:587 lost
That's the client not shutting down cleanly when authentication fails,
and just closing the connection instead.
> 2012-09-28 18:39:53 [24593] no MAIL in SMTP connection from
> ([10.0.1.11]) [75.71.106.148]:36512 I=[216.240.133.65]:587 D=0s
> C=EHLO,STARTTLS,EHLO,AUTH
That's reporting that the connection completed, no MAIL command was
seen, and so you get a list of the command sequence actually seen. In
this case, the client started TLS (SSL) and then tried to authenticate;
you know from the log line above that it was "AUTH PLAIN".
> 2012-09-28 18:39:54 [24427] SMTP connection from [75.71.106.148]:34435
> I=[216.240.133.65]:587 (TCP/IP connection count = 1)
> 2012-09-28 18:39:54 [24595] H=([10.0.1.11]) [75.71.106.148]:34435
> I=[216.240.133.65]:587 Warning: Sender rate 284.9 / 1h
> 2012-09-28 18:39:55 [24595] H=([10.0.1.11]) [75.71.106.148]:34435
> I=[216.240.133.65]:587 Warning: Sender rate 285.9 / 1h
> 2012-09-28 18:39:55 [24595] plain_login authenticator failed for
> ([10.0.1.11]) [75.71.106.148]:34435 I=[216.240.133.65]:587: 535
> Incorrect authentication data
And that's the same client, on the same IP address, trying again a
second later, taking another second to complete.
Since you're logging the rate limit twice for the connection, and the
client is saying EHLO, STARTTLS, EHLO, AUTH, it seems very likely that
your rate limit rule is on the ACL plumbed into the acl_smtp_helo hook.
I think you want to move it to the ACL plumbed into acl_smtp_mail.
And, too, fix the client that's configured with bad authentication data;
also, consider finding out which software that is and pushing to replace
it with something that doesn't sit in a tight loop, repeatedly trying to
AUTH PLAIN with bad data.
-Phil
