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: jgh146exb@???
Reporter: mb-exim@???
CC: exim-dev@???
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_part@???
16:15:44 16473 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:15:44 16473 Considering a_local_part@???
16:15:44 16473 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:15:44 16473 routing a_local_part@???
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_part@???
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_part@???
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_part@???
16:15:44 16473 callout cache: no address record found for
a_local_part@???
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.
