Question : SMTP Timeout From MX Gateway But Only For Some Domains

Hi,

I currently have a setup where I have an external MX server which forwards all the incoming email (after virus scanning and spam-checking) to a mail server for users to login and download their email. This is working fine for 99% of the emails coming in but there are some odd things happening.

First a background on the servers. The MX gateway is running CentOS 4.5 with Exim 4.67 and the mail server is running Windows Server 2003 with MailEnable Profession 2.37.

I first noticed the problem with GMail, I have an account setup in my Thunderbird which I tried to send a test email to an address I have on the mail server. It never came through. I checked the MX gateway and, sure enough, it was sitting in the queue with the error: "2007-06-22 18:31:26 [email protected] R=send_to_winmail T=remote_smtp defer (110): Connection timed out: SMTP timeout while connected to 208.100.38.163 [208.100.38.163] after end of data (2350 bytes written)" and the mail server had a similar message about the connection timing out after DATA.

The strange thing is, I logged into GMail using their webmail area and tried sending another test message and it went through fine. This would only happen if I used my email client to send the message (I tried it on entourage on a different computer using a different GMail account and had the same problem). This boggled my mind as I have a company email and personal email setup in Thunderbird as well which were sending through just fine.

I have tried everything I can think of to get this working and nothing has helped so I am wondering if any of you have dealt with something like this and know how to fix it. Thank you in advance, I will post the debug output from Exim after a failed message below.

Exim Debug:

Exim version 4.67 uid=0 gid=0 pid=23790 D=fbb95cfd
Berkeley DB: Sleepycat Software: Berkeley DB 4.2.52: (February 22, 2005)
Support for: crypteq iconv() Perl OpenSSL move_frozen_messages Content_Scanning Old_Demime
Lookups: lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmnz
Authenticators: cram_md5 plaintext spa
Routers: accept dnslookup ipliteral manualroute queryprogram redirect
Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
Size of off_t: 8
changed uid/gid: forcing real = effective
  uid=0 gid=0 pid=23790
  auxiliary group list:
seeking password data for user "root": cache not available
getpwnam() succeeded uid=0 gid=0
seeking password data for user "mail": cache not available
getpwnam() succeeded uid=8 gid=12
seeking password data for user "majordomo": cache not available
getpwnam() succeeded uid=102 gid=2
seeking password data for user "apache": cache not available
getpwnam() succeeded uid=48 gid=48
seeking password data for user "diradmin": cache not available
getpwnam() succeeded uid=100 gid=101
configuration file is /etc/exim.conf
log selectors = 000024ac 002b9809
cwd=/root 4 args: exim -d -M 1I1tm4-0005fj-TR
trusted user
admin user
skipping ACL configuration - not needed
seeking password data for user "majordomo": cache not available
getpwnam() succeeded uid=102 gid=2
seeking password data for user "majordomo": using cached result
getpwnam() succeeded uid=102 gid=2
seeking password data for user "mail": cache not available
getpwnam() succeeded uid=8 gid=12
seeking password data for user "mail": using cached result
getpwnam() succeeded uid=8 gid=12
seeking password data for user "majordomo": cache not available
getpwnam() succeeded uid=102 gid=2
seeking password data for user "mail": cache not available
getpwnam() succeeded uid=8 gid=12
seeking password data for user "mail": using cached result
getpwnam() succeeded uid=8 gid=12
set_process_info: 23790 delivering specified messages
set_process_info: 23790 delivering 1I1tm4-0005fj-TR
reading spool file 1I1tm4-0005fj-TR-H
user=mail uid=8 gid=12 sender=*myemail*@gmail.com
sender_fullhost = qb-out-0506.google.com [72.14.204.239]
sender_rcvhost = qb-out-0506.google.com ([72.14.204.239])
sender_local=0 ident=unset
Non-recipients:
Empty Tree
---- End of tree ----
recipients_count=1
body_linecount=1 message_linecount=31
running system filter
rda_interpret (file): /etc/system_filter.exim
expanded: /etc/system_filter.exim
12784 bytes read from /etc/system_filter.exim
data is an Exim filter program
Filter: start of processing
Filter: end of processing
system filter returned 1
Delivery address list:
  [email protected]
locking /var/spool/exim/db/retry.lockfile
locked /var/spool/exim/db/retry.lockfile
EXIM_DBOPEN(/var/spool/exim/db/retry)
returned from EXIM_DBOPEN
opened hints database /var/spool/exim/db/retry: flags=O_RDONLY
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
Considering: [email protected]
unique = [email protected]
dbfn_read: key=R:marshallthornton.com
dbfn_read: key=R:admin@marshallthornton.com
dbfn_read: key=R:admin@marshallthornton.com:<*myemail*@gmail.com>
no domain retry record
no address retry record
[email protected]: queued for routing
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
routing [email protected]
--------> large_messages_linux router <--------
local_part=admin domain=marshallthornton.com
checking domains
search_open: lsearch "/etc/virtual/domains"
search_find: file="/etc/virtual/domains"
  key="marshallthornton.com" partial=-1 affix=NULL starflags=0
LRU list:
  :/etc/virtual/domains
  End
internal_search_find: file="/etc/virtual/domains"
  type=lsearch key="marshallthornton.com"
file lookup required for marshallthornton.com
  in /etc/virtual/domains
lookup yielded:
marshallthornton.com in "lsearch;/etc/virtual/domains"? yes (matched "lsearch;/etc/virtual/domains")
checking "condition"
search_open: lsearch "/etc/virtual/domainlimits"
search_find: file="/etc/virtual/domainlimits"
  key="marshallthornton.com" partial=-1 affix=NULL starflags=2
LRU list:
  :/etc/virtual/domainlimits
  :/etc/virtual/domains
  End
internal_search_find: file="/etc/virtual/domainlimits"
  type=lsearch key="marshallthornton.com"
file lookup required for marshallthornton.com
  in /etc/virtual/domainlimits
lookup failed
trying to match *
internal_search_find: file="/etc/virtual/domainlimits"
  type=lsearch key="*"
file lookup required for *
  in /etc/virtual/domainlimits
lookup yielded: 5M
large_messages_linux router skipped: condition failure
--------> large_messages_windows router <--------
local_part=admin domain=marshallthornton.com
checking domains
search_open: lsearch "/etc/virtual/windowsdomains"
search_find: file="/etc/virtual/windowsdomains"
  key="marshallthornton.com" partial=-1 affix=NULL starflags=0
LRU list:
  :/etc/virtual/windowsdomains
  :/etc/virtual/domainlimits
  :/etc/virtual/domains
  End
internal_search_find: file="/etc/virtual/windowsdomains"
  type=lsearch key="marshallthornton.com"
file lookup required for marshallthornton.com
  in /etc/virtual/windowsdomains
lookup yielded:
marshallthornton.com in "lsearch;/etc/virtual/windowsdomains"? yes (matched "lsearch;/etc/virtual/windowsdomains")
checking "condition"
search_open: lsearch "/etc/virtual/domainlimits"
  cached open
search_find: file="/etc/virtual/domainlimits"
  key="marshallthornton.com" partial=-1 affix=NULL starflags=2
LRU list:
  :/etc/virtual/domainlimits
  :/etc/virtual/windowsdomains
  :/etc/virtual/domains
  End
internal_search_find: file="/etc/virtual/domainlimits"
  type=lsearch key="marshallthornton.com"
cached data used for lookup of marshallthornton.com
  in /etc/virtual/domainlimits
lookup failed
trying to match *
internal_search_find: file="/etc/virtual/domainlimits"
  type=lsearch key="*"
cached data used for lookup of *
  in /etc/virtual/domainlimits
lookup yielded: 5M
large_messages_windows router skipped: condition failure
--------> spamcheck_router router <--------
local_part=admin domain=marshallthornton.com
checking for local user
seeking password data for user "admin": cache not available
getpwnam() returned NULL (user not found)
spamcheck_router router skipped: admin is not a local user
--------> send_to_winmail router <--------
local_part=admin domain=marshallthornton.com
checking domains
search_open: lsearch "/etc/virtual/hostname"
search_find: file="/etc/virtual/hostname"
  key="marshallthornton.com" partial=-1 affix=NULL starflags=0
LRU list:
  :/etc/virtual/hostname
  :/etc/virtual/domainlimits
  :/etc/virtual/windowsdomains
  :/etc/virtual/domains
  End
internal_search_find: file="/etc/virtual/hostname"
  type=lsearch key="marshallthornton.com"
file lookup required for marshallthornton.com
  in /etc/virtual/hostname
lookup failed
marshallthornton.com in "lsearch;/etc/virtual/hostname"? no (end of list)
search_open: lsearch "/etc/virtual/windowsdomains"
  cached open
search_find: file="/etc/virtual/windowsdomains"
  key="marshallthornton.com" partial=-1 affix=NULL starflags=0
LRU list:
  :/etc/virtual/windowsdomains
  :/etc/virtual/hostname
  :/etc/virtual/domainlimits
  :/etc/virtual/domains
  End
internal_search_find: file="/etc/virtual/windowsdomains"
  type=lsearch key="marshallthornton.com"
cached data used for lookup of marshallthornton.com
  in /etc/virtual/windowsdomains
lookup yielded:
marshallthornton.com in "lsearch;/etc/virtual/windowsdomains"? yes (matched "lsearch;/etc/virtual/windowsdomains")
data from lookup saved for cache for +windows_domains:
marshallthornton.com in "! +hostname : +windows_domains"? yes (matched "+windows_domains")
calling send_to_winmail router
send_to_winmail router called for [email protected]
  domain = marshallthornton.com
route_item = * 208.100.38.163
marshallthornton.com in "*"? yes (matched "*")
original list of hosts = "208.100.38.163" options =
expanded list of hosts = "208.100.38.163" options =
set transport remote_smtp
finding IP address for 208.100.38.163
doing DNS lookup
DNS lookup of 208.100.38.163 (A) succeeded
208.100.38.163 in "127.0.0.0/8"? no (end of list)
fully qualified name = 208.100.38.163
208.100.38.163 208.100.38.163 mx=-1 sort=-64
queued for remote_smtp transport: local_part = admin
domain = marshallthornton.com
  errors_to=NULL
  domain_data= localpart_data=NULL
routed by send_to_winmail router
  envelope to: [email protected]
  transport: remote_smtp
  host 208.100.38.163 [208.100.38.163]
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
After routing:
  Local deliveries:
  Remote deliveries:
    [email protected]
  Failed addresses:
  Deferred addresses:
search_tidyup called
>>>>>>>>>>>>>>>> Remote deliveries >>>>>>>>>>>>>>>>
--------> [email protected] <--------
search_tidyup called
changed uid/gid: remote delivery to [email protected] with transport=remote_smtp
  uid=8 gid=12 pid=23791
  auxiliary group list:
set_process_info: 23791 delivering 1I1tm4-0005fj-TR using remote_smtp
remote_smtp transport entered
  [email protected]
checking status of 208.100.38.163
locking /var/spool/exim/db/retry.lockfile
locked /var/spool/exim/db/retry.lockfile
EXIM_DBOPEN(/var/spool/exim/db/retry)
returned from EXIM_DBOPEN
opened hints database /var/spool/exim/db/retry: flags=O_RDONLY
dbfn_read: key=T:208.100.38.163:208.100.38.163
dbfn_read: key=T:208.100.38.163:208.100.38.163:1I1tm4-0005fj-TR
no message retry record
208.100.38.163 [208.100.38.163] status = usable
208.100.38.163 in serialize_hosts? no (option unset)
delivering 1I1tm4-0005fj-TR to 208.100.38.163 [208.100.38.163] ([email protected]m)
set_process_info: 23791 delivering 1I1tm4-0005fj-TR to 208.100.38.163 [208.100.38.163] ([email protected]m)
set_process_info: 23790 delivering 1I1tm4-0005fj-TR: waiting for a remote delivery subprocess to finish
selecting on subprocess pipes
Connecting to 208.100.38.163 [208.100.38.163]:25 ... connected
waiting for data on socket
read response data: size=100
  SMTP<< 220 **********************************************************************************************
208.100.38.163 in hosts_avoid_esmtp? no (option unset)
  SMTP>> EHLO dns1.digitalgear.com
waiting for data on socket
read response data: size=135
  SMTP<< 250-208.100.38.163 [209.168.245.26], this server offers 4 extensions
         250-AUTH LOGIN
         250-SIZE 0
         250-XXXA
         250 AUTH=LOGIN
208.100.4.143 in hosts_require_tls? no (option unset)
208.100.4.143 in hosts_avoid_pipelining? no (option unset)
not using PIPELINING
208.100.4.143 in hosts_require_auth? no (option unset)
208.100.4.143 in hosts_try_auth? no (option unset)
  SMTP>> MAIL FROM:<*myemail*@gmail.com> SIZE=9036
waiting for data on socket
read response data: size=43
  SMTP<< 250 Requested mail action okay, completed
  SMTP>> RCPT TO:.com>
waiting for data on socket
read response data: size=43
  SMTP<< 250 Requested mail action okay, completed
  SMTP>> DATA
waiting for data on socket
read response data: size=46
  SMTP<< 354 Start mail input; end with .
  SMTP>> writing message and terminating "."
added header line(s):
Spam-Catcher: This header was added to track abuse, please include it with any abuse report
Spam-Catcher: Primary Hostname - dns1.digitalgear.com
Spam-Catcher: Original Domain - marshallthornton.com
Spam-Catcher: Originator/Caller UID/GID - [8 12] / [0 0]
Spam-Catcher: Sender Address Domain - gmail.com
---
writing data block fd=6 size=2349 timeout=300
waiting for data on socket
selecting on subprocess pipes
selecting on subprocess pipes
selecting on subprocess pipes
selecting on subprocess pipes
selecting on subprocess pipes
selecting on subprocess pipes
selecting on subprocess pipes
selecting on subprocess pipes
selecting on subprocess pipes
selecting on subprocess pipes
ok=0 send_quit=0 send_rset=1 continue_more=0 yield=0 first_address is NULL
set_process_info: 23791 delivering 1I1tm4-0005fj-TR: just tried 208.100.38.163 [208.100.38.163] for [email protected]: result OK
added retry item for T:208.100.38.163:208.100.38.163: errno=110 more_errno=0,A flags=3
added retry item for T:208.100.38.163:208.100.38.163:1I1tm4-0005fj-TR: errno=110 more_errno=0,A flags=6
all IP addresses skipped or deferred at least one address
Leaving remote_smtp transport
set_process_info: 23791 delivering 1I1tm4-0005fj-TR (just run remote_smtp for [email protected] in subprocess)
search_tidyup called
reading pipe for subprocess 23791 (not ended)
read() yielded 482
reading retry information for T:208.100.38.163:208.100.38.163:1I1tm4-0005fj-TR from subprocess
  added retry item
reading retry information for T:208.100.38.163:208.100.38.163 from subprocess
  added delete item
Z0 item read
remote delivery process 23791 ended
set_process_info: 23790 delivering 1I1tm4-0005fj-TR
post-process [email protected] (1)
LOG: MAIN
  == [email protected] R=send_to_winmail T=remote_smtp defer (110): Connection timed out: SMTP timeout while connected to 208.100.38.163 [208.100.38.163] after end of data (2349 bytes written)
>>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
changed uid/gid: post-delivery tidying
  uid=8 gid=12 pid=23790
  auxiliary group list:
set_process_info: 23790 tidying up after delivering 1I1tm4-0005fj-TR
Processing retry items
Succeeded addresses:
Failed addresses:
Deferred addresses:
[email protected]
locking /var/spool/exim/db/retry.lockfile
locked /var/spool/exim/db/retry.lockfile
EXIM_DBOPEN(/var/spool/exim/db/retry)
returned from EXIM_DBOPEN
opened hints database /var/spool/exim/db/retry: flags=O_RDWR
deleted retry information for T:208.100.38.163:208.100.38.163
address match: subject=*@208.100.38.163 pattern=*
208.100.38.163 in "*"? yes (matched "*")
*@208.100.38.163 in "*"? yes (matched "*")
retry for T:208.100.38.163:208.100.38.163:1I1tm4-0005fj-TR (marshallthornton.com) = * 0 0
dbfn_read: key=T:208.100.38.163:208.100.38.163:1I1tm4-0005fj-TR
failing_interval=0 message_age=23472
Writing retry data for T:208.100.38.163:208.100.38.163:1I1tm4-0005fj-TR
  first failed=1182583681 last try=1182583681 next try=1182584581 expired=0
  errno=110 more_errno=0,A Connection timed out
dbfn_write: key=T:208.100.38.163:208.100.38.163:1I1tm4-0005fj-TR
end of retry processing
time on queue = 6h41m13s
warning counts: required 0 done 0
delivery deferred: update_spool=0 header_rewritten=0
end delivery of 1I1tm4-0005fj-TR
search_tidyup called
search_tidyup called
>>>>>>>>>>>>>>>> Exim pid=23790 terminating with rc=0 >>>>>>>>>>>>>>>>

Answer : SMTP Timeout From MX Gateway But Only For Some Domains

Hi Marshal,

Had a look at both version and compared them for anything strange looking. I'm afraid I'm stuck. I can't find anything obvoiusly amiss between the two.

Hopefully someone might be able to find something I've missed.

Try doing a search along the lines of:

exim "selecting on subprocess pipes"

Might unearth some clues as I think that's the critical phrase in the logs.