Re: [exim] Callout cache duplicates + case invertions

Pàgina inicial
Delete this message
Reply to this message
Autor: Evgeniy Berdnikov
Data:  
A: exim-users
Assumpte: 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 = <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