Take the 2-minute tour ×
Server Fault is a question and answer site for system and network administrators. It's 100% free, no registration required.

I'm having a real pickle of a problem:

I have a Postfix 2.6.6 / CentOS 6 server that's set up to forward mail from specific aliases to specific destinations. This is done through a mysql virtual_alias_maps table, as aliases/destinations are generated by a web based front end.

The issue is that sometimes and for no apparent reason Postfix does not bother looking in virtual_alias_maps and gives a "Relay access denied" status for certain aliases.

I can't pin it down to a configuration or DB problem because during a time at which delivery is failing:

  • I can postmap -q valid_alias@mydomain.com mysql:/etc/postfix/mysql_virtual_alias_maps.cf successfully, even when just before and just after that command I get "Relay access denied" for that same address when telneting into the SMTP server.
  • Looking at the mysql general query log, I see queries to transport maps and virtual alias domains, but not virtual alias maps.
  • Immediately after a new address is added to the virtual_alias_maps mysql table it does work.
  • postfix reload nor a restart solve the problem; It seems to resolve itself at an arbitrary time, and with nothing obvious in the logs in between.

The thing that really drives me crazy is that when I find an example of a couple of addresses that aren't working, I can find a whole lot that are working at that same time.

In all cases, the addresses are @mydomain.com AND are successfully looked up using postmap -q.

I don't see any failures in any of the logs (mysql/postfix/syslog). It seems that Postfix simply skips the lookup into virtual alias maps.

Postfix debug log (failure case):

May 28 16:37:39 ext-node01 postfix/smtpd[28115]: < debug_peer.something.com[64.34.10.20]: rcpt to:7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: extract_addr: input: 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: smtpd_check_addr: addr=7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: send attr request = rewrite
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: send attr rule = local
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: send attr address = 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: flags
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: flags
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute value: 0
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: address
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: address
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute value: 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: (list terminator)
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: (end)
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: rewrite_clnt: local: 7muw04pj@mydomain.com -> 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: send attr request = resolve
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: send attr sender =
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: send attr address = 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: flags
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: flags
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute value: 0
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: transport
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: transport
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute value: smtp
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: nexthop
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: nexthop
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute value: mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: recipient
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: recipient
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute value: 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: flags
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: flags
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute value: 4096
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: (list terminator)
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: (end)
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: resolve_clnt: `' -> `7muw04pj@mydomain.com' -> transp=`smtp' host=`mydomain.com' rcpt=`7muw04pj@mydomain.com' flags= class=default
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: ctable_locate: install entry key 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: extract_addr: in: 7muw04pj@mydomain.com, result: 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: send attr request = rewrite
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: send attr rule = local
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: send attr address = double-bounce
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: flags
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: flags
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute value: 0
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: address
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: address
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute value: double-bounce@mx01.mail.myhosting.net
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: private/rewrite socket: wanted attribute: (list terminator)
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: input attribute name: (end)
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: rewrite_clnt: local: double-bounce -> double-bounce@mx01.mail.myhosting.net
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: >>> START Recipient address RESTRICTIONS <<<
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: generic_checks: name=permit_mynetworks
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: permit_mynetworks: debug_peer.something.com 64.34.10.20
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: match_hostname: debug_peer.something.com ~? 127.0.0.0/8
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: match_hostaddr: 64.34.10.20 ~? 127.0.0.0/8
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: match_list_match: debug_peer.something.com: no match
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: match_list_match: 64.34.10.20: no match
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: generic_checks: name=permit_mynetworks status=0
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: generic_checks: name=reject_unauth_destination
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: reject_unauth_destination: 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: permit_auth_destination: 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: ctable_locate: leave existing entry key 7muw04pj@mydomain.com
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: NOQUEUE: reject: RCPT from debug_peer.something.com[64.34.10.20]: 450 4.7.1 <7muw04pj@mydomain.com>: Relay access denied; from=<scott@mintred.com> to=<7muw04pj@mydomain.com> proto=SMTP helo=<fuack>
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: generic_checks: name=reject_unauth_destination status=2
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: > debug_peer.something.com[64.34.10.20]: 450 4.7.1 <7muw04pj@mydomain.com>: Relay access denied

Postfix debug log (success case)

May 28 17:14:20 ext-node01 postfix/smtpd[31233]: < debug_peer.something.com[64.34.10.20]: rcpt to:7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: extract_addr: input: 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: smtpd_check_addr: addr=7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: send attr request = rewrite
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: send attr rule = local
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: send attr address = 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: private/rewrite socket: wanted attribute: flags
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute name: flags
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute value: 0
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: private/rewrite socket: wanted attribute: address
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute name: address
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute value: 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: private/rewrite socket: wanted attribute: (list terminator)
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute name: (end)
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: rewrite_clnt: local: 7muw04pj@mydomain.com -> 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: send attr request = resolve
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: send attr sender =
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: send attr address = 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: private/rewrite socket: wanted attribute: flags
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute name: flags
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute value: 0
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: private/rewrite socket: wanted attribute: transport
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute name: transport
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute value: error
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: private/rewrite socket: wanted attribute: nexthop
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute name: nexthop
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute value: User unknown in virtual alias table
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: private/rewrite socket: wanted attribute: recipient
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute name: recipient
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute value: 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: private/rewrite socket: wanted attribute: flags
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute name: flags
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute value: 512
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: private/rewrite socket: wanted attribute: (list terminator)
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: input attribute name: (end)
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: resolve_clnt: `' -> `7muw04pj@mydomain.com' -> transp=`error' host=`User unknown in virtual alias table' rcpt=`7muw04pj@mydomain.com' flags= class=alias
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: ctable_locate: install entry key 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: extract_addr: in: 7muw04pj@mydomain.com, result: 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: >>> START Recipient address RESTRICTIONS <<<
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: generic_checks: name=permit_mynetworks
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: permit_mynetworks: debug_peer.something.com 64.34.10.20
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: match_hostname: debug_peer.something.com ~? 127.0.0.0/8
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: match_hostaddr: 64.34.10.20 ~? 127.0.0.0/8
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: match_list_match: debug_peer.something.com: no match
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: match_list_match: 64.34.10.20: no match
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: generic_checks: name=permit_mynetworks status=0
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: generic_checks: name=reject_unauth_destination
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: reject_unauth_destination: 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: permit_auth_destination: 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: ctable_locate: leave existing entry key 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: generic_checks: name=reject_unauth_destination status=0
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: >>> END Recipient address RESTRICTIONS <<<
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: >>> CHECKING RECIPIENT MAPS <<<
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: ctable_locate: leave existing entry key 7muw04pj@mydomain.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: maps_find: recipient_canonical_maps: 7muw04pj@mydomain.com: not found
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: match_string: mydomain.com ~? mx01.mail.myhosting.net
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: match_list_match: mydomain.com: no match
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: maps_find: recipient_canonical_maps: @mydomain.com: not found
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: mail_addr_find: 7muw04pj@mydomain.com -> (not found)
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: maps_find: canonical_maps: 7muw04pj@mydomain.com: not found
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: match_string: mydomain.com ~? mx01.mail.myhosting.net
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: match_list_match: mydomain.com: no match
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: maps_find: canonical_maps: @mydomain.com: not found
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: mail_addr_find: 7muw04pj@mydomain.com -> (not found)
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: dict_mysql_get_active: attempting to connect to host 127.0.0.1
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: dict_mysql: successful connection to host 127.0.0.1
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: dict_mysql: successful query from host 127.0.0.1
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: dict_mysql_lookup: retrieved 1 rows
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: maps_find: virtual_alias_maps: mysql:/etc/postfix/mysql_virtual_alias_maps.cf(0,lock|fold_fix): 7muw04pj@mydomain.com = sample-recip@gmail.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: mail_addr_find: 7muw04pj@mydomain.com -> sample-recip@gmail.com
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: smtpd_check_rewrite: trying: permit_inet_interfaces
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: permit_inet_interfaces: debug_peer.something.com 64.34.10.20
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: before input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping enable_milters
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: after input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: connect to subsystem public/cleanup
May 28 17:14:21 ext-node01 postfix/smtpd[31233]: public/cleanup socket: wanted attribute: queue_id
May 28 17:14:21 ext-node01 postfix/smtpd[31233]: input attribute name: queue_id
May 28 17:14:21 ext-node01 postfix/smtpd[31233]: input attribute value: 012DCF8003F
May 28 17:14:21 ext-node01 postfix/smtpd[31233]: public/cleanup socket: wanted attribute: (list terminator)
May 28 17:14:21 ext-node01 postfix/smtpd[31233]: input attribute name: (end)
May 28 17:14:21 ext-node01 postfix/smtpd[31233]: send attr flags = 178
May 28 17:14:21 ext-node01 postfix/smtpd[31233]: 012DCF8003F: client=debug_peer.something.com[64.34.10.20]
May 28 17:14:21 ext-node01 postfix/smtpd[31233]: > debug_peer.something.com[64.34.10.20]: 250 2.1.5 Ok

Note that the timestamps on those log snippets are about 37 minutes apart. During that time I was pouring over logs, not making config changes.

Again, immediately before and after both log snippets:

postmap -q 7muw04pj@mydomain.com mysql:/etc/postfix/mysql_virtual_alias_maps.cf
sample-recip@gmail.com

The server is under low load. Probably about 2-3 SMTP sessions per min.

My own testing aside, I see this same behavior in the logs for valid recipients and valid senders where relay access will be denied a few times (as the upstream SMTP server retries delivery) and then suddenly succeed with no intervention on my part.

I set my reject statuses to soft fails (4xx) as a temporary measure so that other SMTP servers will retry over time.

I also setup a cron job to do a postfix reload every five minutes, but still observed in the wild that this didn't help.

Any advice on where to look next would be welcome. Thanks!

EDIT: The output of postconf -n:

access_map_reject_code = 450
alias_database = hash:/etc/aliases
alias_maps = hash:/etc/aliases
command_directory = /usr/sbin
config_directory = /etc/postfix
content_filter = amavisfeed:[127.0.0.1]:10024
daemon_directory = /usr/libexec/postfix
debug_peer_level = 2
debug_peer_list = 64.34.10.20
html_directory = no
inet_interfaces = localhost, 192.168.1.1  //SANITIZED IP
inet_protocols = ipv4
mail_owner = postfix
mailq_path = /usr/bin/mailq.postfix
manpage_directory = /usr/share/man
maps_rbl_reject_code = 450
mydestination = mx01.mail.myhosting.net  //SANITIZED HOST
myhostname = mx01.mail.myhosting.net  //SANITIZED HOST
mynetworks = 127.0.0.0/8
newaliases_path = /usr/bin/newaliases.postfix
queue_directory = /var/spool/postfix
readme_directory = /usr/share/doc/postfix-2.6.6/README_FILES
reject_code = 450
relay_domains = mysql:/etc/postfix/mysql_relay_domains.cf
relay_domains_reject_code = 450
sample_directory = /usr/share/doc/postfix-2.6.6/samples
sendmail_path = /usr/sbin/sendmail.postfix
setgid_group = postdrop
smtp_host_lookup = native
smtpd_client_connection_count_limit = 10
smtpd_error_sleep_time = 1s
smtpd_hard_error_limit = 20
smtpd_soft_error_limit = 10
transport_maps = mysql:/etc/postfix/mysql_transport_maps.cf
unknown_local_recipient_reject_code = 450
unknown_relay_recipient_reject_code = 450
unknown_virtual_alias_reject_code = 450
unknown_virtual_mailbox_reject_code = 450
virtual_alias_domains = mysql:/etc/postfix/mysql_virtual_alias_domains.cf
virtual_alias_maps = mysql:/etc/postfix/mysql_virtual_alias_maps.cf
share|improve this question
    
Can you post output of postconf -n? –  masegaloeh May 28 at 22:36
    
No prob! Added it to the original post. I "commented" on 3 lines where I sanitized an IP/hosts. They are consistent to the other log snippets, also sanitized. –  s.co.tt May 29 at 2:29
    
Hi, s.co.tt, your question is interesting. Did you have any working solution besides adding 4xx and adding cron jobs? –  tpml7 Oct 25 at 13:44
    
No, I'm afraid I still haven't solved this one. The cron reload doesn't seem to make a difference, but the 4xx does bounce the upstream server to another one of my servers so that when the lookup isn't working the message does through with a small delay. (I have 3 servers running identical Postfix instances, all listed as MX records for mydomain.com). –  s.co.tt Oct 25 at 17:56

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Browse other questions tagged or ask your own question.