https://bugs.exim.org/show_bug.cgi?id=2376
Bug ID: 2376
Summary: log_message doesn't log if connection is interrupted
(which is quite unexpected) while other rules in the
same acl are applied
Product: Exim
Version: 4.91
Hardware: x86
OS: All
Status: NEW
Severity: bug
Priority: medium
Component: Logging
Assignee: nigel@???
Reporter: arekm@???
CC: exim-dev@???
log_message behaviour is quite unexpected. It doesn't log any message if acl
doesn't finish because of some reason (like connection was interrupted).
For example:
acl_notquit:
accept authenticated = *
warn condition = ${if match {$smtp_notquit_reason}{command}{yes}{no}}
log_message = "Connection Ratelimit - $sender_fullhost because
of notquit: $smtp_notquit_reason ($sender_rate/$sender_rate_period
max:$sender_rate_limit)"
logwrite = "LOGWRITE: $tod_log $message_id Connection Ratelimit
- $sender_fullhost because of notquit: $smtp_notquit_reason
($sender_rate/$sender_rate_period max:$sender_rate_limit)"
ratelimit = BADNOAUTH_LIMIT / strict / per_conn
accept
so we want to do ratelimit counting and log message about that (in case if
ratelimit will block something in other rules and we will need to find in logs
why that happened)
Now we have a bad client:
2019-02-15 16:09:27.239 [25025] SMTP connection from [49.86.182.22]:53018
I=[1.1.1.82]:25 (TCP/IP connection count = 31)
2019-02-15 16:09:31.280 [26272] login authenticator failed for (mztyg.com)
[49.86.182.22]:53018 I=[1.1.1.82]:25: 535 Incorrect authentication data
(set_id=info@???)
2019-02-15 16:09:31.830 [26272] "LOGWRITE: 2019-02-15 16:09:31.830 Connection
Ratelimit - (mztyg.com) [49.86.182.22]:53018 because of failed SMTP AUTH
without QUIT: connection-lost (/ max:)"
2019-02-15 16:09:31.831 [26272] SMTP connection from (mztyg.com)
[49.86.182.22]:53018 I=[1.1.1.82]:25 lost D=4.590s
2019-02-15 16:09:31.832 [26272] no MAIL in SMTP connection from (mztyg.com)
[49.86.182.22]:53018 I=[1.1.1.82]:25 D=4.591s C=EHLO,AUTH
2019-02-15 16:09:35.207 [25025] SMTP connection from [49.86.182.22]:53541
I=[1.1.1.82]:25 (TCP/IP connection count = 34)
2019-02-15 16:09:44.204 [26467] login authenticator failed for (mztyg.com)
[49.86.182.22]:53541 I=[1.1.1.82]:25: 535 Incorrect authentication data
(set_id=info@???)
2019-02-15 16:09:49.000 [26467] "LOGWRITE: 2019-02-15 16:09:49.000 Connection
Ratelimit - (mztyg.com) [49.86.182.22]:53541 because of failed SMTP AUTH
without QUIT: connection-lost (/ max:)"
log_message was not logged.
That's very unexpected and from my looking into documentation also not
documented (at least not explicitly). Very unexpected because other rule -
ratelimit - in the same warn statement was executed and applied. Same for
logwrite.
Possible improvements:
1) make log_message reliable and do more what admin would expect
2) clearly document behaviour and suggest to use logwrite instead
--
You are receiving this mail because:
You are on the CC list for the bug.
