Subject: RE: smtp(8) question re hotmail.com

From: zmailer <[email-masked]>
Date: Tue, 7 May 2002 20:05:56 -0300

Hello,

we have a similar problem (not so similar...)
with yahoo.

When a connection is reused for a new mail, sometimes it fails
(451 Timeout)
Zmailer retries twice and the recipient ends with two identical messages.
Here is the log.

first mail is ok, just to show that this is a reused connection.

17944i0000005550#       jobspec: X/3403-14848   yahoo.com
17944i0000105550#       3403-14848:
<5DC7EB0268F3E549BA5ACFB1DDF1236D46AC@mafalda>
17944i0000205550#       (Connecting to `mta-v12.level3.mail.yahoo.com'
[64.157.4.82|25] Tue May  7 18:05:28 2002)
17944i0000305551r       220 YSmtp mta415.mail.yahoo.com ESMTP service ready
17944i0000405551w       EHLO dedos
17944i0000505551r       250-mta415.mail.yahoo.com
17944i0000605551r       250-8BITMIME
17944i0000705551r       250-SIZE 5242880
17944i0000805551r       250 PIPELINING
17944i0000905551#       smtpopen: status = 0
17944i0001005551w       MAIL From:<BB@BB> BODY=8BITMIME SIZE=795
17944i0001105551w       RCPT To:<[email-masked]>
17944i0001205551w       DATA
17944i0001305551r       250 sender <BB@BB> ok
17944i0001405551r       250 recipient <[email-masked]> ok
17944i0001505551r       354 go ahead
17944i0001605551w       .
17944i0001705551r       250 ok dirdel
17944i0001805551#       784 bytes, 645 in header, 1 recipients, 0 secs for
envelope, 0 secs for body xfer
17944i0001905551#       jobspec: K/3390-14849   yahoo.com
17944i0002005551#       3390-14849: <3CD81760.9006.6E9B3C9@localhost>
17944i0002105551w       MAIL From:<BB@BB> BODY=8BITMIME SIZE=978
17944i0002205551w       RCPT To:<[email-masked]>
17944i0002305551w       DATA
17944i0002405552r       250 sender <BB@BB> ok
17944i0002505552r       250 recipient <[email-masked]> ok
17944i0002605552r       354 go ahead
17944i0002705552w       .
17944i0002805553r       250 ok dirdel
17944i0002905553#       975 bytes, 672 in header, 1 recipients, 1 secs for
envelope, 1 secs for body xfer
17944i0003005553#       jobspec: #idle
17944i0003105689#       jobspec: P/3395-14848   yahoo.com
17944i0003205689#       3395-14848:
<[email-masked]>
17944i0003305689w       MAIL From:<n@n> BODY=8BITMIME SIZE=984
17944i0003405689w       RCPT To:<[email-masked]>
17944i0003505689w       DATA
17944i0003605689r       451 Timeout
					^^^^^^^^^^^^^^

17944i0003705689#       Remote hung up on us while 2 responses missing
17944i0003805689#        smtp_sync() did yield code 75
17944i0003905689w       RSET
17944i0004005689#       Remote hung up on us while 3 responses missing
17944i0004105689#        smtp_sync() did yield code 75
17944i0004205689#       (closed SMTP channel - after delivery failure)
17944i0004305689#       (Connecting to `mta-v18.level3.mail.yahoo.com'
[64.157.4.88|25] Tue May  7 18:07:47 2002)
17944i0004405689r       220 YSmtp mta518.mail.yahoo.com ESMTP service ready
17944i0004505689w       EHLO dedos
17944i0004605689r       250-mta518.mail.yahoo.com
17944i0004705689r       250-8BITMIME
17944i0004805689r       250-SIZE 5242880
17944i0004905689r       250 PIPELINING
17944i0005005689#       smtpopen: status = 0
17944i0005105689w       MAIL From:<n@n> BODY=8BITMIME SIZE=984
17944i0005205689w       RCPT To:<[email-masked]>
						^^^^^^^^^^^^^first copy
17944i0005305689w       DATA
17944i0005405690r       250 sender <n@n> ok
17944i0005505690r       250 recipient <[email-masked]> ok
17944i0005605690r       354 go ahead
17944i0005705690w       .
17944i0005805690r       250 ok dirdel
17944i0005905690#       970 bytes, 773 in header, 1 recipients, 1 secs for
envelope, 0 secs for body xfer
17944i0006005690#       jobspec: #idle
17944i0006105699#       jobspec: P/3395-14848   yahoo.com
17944i0006205699#       3395-14848:
<[email-masked]>
17944i0006305699w       MAIL From:<n@n> BODY=8BITMIME SIZE=984
17944i0006405699w       RCPT To:<[email-masked]>
						^^^^^^^^^^^^^^^^ second copy
17944i0006505699w       DATA
17944i0006605699r       250 sender <n@n> ok
17944i0006705699r       250 recipient <[email-masked]> ok
17944i0006805699r       354 go ahead
17944i0006905699w       .
17944i0007005700r       250 ok dirdel
17944i0007105700#       970 bytes, 773 in header, 1 recipients, 0 secs for
envelope, 1 secs for body xfer

Jobspec, Message ID, recipient and source are the same...
Version:
/app/zmailer/bin/ta/smtp  -V
ZMailer smtp (2.99.55 #1: Mon Nov  5 11:32:39 ART 2001)

> -----Original Message-----
> From: Ambrose Li [mailto:[email-masked]]
> Sent: Tuesday, May 07, 2002 1:23 PM
> To: [email-masked]
> Subject: smtp(8) question re hotmail.com
> 
> 
> Hello,
> 
> I wonder if anyone has problems with ZMailer sending mail to
> hotmail.com. It seems that, sometimes, when ZMailer issues the
> MAIL FROM command using a previous connection, hotmail will
> complain 554 Transaction failed, and ZMailer will then bounce
> the input back to the sender.
> 
> Is there an option in scheduler.conf (or some other way) to stop
> ZMailer from keeping the connection to hotmail.com or decrease
> the NOOP keepalive time for hotmail.com? Or I am looking in
> the wrong direction?  Since hotmail is so big, someone must
> recognize what I am doing wrong :-)
> 
> This is ZMailer 2.99.56-pre1 (CVS snapshot from 2002.04.20).
> Thanks very much in advance,
> 
> -- 
> Ambrose Li
> 
> ``A good style should show no sign of effort;
>   what is written should seem a happy accident.'' ~ Somerset Maugham
> -
> To unsubscribe from this list: send the line "unsubscribe zmailer" in
> the body of a message to [email-masked]
> 
-
To unsubscribe from this list: send the line "unsubscribe zmailer" in
the body of a message to [email-masked]

---

From: Ambrose Li <[email-masked]>
Date: Wed, 8 May 2002 10:45:28 -0400

Hello,

> we have a similar problem (not so similar...)

perhaps the two problems are related, that ZMailer is being
confused by an unsolicited response and mistook it for the
response to the MAIL FROM?  (I guess this is why some mailers
like to issue RSET :-/ but the ZMailer docs say RSET behaves
differently on different systems; perhaps we could try to issue
NOOP...)

> Zmailer retries twice and the recipient ends with two
> identical messages.  Here is the log.
>

[...]

The log from my system looks like the following:

(The first mail is ok; the second mail tries to use the reused
connection, fails because of the 554, bounces back, and is
ultimately not delivered.)

12228E0000067640#	jobspec: Z/32135-31031	hotmail.com
[...]
12228E0001867644#	(Connecting to `mc5.law13.hotmail.com' [64.4.50.7|25] Wed May  8 10:20:44 2002)
12228E0001967644r	220-HotMail (NO UCE) ESMTP server ready at Wed, 08 May 2002 07:20:44 -0700 
12228E0002067644r	220 ESMTP spoken here
12228E0002167644w	EHLO webserver
12228E0002267644r	250-hotmail.com Hello
12228E0002367644r	250-8bitmime
12228E0002467644r	250 SIZE 1572864
12228E0002567644#	EHLO rc=0 demand_TLS_mode=0 tls_available=0
12228E0002667644#	smtpopen: status = 0
12228E0002767644w	MAIL From:<[email-masked]> SIZE=282937
12228E0002867645r	250 Requested mail action okay, completed
12228E0002967645w	RCPT To:<[email-masked]>
12228E0003067645r	250 Requested mail action okay, completed
12228E0003167645w	DATA
12228E0003267645r	354 Start mail input; end with <CRLF>.<CRLF>
12228E0003367651w	.
12228E0003467661r	250 Requested mail action okay, completed
12228E0003567661#	273890 bytes, 34 in header, 1 recipients, 1 secs for envelope, 16 secs for body xfer
12228E0003667661#	jobspec: #idle
12228E0003767783#	jobspec: Z/32135-31031	hotmail.com
12228E0003867783#	32135-31031: <[email-masked]>
12228E0003967783w	MAIL From:<[email-masked]> SIZE=632
12228E0004067783r	554 Transaction failed
12228E0004167783#	 smtp_sync() did yield code 69/UNAVAILABLE
12228E0004267793#	Remote hung up on us while 1 responses missing
12228E0004367793#	 smtp_sync() did yield code 69/UNAVAILABLE
12228E0004467793#	(closed SMTP channel - MAIL FROM:<> got two responses! [or EOF])
12228E0004567793#	jobspec: #idle
12228E0004668109#	jobspec: 

-- 
Ambrose Li

---

From: Ambrose Li <[email-masked]>
Date: Wed, 8 May 2002 12:12:49 -0400

Hello,

I dug into the source code and found my answer (which is "no,
there's no way to configure it").

So I changed the source (smtp.c) a bit so that there's a way to
configure it.  Please check if this patch looks ok or not.  (It
seems to be okay, & it seems that sending keep-alives as often
as 60 seconds once is useless for hotmail.) The patch is against
the CVS version as of 2002-04-20.

Of course this doesn't get to the root of the problem, which
seems to be ZMailer being confused by the unsolicited response;
I don't think I know the internals good enough to figure out
what really should be fixed.

BTW, does anyone know which variable controls how long a
reusable connection is kept alive?

------------- cut here ------------- 8< ----------------------
--- transports/smtp/smtp.c.dist	Fri Apr 19 19:26:38 2002
+++ transports/smtp/smtp.c	Wed May  8 11:59:35 2002
@@ -22,6 +22,7 @@
 int timeout_tcpw =  5*60;	/* All tcp writes ?? */
 int timeout_dot  = 20*60;
 int timeout_conn =  3*60;	/* connect() timeout */
+int timeout_noop =  3*60;	/* Another 'keepalive' in 3 minutes */
 
 int sockwbufsize =  0;
 
@@ -61,6 +62,7 @@
 				   "nobody", in which case use "daemon"      */
 
 int D_alloc = 0;		/* Memory usage debug */
+int always_close_after_data = 0;	/* In case the remote system doesn't like keepalives */
 int no_pipelining = 0;		/* In case the system just doesn't cope with it */
 #if defined(AF_INET6) && defined(INET6)
 int use_ipv6 = 1;
@@ -167,7 +169,7 @@
 	time(&now);

-	tmout = now + 3*60;
+	tmout = now + timeout_noop;

 	s = *bufp;
@@ -235,7 +237,7 @@
 	    }
 	  }
 	  if (now >= tmout)
-	    tmout = now + 3*60; /* Another 'keepalive' in 3 minutes */
+	    tmout = now + timeout_noop; /* Another 'keepalive' in 3 minutes or whatever -t noop=# says */
 
 	  if (rc == 1) { /* We have only ONE descriptor readable.. */
 	    /* Got something to read on 'infd' (or EOF)
@@ -472,7 +474,7 @@
 	SS.remotemsg[0] = '\0';
 	SS.remotehost[0] = '\0';
 	while (1) {
-	  c = getopt(argc, argv, "c:deh:l:p:rsvw:xDEF:L:HMPS:T:VWZ:678");
+	  c = getopt(argc, argv, "c:deh:l:p:rsvw:xDEF:L:HKMPS:T:VWZ:678");
 	  if (c == EOF)
 	    break;
 	  switch (c) {
@@ -528,6 +530,10 @@
 	  case 'H':
 	    keep_header8 = 1;
 	    break;
+	  case 'K':		/* close the connection after sending */
+	    always_close_after_data = 1;
+	    close_after_data = 1;	/* actual flag used by delivery code */
+	    break;
 	  case 'L':		/* Specify which local identity to use */
 	    localidentity = strdup(optarg);
 	    break;
@@ -559,6 +565,14 @@
 		++errflg;
 	      }
 	      break;
+	    } else if (CISTREQN(optarg,"noop=",5)) {
+	      timeout_noop = parse_interval(optarg+5,NULL);
+	      if (timeout_noop < 10) {
+		fprintf(stderr, "%s: bad noop (send-keep-alive) timeout: %s\n",
+			argv[0], optarg+5);
+		++errflg;
+	      }
+	      break;
 	    } else if (CISTREQN(optarg,"tcpw=",5)) {
 	      timeout_tcpw = parse_interval(optarg+5,NULL);
 	      if (timeout_tcpw < 10) {
@@ -625,7 +639,7 @@
 
 	if (errflg || optind > argc) {
 	  fprintf(stderr,
-		  "Usage: %s [-8|-8H|-7][-e][-r][-x][-E][-P][-W][-T timeout][-h myhostname][-l logfile][-p portnum][-c channel][-F forcedest][-L localidentity][-S /path/to/SmtpSSL.conf] [host]\n", argv[0]);
+		  "Usage: %s [-8|-8H|-7][-e][-r][-x][-E][-K][-P][-W][-T timeout][-h myhostname][-l logfile][-p portnum][-c channel][-F forcedest][-L localidentity][-S /path/to/SmtpSSL.conf] [host]\n", argv[0]);
 	  exit(EX_USAGE);
 	}
 
@@ -783,7 +797,7 @@
 		if (statusreport)
 		  report(&SS, "NewDomain: %s", host);
 	      }
-	      close_after_data = 0;
+	      close_after_data = always_close_after_data;
 	    }
 	    if (host) free((void*)host);
 	    host = strdup(s);
@@ -1879,7 +1893,7 @@
 	  smtpwrite(SS, 0, "QUIT", -1, NULL);
 	  smtpclose(SS,1);
 	  if (logfp)
-	    fprintf(logfp, "%s#\t(closed SMTP channel - ``close_after_data'' mode.", logtag());
+	    fprintf(logfp, "%s#\t(closed SMTP channel - ``close_after_data'' mode.)\n", logtag());
 	  retryat_time = 0;
 	}
 
--- man/smtp.8.dist	Mon Dec 10 17:35:27 2001
+++ man/smtp.8	Wed May  8 11:26:03 2002
@@ -7,7 +7,7 @@
 \- zmailer SMTP client transport agent
 .SH SYNOPSIS
 .IP \fBsmtp\fR 5em
-[\fB\-678deEHMrPsVxW\fR]
+[\fB\-678deEHKMrPsVxW\fR]
 [\fB\-c\fR\ \fIchannel\fR]
 [\fB\-h\fR\ \fIheloname\fR]
 [\fB\-l\fR\ \fIlogfile\fR]
@@ -130,6 +130,9 @@
 turns off MX lookups on delivery connections.  This may be used ignore
 public MX knowledge and do exactly what the router says in cases where
 delivering to an explicit IP address is inappropriate.
+.IP \-K
+force \(lqclose_after_data\(rq mode:
+disable keep-alives; do not reuse SMTP connections
 .IP \-P
 disable SMTP-PIPELINING usage (ESMTP keyword: PIPELINING)
 .IP \-S\ \fI/path/to/smtp-tls.conf\fR
@@ -157,12 +160,15 @@
 Waiting for command replies (e.g. MAIL FROM, et.al.)
 The default is 5 minutes.
 .IP data=\fI2m\fR
-From "DATA" verb issuance until "354" responce.
+From "DATA" verb issuance until "354" response.
 The default is 2 minutes.
 .IP dot=\fI10m\fR
 From "DATA" phase ending "." issuance until "250 OK" report
 reception (this is \fBafter\fR the TCP write pipeline has completed).
 The default is 20 minutes. (RFC 1123 gives 10 minutes.)
+.IP noop=\fI3m\fR
+Time between keep-alives (NOOP).
+The default is 3 minutes.
 .RE
 .IP \-V
 prints a version message and exits.
------------- cut here ------------- 8< ----------------------

[The patch contains two unrelated typo corrections.)

-- 
Ambrose Li

---

From: Ambrose Li <[email-masked]>
Date: Thu, 9 May 2002 21:05:13 -0400

Hi,

I found another thing about this problem: That this is a relatively
new problem. On my ZMailer running at my home, the smtp TA that
identified itself as from 2.99.50s11 treated the 554 Transaction
Failed as a temporary failure and would retry.

Perhaps this problem got introduced when the handling of 5xx errors
was changed to correct some other problems?

Sample log (from the 2.99.50s11 smtp TA) followed by sample output
from mailq:

23381V0000191854#	jobspec: N/131105-3276	hotmail.com
23381V0000291863#	(Connecting to `mx09.hotmail.com' [64.4.49.71|25] Thu May  9 20:51:03 2002)
23381V0000391864r	220-HotMail (NO UCE) ESMTP server ready at Thu, 09 May 2002 17:51:04 -0700 
23381V0000491864r	220 ESMTP spoken here
23381V0000591864w	EHLO example.org
23381V0000691865r	250-hotmail.com Hello
23381V0000791865r	250-8bitmime
23381V0000891865r	250 SIZE 1572864
23381V0000991865#	131105-3276: <[email-masked]>
23381V0001091865w	MAIL From:<[email-masked]> SIZE=474
23381V0001191866r	250 Requested mail action okay, completed
23381V0001291866w	RCPT To:<[email-masked]>
23381V0001391866r	250 Requested mail action okay, completed
23381V0001491866w	DATA
23381V0001591866r	354 Start mail input; end with <CRLF>.<CRLF>
23381V0001691866w	.
23381V0001791868r	250 Requested mail action okay, completed
23381V0001891868#	5 bytes, 447 in header, 1 recipients, 1 secs for envelope, 2 secs for body xfer
23381V0001991875#	jobspec: #idle
23381V0002091956#	jobspec: N/131105-3276	hotmail.com
23381V0002191956#	131105-3276: <[email-masked]>
23381V0002291956w	MAIL From:<[email-masked]> SIZE=474
23381V0002391956r	554 Transaction failed
23381V0002491966#	(closed SMTP channel - bad response on smtpwrite() )
23381V0002591966#	(closed SMTP channel - MAIL FROM:<> got two responses!)
23381V0002691966#	jobspec: #idle
23381V0002792089#	jobspec: 

$ mailq
0 entries in router queue: idle
1 message in transport queue: working
smtp/hotmail.com:
        N/131105-3276:  smtp; 500 (Error on initial SMTP response read: Broken p
ipe) (retry in 2m45s, expires in 1d23h, tries=1)
          id    <[email-masked]>, 398 bytes, age 5m10s
          from  [email-masked]
          to    [email-masked]

-- 
Ambrose Li  <[email-masked]>   http://trends.ca/~foo/
                                              http://www.cccgt.org/
A good style should show no sign of effort;
  what is written should seem a happy accident. - Somerset Maugham
-
To unsubscribe from this list: send the line "unsubscribe zmailer" in
the body of a message to [email-masked]