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: ni...@exim.org
          Reporter: ar...@maven.pl
                CC: exim-dev@exim.org

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=i...@example.pl)
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=i...@example.pl)
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.
-- 
## List details at https://lists.exim.org/mailman/listinfo/exim-dev Exim 
details at http://www.exim.org/ ##

Reply via email to