[lug] postfix speed optimization

Ben Luey bluey at iguanaworks.net
Fri May 6 12:06:24 MDT 2011 

Is there a way to get postfix to delay checking for email aliases until 
after accepting emails from local users? (Or if not, get postfix to only 
do lookups for local recipients)? I recently added some email aliases to 
postfix via ldap and sql queries. They work fine, but the queries are 
relatively slow. Which I wouldn't care about if (for local connections) 
postfix did these queries after accepting a message for delivery. 
Instead it is doing the queries in (what I think is) the 'incoming' 
queue and not the 'active' queue. So users sending mail for, say, 
thunderbird, have to wait while postfix does this query... I want this 
query done after t-bird disconnects (or never).

So, when a local user connects to postfix to send email, postfix checks 
that the sender and recipient have valid email syntax (X at A.B), and if 
that is met, postfix asks for the data, disconnects and then figures out 
how to send the mail. For non-authorized users connect, I want postfix 
to do all the spam checks and alias lookups, etc, before accepting the 
email.

In my postfix config, I have

##these are slow lookups
virtual_alias_maps = hash:/etc/postfix/aliases, 
ldap:/etc/postfix/ldap-aliases.cf, pgsql:/etc/postfix/pg-mailinglist.cf

smtpd_recipient_restrictions =
         permit_mynetworks
         permit_sasl_authenticated,
         reject_non_fqdn_recipient
         reject_unauth_destination,
         check_recipient_access hash:/etc/postfix/access,



Looking at the logs (with smtpd -v) I see  (for sending to 
asdf at sdfasdf.com.mdf as a test)

May  6 10:12:31 mail postfix/smtpd[24164]: >>> START Recipient address 
RESTRICTIONS <<<
May  6 10:12:31 mail postfix/smtpd[24164]: generic_checks: 
name=permit_mynetworks
May  6 10:12:31 mail postfix/smtpd[24164]: permit_mynetworks: 
computer1.company.int 192.168.24.139
May  6 10:12:31 mail postfix/smtpd[24164]: match_hostname: 
computer1.company.int ~? 127.0.0.0/8
May  6 10:12:31 mail postfix/smtpd[24164]: match_hostaddr: 
192.168.24.139 ~? 127.0.0.0/8
May  6 10:12:31 mail postfix/smtpd[24164]: match_hostname: 
computer1.company.int ~? [::ffff:127.0.0.0]/104
May  6 10:12:31 mail postfix/smtpd[24164]: match_hostaddr: 
192.168.24.139 ~? [::ffff:127.0.0.0]/104
May  6 10:12:31 mail postfix/smtpd[24164]: match_hostname: 
computer1.company.int ~? [::1]/128
May  6 10:12:31 mail postfix/smtpd[24164]: match_hostaddr: 
192.168.24.139 ~? [::1]/128
May  6 10:12:31 mail postfix/smtpd[24164]: match_hostname: 
computer1.company.int ~? 192.168.24.0/24
May  6 10:12:31 mail postfix/smtpd[24164]: match_hostaddr: 
192.168.24.139 ~? 192.168.24.0/24
May  6 10:12:31 mail postfix/smtpd[24164]: generic_checks: 
name=permit_mynetworks status=1
May  6 10:12:31 mail postfix/smtpd[24164]: >>> CHECKING RECIPIENT MAPS <<<
May  6 10:12:31 mail postfix/smtpd[24164]: ctable_locate: leave existing 
entry key asdf at sdfasdf.com.mdf
May  6 10:12:31 mail postfix/smtpd[24164]: maps_find: 
recipient_canonical_maps: asdf at sdfasdf.com.mdf: not found
May  6 10:12:31 mail postfix/smtpd[24164]: match_string: sdfasdf.com.mdf 
~? localhost
May  6 10:12:31 mail postfix/smtpd[24164]: match_string: sdfasdf.com.mdf 
~? locahost.company.int
May  6 10:12:31 mail postfix/smtpd[24164]: match_list_match: 
sdfasdf.com.mdf: no match
May  6 10:12:31 mail postfix/smtpd[24164]: maps_find: 
recipient_canonical_maps: @sdfasdf.com.mdf: not found
May  6 10:12:31 mail postfix/smtpd[24164]: mail_addr_find: 
asdf at sdfasdf.com.mdf -> (not found)
May  6 10:12:31 mail postfix/smtpd[24164]: maps_find: canonical_maps: 
asdf at sdfasdf.com.mdf: not found
May  6 10:12:31 mail postfix/smtpd[24164]: match_string: sdfasdf.com.mdf 
~? localhost
May  6 10:12:31 mail postfix/smtpd[24164]: match_string: sdfasdf.com.mdf 
~? locahost.company.int
May  6 10:12:31 mail postfix/smtpd[24164]: match_list_match: 
sdfasdf.com.mdf: no match
May  6 10:12:31 mail postfix/smtpd[24164]: maps_find: canonical_maps: 
@sdfasdf.com.mdf: not found
May  6 10:12:31 mail postfix/smtpd[24164]: mail_addr_find: 
asdf at sdfasdf.com.mdf -> (not found)
May  6 10:12:31 mail postfix/smtpd[24164]: dict_ldap_lookup: In 
dict_ldap_lookup
May  6 10:12:31 mail postfix/smtpd[24164]: dict_ldap_lookup: No existing 
connection for LDAP source /etc/postfix/ldap-aliases.cf, reopening
May  6 10:12:31 mail postfix/smtpd[24164]: dict_ldap_connect: Connecting 
to server ldap://localhost:389
May  6 10:12:31 mail postfix/smtpd[24164]: dict_ldap_connect: Actual 
Protocol version used is 3.
May  6 10:12:31 mail postfix/smtpd[24164]: dict_ldap_connect: Binding to 
server ldap://localhost:389 as dn
May  6 10:12:31 mail postfix/smtpd[24164]: dict_ldap_connect: Successful 
bind to server ldap://localhost:389 as
May  6 10:12:31 mail postfix/smtpd[24164]: dict_ldap_connect: Cached 
connection handle for LDAP source /etc/postfix/ldap-aliases.cf
May  6 10:12:31 mail postfix/smtpd[24164]: dict_ldap_lookup: 
/etc/postfix/ldap-aliases.cf: Searching with filter 
(mail=asdf at sdfasdf.com.mdf)
May  6 10:12:31 mail postfix/smtpd[24164]: dict_ldap_get_values[1]: 
Search found 0 match(es)
May  6 10:12:31 mail postfix/smtpd[24164]: dict_ldap_get_values[1]: 
Leaving dict_ldap_get_values
...
and then the same on the SQL server.


Also, I see a 2 second lag after the "rcpt to: asdf at asdf.com" is sent to 
the smtp server before the server replies "250 2.1.0 OK" In the logs, I see

May  6 10:12:29 mail postfix/smtpd[24164]: private/rewrite socket: 
wanted attribute: (list terminator)
May  6 10:12:29 mail postfix/smtpd[24164]: input attribute name: (end)
May  6 10:12:29 mail postfix/smtpd[24164]: rewrite_clnt: local: 
asdf at sdfasdf.com.mdf -> asdf at sdfasdf.com.mdf
May  6 10:12:29 mail postfix/smtpd[24164]: send attr request = resolve
May  6 10:12:29 mail postfix/smtpd[24164]: send attr sender =
May  6 10:12:29 mail postfix/smtpd[24164]: send attr address = 
asdf at sdfasdf.com.mdf
May  6 10:12:31 mail postfix/smtpd[24164]: private/rewrite socket: 
wanted attribute: flags
May  6 10:12:31 mail postfix/smtpd[24164]: input attribute name: flags
May  6 10:12:31 mail postfix/smtpd[24164]: input attribute value: 0
May  6 10:12:31 mail postfix/smtpd[24164]: private/rewrite socket: 
wanted attribute: transport
May  6 10:12:31 mail postfix/smtpd[24164]: input attribute name: transport
May  6 10:12:31 mail postfix/smtpd[24164]: input attribute value: smtp
May  6 10:12:31 mail postfix/smtpd[24164]: private/rewrite socket: 
wanted attribute: nexthop

Any ideas on what is causing this delay?

Thanks,
Ben

More information about the LUG mailing list