https://bugs.exim.org/show_bug.cgi?id=2156

            Bug ID: 2156
           Summary: Exim "freezes" on recipients callouts to specific SMTP
                    servers
           Product: Exim
           Version: 4.89
          Hardware: x86
                OS: Linux
            Status: NEW
          Severity: bug
          Priority: medium
         Component: ACLs
          Assignee: jgh146...@wizmail.org
          Reporter: mb-e...@kittycat.fr
                CC: exim-dev@exim.org

I encounter a weird problem for callouts to specific SMTP servers, those of OVH
hosting provider: mx1.ovh.net, mx2.ovh.net and mxb.ovh.net
At the beginning, I thought it was a corner-case, related to those specific
SMTP servers, which were only requiring a small config tuning on my Exim setup.
However, after many unsuccessful tries, I begin to believe it could be an Exim
bug.

The problem is that recipients callouts, to addresses handled by those SMTP
servers, seem to "freeze" Exim.
The connection performs well, the 220 response is received and correct, and
then... nothing. This is true for the 3 servers.
Summary:
1- Connection to 'mx1.ovh.net'
2- Reception of 220-mx1.ovh.net in14
3- nothing happens until the callout timeout expires
4- SMTP connection close
5- same cycle for the next 2 MX hosts: mx2.ovh.net and mxb.ovh.net

Telnet connections to those hosts work well: EHLO, MAIL FROM, RCPT TO
This seems to work well too for TLS connections via openssl s_client
I tried several ways to fix the problem:
    - TLS: to be really sure I tried with 'hosts_avoid_tls' and
'hosts_verify_avoid_tls' SMTP transport options
    - others Exim SMTP transport options:
        * hosts_avoid_esmtp
        * hosts_avoid_pipelining
    - recompilation with fixes for bugs #2147 and #2151 applied, as they were
related to callout problems

I don't see anything suspect in the debug log.
When I perform a network capture, the observation is confirmed for the 3 SMTP
servers:
    - Exim sends back a TCP ACK after the 220 response
    - Then, when the callout timeout expires, it sends a TCP FIN/ACK
When I dump the callout cache with exim_dumpdb, there is no presence of the
target domain/address.

At this point, I don't understand what could be the problem.
My callout setup, nowadays, works for all others SMTP hosts...
Of course, feel free to ask if you need more info.


Version info
------------

Exim version 4.89 #3 built 04-Aug-2017 17:11:41
Copyright (c) University of Cambridge, 1995 - 2017
(c) The Exim Maintainers and contributors in ACKNOWLEDGMENTS file, 2007 - 2017
Berkeley DB: Berkeley DB 5.3.28: (September  9, 2013)
Support for: crypteq iconv() OpenSSL DKIM DNSSEC Event OCSP PRDR
Experimental_SPF Experimental_DANE Experimental_DMARC
Lookups (built-in): lsearch wildlsearch nwildlsearch iplsearch
Authenticators: dovecot
Routers: accept dnslookup manualroute redirect
Transports: appendfile/maildir smtp
Fixed never_users: 0
Configure owner: 0:0
Size of off_t: 8


Callout config
--------------

verify = recipient/callout=2s,maxwait=10s


Debug log extract
-----------------

16:15:44 16473 check verify = recipient/callout=2s,maxwait=10s
16:15:44 16473 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:15:44 16473 Verifying a_local_p...@lra-raby.fr
16:15:44 16473 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:15:44 16473 Considering a_local_p...@lra-raby.fr
16:15:44 16473 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:15:44 16473 routing a_local_p...@lra-raby.fr
16:15:44 16473 --------> dnslookup router <--------
16:15:44 16473 local_part=a_local_part domain=lra-raby.fr
16:15:44 16473 checking domains
16:15:44 16473 cached no match for +local_domains
16:15:44 16473 cached lookup data = NULL
16:15:44 16473 lra-raby.fr in "! +local_domains"? yes (end of list)
16:15:44 16473 calling dnslookup router
16:15:44 16473 dnslookup router called for a_local_p...@lra-raby.fr
16:15:44 16473   domain = lra-raby.fr
16:15:44 16473 lra-raby.fr in "*"? yes (matched "*")
16:15:44 16473 DNS lookup of lra-raby.fr (MX) succeeded
16:15:44 16473 DNS lookup of mx1.ovh.net (A) succeeded
16:15:44 16473 137.74.125.138 in "0.0.0.0 : 10.0.0.0/8 : 127.0.0.0/8 :
169.254.0.0/16 : 172.16.0.0/12 : 192.168.0.0/16"? no (end of list)
16:15:44 16473 DNS lookup of mx2.ovh.net (A) succeeded
16:15:44 16473 137.74.125.139 in "0.0.0.0 : 10.0.0.0/8 : 127.0.0.0/8 :
169.254.0.0/16 : 172.16.0.0/12 : 192.168.0.0/16"? no (end of list)
16:15:44 16473 DNS lookup of mxb.ovh.net (A) succeeded
16:15:44 16473 178.33.124.188 in "0.0.0.0 : 10.0.0.0/8 : 127.0.0.0/8 :
169.254.0.0/16 : 172.16.0.0/12 : 192.168.0.0/16"? no (end of list)
16:15:44 16473 Actual local interface address is 127.0.0.1 (lo)
16:15:44 16473 Actual local interface address is 78.242.33.121 (eth1)
16:15:44 16473 Actual local interface address is 192.168.1.1 (eth1)
16:15:44 16473 Actual local interface address is 192.168.0.1 (br0)
16:15:44 16473 fully qualified name = lra-raby.fr
16:15:44 16473 host_find_bydns yield = HOST_FOUND (2); returned hosts:
16:15:44 16473   mx1.ovh.net 137.74.125.138 MX=1 
16:15:44 16473   mx2.ovh.net 137.74.125.139 MX=5 
16:15:44 16473   mxb.ovh.net 178.33.124.188 MX=100 
16:15:44 16473 set transport remote_smtp
16:15:44 16473 queued for remote_smtp transport: local_part = a_local_part
16:15:44 16473 domain = lra-raby.fr
16:15:44 16473   errors_to=NULL
16:15:44 16473   domain_data=NULL localpart_data=NULL
16:15:44 16473 routed by dnslookup router
16:15:44 16473   envelope to: a_local_p...@lra-raby.fr
16:15:44 16473   transport: remote_smtp
16:15:44 16473   host mx1.ovh.net [137.74.125.138] MX=1 dnssec=no
16:15:44 16473   host mx2.ovh.net [137.74.125.139] MX=5 dnssec=no
16:15:44 16473   host mxb.ovh.net [178.33.124.188] MX=100 dnssec=no
16:15:44 16473 Attempting full verification using callout
16:15:44 16473 locking /var/spool/exim/db/callout.lockfile
16:15:44 16473 locked  /var/spool/exim/db/callout.lockfile
16:15:44 16473 EXIM_DBOPEN(/var/spool/exim/db/callout)
16:15:44 16473 returned from EXIM_DBOPEN
16:15:44 16473 opened hints database /var/spool/exim/db/callout: flags=O_RDWR
16:15:44 16473 dbfn_read: key=lra-raby.fr
16:15:44 16473 callout cache: no domain record found for lra-raby.fr
16:15:44 16473 dbfn_read: key=a_local_p...@lra-raby.fr
16:15:44 16473 callout cache: no address record found for
a_local_p...@lra-raby.fr
16:15:44 16473 closed hints database and lockfile
16:15:44 16473 137.74.125.138 in hosts_require_dane? no (option unset)
16:15:44 16473 interface=NULL port=25
16:15:44 16473 Connecting to mx1.ovh.net [137.74.125.138]:25 ... connected
 16:15:44 16473 /considering: $primary_hostname
 16:15:44 16473 |__expanding: $primary_hostname
 16:15:44 16473 \_____result: kittycat.fr
16:15:44 16473 read response data: size=21
16:15:44 16473   SMTP<< 220-mx1.ovh.net in7
16:15:46 16473   SMTP(close)>>
16:15:46 16473 SMTP timeout
16:15:46 16473 137.74.125.139 in hosts_require_dane? no (option unset)
16:15:46 16473 interface=NULL port=25
16:15:46 16473 Connecting to mx2.ovh.net [137.74.125.139]:25 ... connected
 16:15:46 16473 /considering: $primary_hostname
 16:15:46 16473 |__expanding: $primary_hostname
 16:15:46 16473 \_____result: kittycat.fr
16:15:46 16473 read response data: size=21
16:15:46 16473   SMTP<< 220-mx2.ovh.net in3
16:15:48 16473   SMTP(close)>>
16:15:48 16473 SMTP timeout
16:15:48 16473 178.33.124.188 in hosts_require_dane? no (option unset)
16:15:48 16473 interface=NULL port=25
16:15:48 16473 Connecting to mxb.ovh.net [178.33.124.188]:25 ... connected
 16:15:48 16473 /considering: $primary_hostname
 16:15:48 16473 |__expanding: $primary_hostname
 16:15:48 16473 \_____result: kittycat.fr
16:15:48 16473 read response data: size=23
16:15:48 16473   SMTP<< 220-mxb.ovh.net in101
16:15:50 16473   SMTP(close)>>
16:15:50 16473 SMTP timeout
16:15:50 16473 ----------- end verify ------------
16:15:50 16473 require: condition test deferred in ACL "acl_check_rcpt"
16:15:50 16473 SMTP>> 451 Could not complete recipient verify callout

-- 
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