[Mailman-Users] Mailman needs 20 seconds to complete per email

[Stephen J. Turnbull]

Karsten Becker writes:
 > WTF?
 > 
 > > Dec 04 09:25:15 2012 qrunner(8680): connect:   ('localhost', 10030)
 > > Dec 04 09:25:15 2012 qrunner(8680): connect:   (10030, 'localhost')
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '220 mail01.foodmz.local ESMTP Ecologic Institute ready\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply: retcode (220); Msg: mail01.foodmz.local ESMTP Foo ready
 > > Dec 04 09:25:36 2012 qrunner(8680): connect:   mail01.foodmz.local ESMTP Foo ready
 > > Dec 04 09:25:36 2012 qrunner(8680): send:   'ehlo mail01.foodmz.local\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250-mail01.foodmz.local\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250-PIPELINING\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250-SIZE 20971520\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250-ETRN\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250-STARTTLS\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250-AUTH PLAIN LOGIN\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250-AUTH=PLAIN LOGIN\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250-ENHANCEDSTATUSCODES\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250-8BITMIME\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply:   '250 DSN\r\n'
 > > Dec 04 09:25:36 2012 qrunner(8680): reply: retcode (250); Msg: mail01.foodmz.local
 > 
 > 
 > What is this f***ing Postfix doing...????

This is just a normal handshake.  The two connects at 09:25:15 are
evidently a low-level TCP handshake by the qrunner connecting to the
SMTP server (Postfix, and port 25 is implied) on localhost from port
10030 (localhost is implied for the "from" host).  Why it's listed
twice I don't know; perhaps the first one is the qrunner sending an
initial SYN packet, and the second is the qrunner receiving an ACK
that confirms the connection is established.

The first two replies at 09:25:36 are not really replies: they are
Postfix announcing its presence to the new connection, not a response
to anything the qrunner said.  I have no idea why it takes 21 seconds
for Postfix to make that announcement.

I would guess that the following connect is the qrunner logging the
successful connection, not a new one.  The send, starting with "elho",
is the qrunner identifying itself to Postfix.  Each line starting with
"250" is a status code (250) saying Postfix is happy to talk to
"mail01.foodmz.local", followed by an extended SMTP feature that
Postfix offers over and above the features required by RFC 821 (and
its successors).  The final "reply: retcode" is the qrunner's
interpretation of the preceding gobbledygook, that Postfix is ready to
talk, and accept a message from "mail01".

HTH

Steve