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 = <infovestnik@???>
2019-08-26 15:54:52.779 [31427] 1D0-0B4-D0C: TRACE/acl_mail:1 sender_address = <infovestnik@???>
2019-08-26 15:54:52.779 [31427] 1D0-0B4-D0C: TRACE/acl_mail:1 callout_db: 26-Aug-2019 15:54:51 infovestnik@??? callout=accept\n26-Aug-2019 15:54:52 infovestnik@??? 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 = <infovestnik@???>
2019-08-26 15:54:52.921 [31427] 1D0-0B4-D0C: TRACE/acl_rcpt:0 callout_db: 26-Aug-2019 15:54:51 infovestnik@??? callout=accept\n26-Aug-2019 15:54:52 infovestnik@??? callout=accept\n
2019-08-26 15:54:52.926 [31427] 1D0-0B4-D0C: TRACE/acl_rcpt:1 sender_address = <infovestnik@???>
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 same time, for which case was not inverted on the acl_mail,
only on acl_rcpt:
2019-08-26 15:54:51.630 [31210] 570-36F-95D: TRACE/acl_mail:0 sender_address = <infovestnik@???>
2019-08-26 15:54:51.937 [31210] 570-36F-95D: TRACE/acl_mail:1 sender_address = <infovestnik@???>
2019-08-26 15:54:51.937 [31210] 570-36F-95D: TRACE/acl_mail:1 callout_db: 26-Aug-2019 15:54:51 infovestnik@??? callout=accept\n
2019-08-26 15:54:51.937 [31210] 570-36F-95D: TRACE/acl_mail:1 mx records: 10 mx.31russ-pr.ru
2019-08-26 15:54:51.938 [31210] 570-36F-95D: [acl_mail] turn off debug logging
2019-08-26 15:54:52.091 [31210] 570-36F-95D: TRACE/acl_rcpt:0 sender_address = <infovestnik@???>
2019-08-26 15:54:52.091 [31210] 570-36F-95D: TRACE/acl_rcpt:0 callout_db: 26-Aug-2019 15:54:51 infovestnik@??? callout=accept\n
2019-08-26 15:54:52.272 [31210] 570-36F-95D: TRACE/acl_rcpt:1 sender_address = <infovestnik@???>
2019-08-26 15:54:52.273 [31210] 570-36F-95D: TRACE/acl_rcpt:2 TRAP 31RUSS-PR.ru
2019-08-26 15:54:52.286 [31210] mv: success 570-36F-95D.debug_rcpt
2019-08-26 15:54:52.286 [31210] 570-36F-95D: [acl_rcpt] turn off debug logging
I have couple of trace files, they all contain similar lines where
case of $sender_address is changed, like this:
Attempting full verification using callout
---0 Get 0x572a4f48 16 dbfn.c 305
---0 Get 0x572a4f58 24 dbfn.c 318
callout cache: found domain record for 31russ-pr.ru
---0 Get 0x572a4f70 32 dbfn.c 305
---0 Get 0x572a4f90 8 dbfn.c 318
callout cache: found address record for infovestnik@???
callout cache: address record is positive
---0 Get 0x572a4f98 96 string.c 1103
┌considering: $sender_address
---0 Rst 0x572a4f98 ** expand.c 4167 1541240
---0 Get 0x572a4f98 16 expand.c 4169
---0 Get 0x572a4fa8 144 string.c 1103
---0 Rst 0x572a4fcd ** expand.c 7893 1541240
├──expanding: $sender_address
└─────result: infovestnik@???
Then $sender_address is expanded with uppercase letters.
I can send trace files to developers, but do not want to post them here,
because they contain some sensitive information. However, I failed to send
them directly to Jeremy, because got "550-Message rejected by user choice
of dnsbl ru.countries.nerd.dk:\n550 Your IP is in ru, rejected based on
geographical location".
And one more interesting fact: all the observerd case inversions are
related to sender's top-level domain "ru". I suspect it can reflect
some anomalies with dns system, but I can't find anything.
--
Eugene Berdnikov
