Re: [exim] Callout cache duplicates + case invertions
Hi, Jeremy.
Let us return to the discussion
https://lists.exim.org/lurker/thread/20190816.084603.570e7217.en.html
I've got close to the point where case inversions occure. This is exactly
execution of "verify = callout" acl condition. The case of $sender_address
is changed before actual callout is done (before SMTP session), then
modified $sender_address remains until end of mail processing.
I add some debugging code to acl_mail and acl_rcpt:
--- acl_mail --
# DEBUG <
warn
set acl_m_snd_addr0=$sender_address
logwrite= $acl_c1: TRACE/acl_mail:0 sender_address = <$acl_m_snd_addr0>
control =
debug/tag=.$acl_c1/opts=-all+verify+expand+dns+lookup+transport+memory
!verify = sender/callout=300s/defer_ok
logwrite= $acl_c1: TRACE/acl_mail:0 address verification for \
<$sender_address> failed
set acl_m2 = $acl_m2 SV=fail
warn
set acl_m_snd_addr1=$sender_address
set acl_m_snd_caldb1=${run{/bin/sh -c "/usr/sbin/exim_dumpdb
/var/spool/exim4 callout | fgrep -i $sender_address"}{$value}{LOOKUP FAILED:
$value}}
set acl_m_mx = ${lookup dnsdb{defer_never,mx=${domain:$sender_address}}\
{$value}{FAILED}}
logwrite= $acl_c1: TRACE/acl_mail:1 sender_address = <$acl_m_snd_addr1>
logwrite= $acl_c1: TRACE/acl_mail:1 callout_db: $acl_m_snd_caldb1
logwrite= $acl_c1: TRACE/acl_mail:1 mx records: $acl_m_mx
warn
condition = ${if !eq{${domain:$acl_m_snd_addr0}}\
{${domain:$acl_m_snd_addr1}}}
logwrite= $acl_c1: TRACE/acl_mail:2 TRAP ${domain:$sender_address}
logwrite= mv: ${run{/bin/mv /var/log/exim4/debuglog.$acl_c1
/var/log/exim4/$acl_c1.debug_mail}{success $acl_c1.debug_mail}{failure: $value}}
warn
logwrite= $acl_c1: [acl_mail] turn off debug logging
control = debug/kill
# DEBUG >
--- acl_rcpt --
# DEBUG <
warn
set acl_m_snd_addr2=$sender_address
set acl_m_snd_caldb2=${run{/bin/sh -c "/usr/sbin/exim_dumpdb
/var/spool/exim4 callout | fgrep -i $sender_address"}{$value}{LOOKUP FAILED:
$value}}
logwrite= $acl_c1: TRACE/acl_rcpt:0 sender_address = <$acl_m_snd_addr2>
logwrite= $acl_c1: TRACE/acl_rcpt:0 callout_db: $acl_m_snd_caldb2
deny
!hosts = : +relay_from_hosts
!domains= +pass_domains
!acl= acl_check_mail_exceptions
control =
debug/tag=.$acl_c1/opts=-all+verify+expand+dns+lookup+transport+memory
!verify = sender/callout=300s
warn
set acl_m_snd_addr3=$sender_address
logwrite= $acl_c1: TRACE/acl_rcpt:1 sender_address = <$acl_m_snd_addr3>
condition = ${if or{\
{ !eq{${domain:$acl_m_snd_addr2}}\
{${domain:$acl_m_snd_addr3}} }\
{ !eq{${domain:$acl_m_snd_addr0}}\
{${domain:$acl_m_snd_addr3}} }\
}\
}
logwrite= $acl_c1: TRACE/acl_rcpt:2 TRAP ${domain:$sender_address}
logwrite= mv: ${run{/bin/mv /var/log/exim4/debuglog.$acl_c1
/var/log/exim4/$acl_c1.debug_rcpt}{success $acl_c1.debug_rcpt}{failure: $value}}
warn
logwrite= $acl_c1: [acl_rcpt] turn off debug logging
control = debug/kill
# DEBUG >
---
The acl_c1 is my custom connection identifier, used to simplify tracing.
Tipical output of "fgrep $acl_c1 mainlog" is:
2019-08-26 15:54:52.613 [31427] 1D0-0B4-D0C: TRACE/acl_mail:0 sender_address =
2019-08-26 15:54:52.779 [31427] 1D0-0B4-D0C: TRACE/acl_mail:1 sender_address =
2019-08-26 15:54:52.779 [31427] 1D0-0B4-D0C: TRACE/acl_mail:1 callout_db:
26-Aug-2019 15:54:51 infovest...@31russ-pr.ru callout=accept\n26-Aug-2019
15:54:52 infovest...@31russ-pr.ru callout=accept\n
2019-08-26 15:54:52.779 [31427] 1D0-0B4-D0C: TRACE/acl_mail:1 mx records: 10
mx.31russ-pr.ru
2019-08-26 15:54:52.779 [31427] 1D0-0B4-D0C: TRACE/acl_mail:2 TRAP 31RUSS-PR.ru
2019-08-26 15:54:52.782 [31427] mv: success 1D0-0B4-D0C.debug_mail
2019-08-26 15:54:52.782 [31427] 1D0-0B4-D0C: [acl_mail] turn off debug logging
2019-08-26 15:54:52.921 [31427] 1D0-0B4-D0C: TRACE/acl_rcpt:0 sender_address =
2019-08-26 15:54:52.921 [31427] 1D0-0B4-D0C: TRACE/acl_rcpt:0 callout_db:
26-Aug-2019 15:54:51 infovest...@31russ-pr.ru callout=accept\n26-Aug-2019
15:54:52 infovest...@31russ-pr.ru callout=accept\n
2019-08-26 15:54:52.926 [31427] 1D0-0B4-D0C: TRACE/acl_rcpt:1 sender_address =
2019-08-26 15:54:52.927 [31427] 1D0-0B4-D0C: TRACE/acl_rcpt:2 TRAP 31RUSS-PR.ru
2019-08-26 15:54:52.929 [31427] mv: success 1D0-0B4-D0C.debug_rcpt
2019-08-26 15:54:52.929 [31427] 1D0-0B4-D0C: [acl_rcpt] turn off debug logging
Curious fact: there was another connection from this site (31russ-pr.ru)
at the
Re: [exim] Callout cache duplicates + case invertions
On Fri, Aug 16, 2019 at 09:29:19AM +0100, Jeremy Harris via Exim-users wrote: > Might there be an IDN-related component to the issue? Do you run with > smtputf8_advertise_hosts ? No, this parameter is unset. Only 8BITMIME is advertized on SMTP. > My only other thought would be to try to catch one of these in the act > of creation, and get a full debug run. That won't be simple. Well, I'll try to gather more info. -- Eugene Berdnikov -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] Callout cache duplicates + case invertions
On 16/08/2019 09:17, Evgeniy Berdnikov via Exim-users wrote: > On Thu, Aug 15, 2019 at 10:37:47PM +0100, Jeremy Harris via Exim-users wrote: >> On 15/08/2019 21:59, Evgeniy Berdnikov via Exim-users wrote: >>> However, there are duplicates in cache, for different domains. >>> Examples: >>> >>> # exim_dumpdb /var/spool/exim4 callout | fgrep -i nore...@cnews.ru >>> 25-Jul-2019 15:06:55 nore...@cnews.ru callout=accept >>> 25-Jul-2019 15:06:56 nore...@cnews.ru callout=accept >> >>> Have anybody idea why could it happen? >> >> You also verify header_sender ? > > No, only env_from. > > Duplicates are also seen for mails rejected on the RCPT stage: > > 18-Jul-2019 12:05:21 i...@03-mrx.ru callout=reject > 18-Jul-2019 12:05:22 i...@03-mrx.ru callout=reject > > 24-Jul-2019 10:41:12 i...@avtosnabservice.ru callout=reject > 24-Jul-2019 10:41:12 i...@avtosnabservice.ru callout=reject > > It's interesting that case change happens for 2nd level subdomain part. Indeed. I'm still baffled by the duplication. Might there be an IDN-related component to the issue? Do you run with smtputf8_advertise_hosts ? My only other thought would be to try to catch one of these in the act of creation, and get a full debug run. That won't be simple. -- Cheers, Jeremy -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] Callout cache duplicates + case invertions
On Thu, Aug 15, 2019 at 10:37:47PM +0100, Jeremy Harris via Exim-users wrote: > On 15/08/2019 21:59, Evgeniy Berdnikov via Exim-users wrote: > > However, there are duplicates in cache, for different domains. > > Examples: > > > > # exim_dumpdb /var/spool/exim4 callout | fgrep -i nore...@cnews.ru > > 25-Jul-2019 15:06:55 nore...@cnews.ru callout=accept > > 25-Jul-2019 15:06:56 nore...@cnews.ru callout=accept > > > Have anybody idea why could it happen? > > You also verify header_sender ? No, only env_from. Duplicates are also seen for mails rejected on the RCPT stage: 18-Jul-2019 12:05:21 i...@03-mrx.ru callout=reject 18-Jul-2019 12:05:22 i...@03-mrx.ru callout=reject 24-Jul-2019 10:41:12 i...@avtosnabservice.ru callout=reject 24-Jul-2019 10:41:12 i...@avtosnabservice.ru callout=reject It's interesting that case change happens for 2nd level subdomain part. -- Eugene Berdnikov -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] Callout cache duplicates + case invertions
On 15/08/2019 21:59, Evgeniy Berdnikov via Exim-users wrote: > However, there are duplicates in cache, for different domains. > Examples: > > # exim_dumpdb /var/spool/exim4 callout | fgrep -i nore...@cnews.ru > 25-Jul-2019 15:06:55 nore...@cnews.ru callout=accept > 25-Jul-2019 15:06:56 nore...@cnews.ru callout=accept > Have anybody idea why could it happen? You also verify header_sender ? -- Cheers, Jeremy -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
[exim] Callout cache duplicates + case invertions
Hi guys. I have several mail relays with Exim-4.92 on Debian, running with "verify = sender/callout=300s". Today one incoming mail passed this sender verify procedure on 1st relay (highest priority MX), then hit greylisting (got 451) and came to the 2nd relay, where it was rejected with Aug 15 16:04:25 citrine exim[25920]: 2019-08-15 16:04:25.148 [25920] H=relay.seldon.ru [185.179.199.32]:49727 I=[192.168.10.13]:25 sender verify fail for : relay.seldon.ru [185.179.199.32] : SMTP error from remote mail server after RCPT TO:: 550 5.1.1 Backscatter Protection detected an invalid or expired email address (real user address is mangled). Investigation shows that sender's MX host does not pass sender verify if address contain uppercase letters: 220 relay.seldon.ru ESMTP MDaemon 18.0.2; Thu, 15 Aug 2019 18:05:39 +0300 [...] mail from: <> 250 2.1.0 Sender OK rcpt to: 250 2.1.5 Recipient OK rcpt to: 550 5.1.1 Backscatter Protection detected an invalid or expired email address Well, this is obvious violation of the case insensitivity principle for domain part. But MDaemon bugs are not targets for this discussion. I was surprised that sender's MTA came to my 1st relay with lowercase domain in env_from address (seldon.ru), which passed sender verify, and since several seconds came to came to 2nd relay with uppercase letters in domain part. Logs have different register for env_from domain of the same mail. Maybe this is some other MDaemon bug resulting in case change during relay's traversal, but this scenario does not explain all facts below. First, I see something strange with callout cache on the 2nd relay: # exim_dumpdb /var/spool/exim4 callout | fgrep -i seldon 15-Aug-2019 16:04:24 prvs=113054f968=usern...@seldon.ru callout=accept 15-Aug-2019 16:04:25 prvs=113054f968=usern...@seldon.ru callout=reject Only one mail was logged around 16:04:25 from this address, and it was rejected. Why callout cache have TWO different entries with very close timestamps but different cases for domain part and different results? I made some experiments, feeding some env_from addresses to my relays and watching network traffic. Results are: 1. Callout entries for mail addresses have the same case as in MAIL FROM. 2. Callout entries for host names are always in low case. 3. Single env_from results in a single SMTP callout. I failed to reproduce duplication of callout records and case inversions. However, there are duplicates in cache, for different domains. Examples: # exim_dumpdb /var/spool/exim4 callout | fgrep -i nore...@cnews.ru 25-Jul-2019 15:06:55 nore...@cnews.ru callout=accept 25-Jul-2019 15:06:56 nore...@cnews.ru callout=accept # exim_dumpdb /var/spool/exim4 callout | fgrep -i c...@cnews.ru 25-Jul-2019 11:15:52 c...@cnews.ru callout=accept 25-Jul-2019 11:15:52 c...@cnews.ru callout=accept # exim_dumpdb /var/spool/exim4 callout | fgrep -i osp.ru 18-Jul-2019 17:39:36 bounce-264727...@bounce.email.osp.ru callout=accept 18-Jul-2019 17:39:35 bounce-264727...@bounce.email.osp.ru callout=accept 18-Jul-2019 17:39:36 bounce.email.osp.ru callout=accept postmaster=unknown random=unknown Logs for these 3 mails contain addresses with lowcase domain parts. Case inversions+duplicates are not rare, they count to ~ 25% mails on my hosts: # exim_dumpdb /var/spool/exim4 callout | fgrep -v random= | egrep '[A-Z]\.' | wc -l 1340 # exim_dumpdb /var/spool/exim4 callout | fgrep -v random= | egrep -v '[A-Z]\.' | wc -l 5951 Have anybody idea why could it happen? Is it a bug? -- Eugene Berdnikov -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
