>>>>> "Rory" == Rory Campbell-Lange <rory@???> writes:
Rory> I'm not sure I'm reading this correctly. Some responses from my
Rory> host appear to happen in a very short period, while others seem
Rory> to take a bit longer.
Rory> Its not clear to me why lfallback2's connection at 12. requires
Rory> 3 different connections from my host (13-15).
You're doing ident lookups (the ".auth" packets). They're blocking
those. That means that your exim is waiting for the ident lookup to
fail (time out) before giving the banner, and in the mean time the
sender has given up.
You could turn ident off - but frankly, when dealing with a sender with
stupidly small timeouts it's better to get the sender fixed. Beat them
over the head with RFC1123 and RFC2821, both of which specify 5 _minute_
timeouts where this sender appears to be using 5 _seconds_.
Rory> 1 13:24:04.193597 lfallback2.lnd.ops.eu.uu.net.46989 >
Rory> myhost.smtp: S 1626069298:1626069298(0) win 24820
Rory> <nop,nop,sackOK,mss 1460> (DF)
Rory> 2 13:24:04.193674 myhost.smtp >
Rory> lfallback2.lnd.ops.eu.uu.net.46989: S 727894628:727894628(0)
Rory> ack 1626069299 win 5840 <mss 1460,nop,nop,sackOK> (DF)
Rory> 3 13:24:04.197835 lfallback2.lnd.ops.eu.uu.net.46989 >
Rory> myhost.smtp: . ack 1 win 24820 (DF)
These three are the connection setup - at this point the SMTP connection
is in ESTABLISHED state on both ends, though no data has been transferred
yet. Call this time T.
Rory> 4 13:24:04.199240 myhost.24208 >
Rory> lfallback2.lnd.ops.eu.uu.net.auth: S 732414249:732414249(0)
Rory> win 5840 <mss 1460,sackOK,timestamp 985295444 0,nop,wscale 0>
Rory> (DF)
Rory> 5 13:24:07.193367 myhost.24208 >
Rory> lfallback2.lnd.ops.eu.uu.net.auth: S 732414249:732414249(0)
Rory> win 5840 <mss 1460,sackOK,timestamp 985295744 0,nop,wscale 0>
Rory> (DF)
Your system makes two attempts, 3 seconds apart, to get an ident
connection.
Rory> 6 13:24:09.209326 lfallback2.lnd.ops.eu.uu.net.46989 >
Rory> myhost.smtp: P 1:7(6) ack 1 win 24820 (DF)
This is time T+5 or so. You haven't sent the banner yet (ident lookup not
yet timed out), but here is the sender sending you 6 bytes of unexpected
data, almost certainly "QUIT\r\n".
Rory> 7 13:24:09.209370 myhost.smtp >
Rory> lfallback2.lnd.ops.eu.uu.net.46989: . ack 7 win 5840 (DF)
Your system acks the 6 data bytes.
Rory> 8 13:24:09.209731 lfallback2.lnd.ops.eu.uu.net.46989 >
Rory> myhost.smtp: F 7:7(0) ack 1 win 24820 (DF)
The sender sends a FIN, which means "This is the end of the data stream
I'm sending to you".
Rory> 9 13:24:09.243504 myhost.smtp >
Rory> lfallback2.lnd.ops.eu.uu.net.46989: . ack 8 win 5840 (DF)
You ack the FIN. At this point exim is still waiting for the ident lookup,
it won't notice the synchronization error or the sender's close of the
connection until it's finished with that.
Rory> 10 13:24:09.560420 lfallback2.lnd.ops.eu.uu.net.47028 >
Rory> myhost.smtp: S 2889702440:2889702440(0) win 24820
Rory> <nop,nop,sackOK,mss 1460> (DF)
Rory> 11 13:24:09.560459 myhost.smtp >
Rory> lfallback2.lnd.ops.eu.uu.net.47028: S 730092098:730092098(0)
Rory> ack 2889702441 win 5840 <mss 1460,nop,nop,sackOK> (DF)
Rory> 12 13:24:09.564674 lfallback2.lnd.ops.eu.uu.net.47028 >
Rory> myhost.smtp: . ack 1 win 24820 (DF)
for some inexplicable reason, the sender is trying a new SMTP connection at
this point.
Rory> 13 13:24:09.565942 myhost.24210 >
Rory> lfallback2.lnd.ops.eu.uu.net.auth: S 722300617:722300617(0) win
Rory> 5840 <mss 1460,sackOK,timestamp 985295981 0,nop,wscale 0> (DF)
Rory> 14 13:24:12.563758 myhost.24210 >
Rory> lfallback2.lnd.ops.eu.uu.net.auth: S 722300617:722300617(0) win
Rory> 5840 <mss 1460,sackOK,timestamp 985296281 0,nop,wscale 0> (DF)
Rory> 15 13:24:13.193799 myhost.24208 >
Rory> lfallback2.lnd.ops.eu.uu.net.auth: S 732414249:732414249(0) win
Rory> 5840 <mss 1460,sackOK,timestamp 985296344 0,nop,wscale 0> (DF)
Ident lookups again. The third of those is a retry from the original lookup
which is still proceeding; the first two are for the new connection.
Rory> 16 13:24:14.593814 lfallback2.lnd.ops.eu.uu.net.47028 >
Rory> myhost.smtp: P 1:7(6) ack 1 win 24820 (DF)
Another QUIT on the new connection, which again has been up for only 5
seconds.
Rory> 17 13:24:14.593841 myhost.smtp >
Rory> lfallback2.lnd.ops.eu.uu.net.47028: . ack 7 win 5840 (DF)
Rory> 18 13:24:14.593891 lfallback2.lnd.ops.eu.uu.net.47028 >
Rory> myhost.smtp: F 7:7(0) ack 1 win 24820 (DF)
Rory> 19 13:24:14.633896 myhost.smtp >
Rory> lfallback2.lnd.ops.eu.uu.net.47028: . ack 8 win 5840 (DF)
ack/FIN/ack for the new connection.
>From this point on it's just cleanup:
Rory> 20 13:24:18.564190 myhost.24210 >
Rory> lfallback2.lnd.ops.eu.uu.net.auth: S 722300617:722300617(0) win
Rory> 5840 <mss 1460,sackOK,timestamp 985296881 0,nop,wscale 0> (DF)
Rory> 21 13:24:25.194690 myhost.24208 >
Rory> lfallback2.lnd.ops.eu.uu.net.auth: S 732414249:732414249(0) win
Rory> 5840 <mss 1460,sackOK,timestamp 985297544 0,nop,wscale 0> (DF)
Rory> 22 13:24:30.565070 myhost.24210 >
Rory> lfallback2.lnd.ops.eu.uu.net.auth: S 722300617:722300617(0) win
Rory> 5840 <mss 1460,sackOK,timestamp 985298081 0,nop,wscale 0> (DF)
These are the final retries for the ongoing ident lookups
Rory> 23 13:24:35.368607 myhost.smtp >
Rory> lfallback2.lnd.ops.eu.uu.net.46989: P 1:33(32) ack 8 win 5840
Rory> (DF)
For the first connection: this is your exim returning the "synchronization
failed" error code.
Rory> 24 13:24:35.369020 myhost.smtp >
Rory> lfallback2.lnd.ops.eu.uu.net.46989: R 33:33(0) ack 8 win 5840
Rory> (DF)
Here your exim aborts the connection. (why is it aborting it rather than
closing?)
Rory> 25 13:24:35.372742 lfallback2.lnd.ops.eu.uu.net.46989 >
Rory> myhost.smtp: R 1626069306:1626069306(0) win 24820 (DF)
The sending end aborts the connection too.
Rory> 26 13:24:39.568955 myhost.smtp >
Rory> lfallback2.lnd.ops.eu.uu.net.47028: P 1:33(32) ack 8 win 5840
Rory> (DF)
Rory> 27 13:24:39.569379 myhost.smtp >
Rory> lfallback2.lnd.ops.eu.uu.net.47028: R 33:33(0) ack 8 win 5840
Rory> (DF)
and the same for the other SMTP connection.
--
Andrew, Supernews
http://www.supernews.com
