[wplug] more on SMTP delay

[Bill Moran]

duncanhutty at comcast.net wrote:
> I turned up the logging on Postfix, by changing the smtp service line
> in master.cf to smtpd -v and adding debug_peer_list = 192.168.0.0/16
> to main.cf
> I noticed that in this transaction there are three separate 5s delays;
> where the timestamp of consecutive log entries (of which there were a
> total of about 500 for one email) were separated by 5s.

I still don't have a sure concept of what I think is wrong, but for the
sake of brainstorming, it looks like spawning processes is taking a long
time.

> Here are those log entries that I noticed:
> 14:15:31 mail postfix/smtpd[11064]: connect from unknown[192.168.1.50]
> 14:15:31 mail postfix/smtpd[11064]: private/rewrite socket: wanted attribute: transport

Here it's trying to start a transport provider.  If I understand the
source code correctly (which I probably don't) the "wanted attribute:"
means that it's having trouble finding a particular config value.  It's
possible that it's being forced to fall back on a default because it
can't find a transport map.  Do you have any special configurations
for transport maps?

> 14:15:36 mail postfix/smtpd[11064]: vstream_buf_get_ready: fd 17 got 95
> 14:15:36 mail postfix/smtpd[11064]: input attribute name: transport
> 14:15:36 mail postfix/smtpd[11064]: dict_ldap_lookup: No existing connection for LDAP source ldapalias, reopening

Here I would suspect that you're correct and that it's having trouble
establishing the LDAP connection ... could just be slow.

> 14:15:41 mail postfix/smtpd[11064]: dict_ldap_connect: Connecting to server ldap://localhost:389
> 14:15:41 mail postfix/smtpd[11064]: public/cleanup socket: wanted attribute: status

Here again, we're passing the message from the smtpd process to the
cleanup process.  It appears as if the cleanup process needs a status
attribute that it's not finding, and I would guess it's falling back
to a default value.

> 14:15:46 mail postfix/cleanup[11067]: 8124530F7A: message-id=KOEEIIAAFANAOOGGFAKPIEIKEOAA.duncanh at mail.holidaytvl.com
> 14:15:46 mail postfix/smtpd[11064]: > unknown[192.168.1.50]: 250 Ok: queued as 8124530F7A
> I am not sure what the first delay (between 14:15:31 and 14:15:36) is
> about: private/rewrite wants a transport attribute; shouldn't that
> come from master.cf? If so I can't see why it would take so long.

The transport is usually set up in main.cf

What do you see when if you do "postconf | grep transport"?

> The second delay (between :36 and :41) appears to be while postfix is
> waiting for the LDAP server. Fair enough, I suppose there is a way to
> have a persistent connection with the LDAP server. Perhaps if I have
> postfix bind to the LDAP server, the connection will be persistent?

I've yet to use LDAP in a mail system (believe it or not) so I'm not
100% sure how to improve this.  5 seconds seems like a _long_ connection
delay in any case.  There's the Postfix proxy service for this kind of
thing, but I've yet to need that either.

> I am not sure what the third delay (between :41 and :46) is either:
> public/cleanup wants a status attribute?

This one is the most cryptic to me.  I don't know what it's trying to
do here.

Can you make you main.cf available?

-- 
Bill Moran
Potential Technologies
http://www.potentialtech.com