Ok, I'm stuck. I've jumped through the hoops. I've waved the rubber chicken.
Symptom: With certain sites, and certain messages hang at end of data.
I've seen this problem mentioned in the Archives, and have tried
every fix I've found there.
Status in msglog/
2003-05-01 15:44:51 SMTP timeout while connected to mail.roadrunner.nf.net [192.75.13.132] after end of data (6535 bytes written): Operation timed out
2003-05-01 15:44:51 fannyt@??? R=dnslookup T=remote_smtp defer (60): Operation timed out: SMTP timeout while connected to mail.roadrunner.nf.net [192.75.13.132] after end of data (6535 bytes written)
Situation:
Mail server is named postie. He's running exim-4.14, compiled with
DELIVER_OUT_BUFFER_SIZE=512
Firewall is win2k running sygate office network for NAT translation.
The firewall is set to use an MTU of 1400.
Link is bidirectional: Uplink is 28,800 modem connection to Telus.net
Downlink is DirecPC satellite link. (Which is why the firewall runs windows.
Sigh.)
The same problem occurs with even greater frequency (more sites)
with Midpoint firewall.
What do I try next?
I'm including tcpdump -vvv and exim -d logs.
Exim output
Exim version 4.14 uid=0 gid=0 pid=3861 D=fbb95cfd
Probably Berkeley DB version 1.8x (native mode)
Support for:
Authenticators:
Routers: accept dnslookup ipliteral manualroute queryprogram redirect
Transports: appendfile autoreply pipe smtp
changed uid/gid: forcing real = effective
uid=0 gid=0 pid=3861
auxiliary group list: 0
configuration file is /opt/exim/configure
log selector = 030d89d8
trusted user
admin user
skipping ACL configuration - not needed
set_process_info: 3861 delivering specified messages
set_process_info: 3861 delivering 19AEwO-000KO5-00
reading spool file 19AEwO-000KO5-00-H
user=exim uid=25 gid=25 sender=pbelton@???
sender_fullhost = (REGISTRAR) [192.168.1.208]
sender_rcvhost = [192.168.1.208] (helo=REGISTRAR)
sender_local=0 ident=unset
Non-recipients:
Empty Tree
---- End of tree ----
recipients_count=1
body_linecount=186 message_linecount=13
Writing spool header file
Size of headers = 528
Delivery address list:
fannyt@???
locking /var/spool/exim/db/retry.lockfile
locked /var/spool/exim/db/retry.lockfile
opened hints database /var/spool/exim/db/retry: flags=0
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
Considering: fannyt@???
unique = fannyt@???
dbfn_read: key=R:roadrunner.nf.net
dbfn_read: key=R:fannyt@???
no domain retry record
no address retry record
fannyt@???: queued for routing
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
routing fannyt@???
--------> dnslookup router <--------
local_part=fannyt domain=roadrunner.nf.net
checking domains
roadrunner.nf.net in "@ : localhost : localhost.sjsa.internal.net *.sjsa.ab.ca:sjsa.ab.ca : *.sjsa.internal.net : sjsa.internal.net :129.168.1.0/24"? no (end of list)
roadrunner.nf.net in "! +local_domains"? yes (end of list)
cached lookup data = NULL
calling dnslookup router
dnslookup router called for fannyt@???
domain = roadrunner.nf.net
DNS lookup of roadrunner.nf.net (MX) succeeded
DNS lookup of mail.roadrunner.nf.net (A) succeeded
192.75.13.132 in "0.0.0.0 : 127.0.0.0/8"? no (end of list)
fully qualified name = roadrunner.nf.net
host_find_bydns yield = HOST_FOUND (2); returned hosts:
mail.roadrunner.nf.net 192.75.13.132 0
set transport remote_smtp
queued for remote_smtp transport: local_part = fannyt
domain = roadrunner.nf.net
errors_to=NULL
domain_data=NULL localpart_data=NULL
routed by dnslookup router
envelope to: fannyt@???
transport: remote_smtp
host mail.roadrunner.nf.net [192.75.13.132] MX=0
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
After routing:
Local deliveries:
Remote deliveries:
fannyt@???
Failed addresses:
Deferred addresses:
search_tidyup called
>>>>>>>>>>>>>>>> Remote deliveries >>>>>>>>>>>>>>>>
--------> fannyt@??? <--------
search_tidyup called
set_process_info: 3861 delivering 19AEwO-000KO5-00: waiting for a remote delivery subprocess to finish
selecting on subprocess pipes
changed uid/gid: remote delivery to fannyt@??? with transport=remote_smtp
uid=25 gid=25 pid=3862
auxiliary group list: 25
set_process_info: 3862 delivering 19AEwO-000KO5-00 using remote_smtp
remote_smtp transport entered
fannyt@???
checking status of mail.roadrunner.nf.net
locking /var/spool/exim/db/retry.lockfile
locked /var/spool/exim/db/retry.lockfile
opened hints database /var/spool/exim/db/retry: flags=0
dbfn_read: key=T:mail.roadrunner.nf.net:192.75.13.132
dbfn_read: key=T:mail.roadrunner.nf.net:192.75.13.132:19AEwO-000KO5-00
no host retry record
mail.roadrunner.nf.net [192.75.13.132] status = usable
192.75.13.132 in serialize_hosts? no (option unset)
delivering 19AEwO-000KO5-00 to mail.roadrunner.nf.net [192.75.13.132] (fannyt@???)
set_process_info: 3862 delivering 19AEwO-000KO5-00 to mail.roadrunner.nf.net [192.75.13.132] (fannyt@???)
Connecting to mail.roadrunner.nf.net [192.75.13.132]:25 ... connected
read response data: size=102
SMTP<< 220 smtp-stjh-01-04.rogers.nf.net ESMTP Sendmail 8.12.9/8.12.8; Thu, 1 May 2003 19:05:48 -0230 (NDT)
SMTP>> EHLO postie.sjsa.ab.ca
read response data: size=198
SMTP<< 250-smtp-stjh-01-04.rogers.nf.net Hello [216.208.101.220], pleased to meet you
250-ENHANCEDSTATUSCODES
250-PIPELINING
250-8BITMIME
250-SIZE 10485760
250-DSN
250-ETRN
250-DELIVERBY
250 HELP
192.75.13.132 in hosts_require_auth? no (option unset)
SMTP>> MAIL FROM:<pbelton@???> SIZE=7555
SMTP>> RCPT TO:<fannyt@???>
SMTP>> DATA
read response data: size=149
SMTP<< 250 2.1.0 <pbelton@???>... Sender ok
SMTP<< 250 2.1.5 <fannyt@???>... Recipient ok
SMTP<< 354 Enter mail, end with "." on a line by itself
SMTP>> writing message and terminating "."
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=509 timeout=300
writing data block fd=7 size=427 timeout=300
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=0
set_process_info: 3862 delivering 19AEwO-000KO5-00: just tried mail.roadrunner.nf.net [192.75.13.132] for fannyt@???: result OK
added retry item for T:mail.roadrunner.nf.net:192.75.13.132:19AEwO-000KO5-00: errno=60 77 flags=6
all IP addresses skipped or deferred at least one address
locking /var/spool/exim/db/wait-remote_smtp.lockfile
locked /var/spool/exim/db/wait-remote_smtp.lockfile
opened hints database /var/spool/exim/db/wait-remote_smtp: flags=2
Leaving remote_smtp transport
set_process_info: 3862 delivering 19AEwO-000KO5-00 (just run remote_smtp for fannyt@??? in subprocess)
search_tidyup called
reading pipe for subprocess 3862 (not ended)
read() yielded 5
selecting on subprocess pipes
reading pipe for subprocess 3862 (not ended)
read() yielded 176
reading retry information for T:mail.roadrunner.nf.net:192.75.13.132:19AEwO-000KO5-00 from subprocess
added retry item
selecting on subprocess pipes
reading pipe for subprocess 3862 (not ended)
read() yielded 125
selecting on subprocess pipes
reading pipe for subprocess 3862 (not ended)
read() yielded 2
Z0 item read
remote delivery process 3862 ended
set_process_info: 3861 delivering 19AEwO-000KO5-00
post-process fannyt@??? (1)
LOG: MAIN
== fannyt@??? R=dnslookup T=remote_smtp defer (60): Operation timed out: SMTP timeout while connected to mail.roadrunner.nf.net [192.75.13.132] after end of data (6535 bytes written)
>>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
changed uid/gid: post-delivery tidying
uid=25 gid=25 pid=3861
auxiliary group list: 25
set_process_info: 3861 tidying up after delivering 19AEwO-000KO5-00
Processing retry items
Succeeded addresses:
Failed addresses:
Deferred addresses:
fannyt@???
locking /var/spool/exim/db/retry.lockfile
locked /var/spool/exim/db/retry.lockfile
opened hints database /var/spool/exim/db/retry: flags=2
address match: subject=*@mail.roadrunner.nf.net pattern=*
mail.roadrunner.nf.net in "*"? yes (matched "*")
*@mail.roadrunner.nf.net in "*"? yes (matched "*")
retry for T:mail.roadrunner.nf.net:192.75.13.132:19AEwO-000KO5-00 (roadrunner.nf.net) = *
dbfn_read: key=T:mail.roadrunner.nf.net:192.75.13.132:19AEwO-000KO5-00
Writing retry data for T:mail.roadrunner.nf.net:192.75.13.132:19AEwO-000KO5-00
first failed=1051561119 last try=1051825491 next try=1051847091 expired=0
error 60 77: Operation timed out
dbfn_write: key=T:mail.roadrunner.nf.net:192.75.13.132:19AEwO-000KO5-00
end of retry processing
time on queue = 3d1h35m19s
warning counts: required 3 done 3
delivery deferred: update_spool=0 header_rewritten=0
end delivery of 19AEwO-000KO5-00
search_tidyup called
search_tidyup called
>>>>>>>>>>>>>>>> Exim pid=3861 terminating with rc=0 >>>>>>>>>>>>>>>>
TCPDUMP for this same transaction:
tcpdump: listening on xl0
15:35:47.851758 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: S [bad tcp cksum 8b1e!] 73069535:73069535(0) win 65535 <mss 1460,nop,wscale 1,nop,nop,timestamp 389281490 0> (DF) (ttl 64, id 42306, len 60, bad cksum 0!)
15:35:48.535852 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: S [tcp sum ok] 478952694:478952694(0) ack 73069536 win 25612 <nop,nop,timestamp 2787663206 389281490,nop,wscale 0,mss 1460> (DF) (ttl 53, id 42493, len 60)
15:35:48.535916 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . [bad tcp cksum d96a!] 1:1(0) ack 1 win 33304 <nop,nop,timestamp 389281558 2787663206> (DF) (ttl 64, id 42307, len 52, bad cksum 0!)
15:35:49.286260 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: P 1:103(102) ack 1 win 25612 <nop,nop,timestamp 2787663279 389281558> (DF) (ttl 53, id 42494, len 154)
15:35:49.286650 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P [bad tcp cksum cd86!] 1:25(24) ack 103 win 33304 <nop,nop,timestamp 389281633 2787663279> (DF) (ttl 64, id 42310, len 76, bad cksum 0!)
15:35:49.917335 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 103:103(0) ack 25 win 25612 (DF) (ttl 53, id 42495, len 40)
15:35:49.917559 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: P 103:301(198) ack 25 win 25612 (DF) (ttl 53, id 42496, len 238)
15:35:49.918375 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P 25:109(84) ack 301 win 33304 <nop,nop,timestamp 389281696 2787663279> (DF) (ttl 64, id 42311, len 136, bad cksum 0!)
15:35:50.788046 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 301:301(0) ack 109 win 25612 (DF) (ttl 53, id 42497, len 40)
15:35:51.168846 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: P 301:450(149) ack 109 win 25612 (DF) (ttl 53, id 42498, len 189)
15:35:51.169234 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P 109:618(509) ack 450 win 33304 <nop,nop,timestamp 389281821 2787663279> (DF) (ttl 64, id 42312, len 561, bad cksum 0!)
15:35:51.169593 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P 618:1127(509) ack 450 win 33304 <nop,nop,timestamp 389281821 2787663279> (DF) (ttl 64, id 42313, len 561, bad cksum 0!)
15:35:51.169722 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P 1127:1636(509) ack 450 win 33304 <nop,nop,timestamp 389281821 2787663279> (DF) (ttl 64, id 42314, len 561, bad cksum 0!)
15:35:51.169848 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P 1636:2145(509) ack 450 win 33304 <nop,nop,timestamp 389281821 2787663279> (DF) (ttl 64, id 42315, len 561, bad cksum 0!)
15:35:51.169973 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P 2145:2654(509) ack 450 win 33304 <nop,nop,timestamp 389281821 2787663279> (DF) (ttl 64, id 42316, len 561, bad cksum 0!)
15:35:51.170100 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P 2654:3163(509) ack 450 win 33304 <nop,nop,timestamp 389281821 2787663279> (DF) (ttl 64, id 42317, len 561, bad cksum 0!)
15:35:51.170226 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P 3163:3672(509) ack 450 win 33304 <nop,nop,timestamp 389281821 2787663279> (DF) (ttl 64, id 42318, len 561, bad cksum 0!)
15:35:51.170354 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P 3672:4181(509) ack 450 win 33304 <nop,nop,timestamp 389281821 2787663279> (DF) (ttl 64, id 42319, len 561, bad cksum 0!)
15:35:52.040250 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 450:450(0) ack 109 win 25612 (DF) (ttl 53, id 42499, len 40)
15:35:52.170102 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 450:450(0) ack 109 win 25612 (DF) (ttl 53, id 42500, len 40)
15:35:52.290228 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 450:450(0) ack 109 win 25612 (DF) (ttl 53, id 42501, len 40)
15:35:52.290265 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 109:1557(1448) ack 450 win 33304 <nop,nop,timestamp 389281933 2787663279> (DF) (ttl 64, id 42320, len 1500, bad cksum 0!)
15:35:52.410439 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 450:450(0) ack 109 win 25612 (DF) (ttl 53, id 42502, len 40)
15:35:52.410471 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389281945 2787663279> (DF) (ttl 64, id 42321, len 1500, bad cksum 0!)
15:35:52.410487 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: P 5629:6644(1015) ack 450 win 33304 <nop,nop,timestamp 389281945 2787663279> (DF) (ttl 64, id 42322, len 1067, bad cksum 0!)
15:35:52.540708 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 450:450(0) ack 109 win 25612 (DF) (ttl 53, id 42503, len 40)
15:35:52.660447 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 450:450(0) ack 109 win 25612 (DF) (ttl 53, id 42504, len 40)
15:35:52.790743 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 450:450(0) ack 3163 win 25612 (DF) (ttl 53, id 42505, len 40)
15:35:52.790784 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 3163:4611(1448) ack 450 win 33304 <nop,nop,timestamp 389281984 2787663279> (DF) (ttl 64, id 42323, len 1500, bad cksum 0!)
15:35:52.910864 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 450:450(0) ack 4181 win 25612 (DF) (ttl 53, id 42506, len 40)
15:35:53.792308 mail.rogers.nf.net.smtp > postie.sjsa.internal.net.1313: . [tcp sum ok] 450:450(0) ack 4181 win 25612 (DF) (ttl 53, id 42507, len 40)
15:35:54.620577 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389282167 2787663279> (DF) (ttl 64, id 42324, len 1500, bad cksum 0!)
15:35:58.040651 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389282509 2787663279> (DF) (ttl 64, id 42325, len 1500, bad cksum 0!)
15:36:04.880772 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389283193 2787663279> (DF) (ttl 64, id 42354, len 1500, bad cksum 0!)
15:36:18.560992 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389284561 2787663279> (DF) (ttl 64, id 42358, len 1500, bad cksum 0!)
15:36:45.921465 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389287297 2787663279> (DF) (ttl 64, id 42404, len 1500, bad cksum 0!)
15:37:23.682110 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389291073 2787663279> (DF) (ttl 64, id 42429, len 1500, bad cksum 0!)
15:38:27.683196 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389297473 2787663279> (DF) (ttl 64, id 42569, len 1500, bad cksum 0!)
15:39:31.684283 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389303873 2787663279> (DF) (ttl 64, id 42655, len 1500, bad cksum 0!)
15:40:35.685355 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389310273 2787663279> (DF) (ttl 64, id 42774, len 1500, bad cksum 0!)
15:41:39.686461 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389316673 2787663279> (DF) (ttl 64, id 42858, len 1500, bad cksum 0!)
15:42:43.687521 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389323073 2787663279> (DF) (ttl 64, id 42943, len 1500, bad cksum 0!)
15:43:47.688611 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: . 4181:5629(1448) ack 450 win 33304 <nop,nop,timestamp 389329473 2787663279> (DF) (ttl 64, id 43109, len 1500, bad cksum 0!)
15:44:51.689671 postie.sjsa.internal.net.1313 > mail.rogers.nf.net.smtp: R [bad tcp cksum 1d9a!] 6644:6644(0) ack 450 win 33304 (DF) (ttl 64, id 43161, len 40, bad cksum 0!)
3179 packets received by filter
0 packets dropped by kernel
--
Sherwood Botsford 1-780-848-2881 Ext 134
St. John's School of Alberta RR - 5 Stony Plain, Alberta TZ7 1X5
Alternate address sgbotsford@yahoo . com
