Estou tendo um problema real:
Eu tenho um servidor Postfix 2.6.6 / CentOS 6 configurado para encaminhar e-mails de aliases específicos para destinos específicos. Isso é feito através de uma tabela mysql virtual_alias_maps , pois os aliases / destinos são gerados por um front-end baseado na web.
A questão é que algumas vezes e nenhuma razão aparente O Postfix não se preocupa em procurar em virtual_alias_maps e dá um status de "Relay access denied" para certos aliases.
Não consigo defini-lo como um problema de configuração ou banco de dados porque, durante um período no qual a entrega está falhando:
postmap -q [email protected] mysql:/etc/postfix/mysql_virtual_alias_maps.cf com êxito, mesmo quando pouco antes e logo após o comando recebo "Relay access denied" para o mesmo endereço quando telnet ing no servidor SMTP. postfix reload nem uma reinicialização resolvem o problema; Parece resolver-se em um momento arbitrário, e sem nada óbvio nos logs entre. Em todos os casos, os endereços são @ meudominio.com.br E são pesquisados com sucesso usando postmap -q .
Não vejo falhas em nenhum dos logs (mysql / postfix / syslog). Parece que o Postfix simplesmente ignora a pesquisa em mapas de alias virtuais.
Log de depuração do postfix (caso de falha) :
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: < debug_peer.something.com[64.34.10.20]: rcpt to:[email protected]
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: extract_addr: input: [email protected]
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: smtpd_check_addr: [email protected]
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 = [email protected]
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: [email protected]
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: [email protected] -> [email protected]
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 = [email protected]
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: [email protected]
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: '' -> '[email protected]' -> transp='smtp' host='mydomain.com' rcpt='[email protected]' flags= class=default
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: ctable_locate: install entry key [email protected]
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: extract_addr: in: [email protected], result: [email protected]
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: [email protected]
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 -> [email protected]
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: [email protected]
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: permit_auth_destination: [email protected]
May 28 16:37:39 ext-node01 postfix/smtpd[28115]: ctable_locate: leave existing entry key [email protected]
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 <[email protected]>: Relay access denied; from=<[email protected]> to=<[email protected]> 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 <[email protected]>: Relay access denied
Log de depuração do postfix (caso de sucesso)
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: < debug_peer.something.com[64.34.10.20]: rcpt to:[email protected]
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: extract_addr: input: [email protected]
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: smtpd_check_addr: [email protected]
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 = [email protected]
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: [email protected]
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: [email protected] -> [email protected]
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 = [email protected]
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: [email protected]
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: '' -> '[email protected]' -> transp='error' host='User unknown in virtual alias table' rcpt='[email protected]' flags= class=alias
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: ctable_locate: install entry key [email protected]
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: extract_addr: in: [email protected], result: [email protected]
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: [email protected]
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: permit_auth_destination: [email protected]
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: ctable_locate: leave existing entry key [email protected]
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 [email protected]
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: maps_find: recipient_canonical_maps: [email protected]: 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: [email protected] -> (not found)
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: maps_find: canonical_maps: [email protected]: 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: [email protected] -> (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): [email protected] = [email protected]
May 28 17:14:20 ext-node01 postfix/smtpd[31233]: mail_addr_find: [email protected] -> [email protected]
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
Observe que os timestamps nesses snippets de log têm cerca de 37 minutos de diferença. Durante esse tempo eu estava derramando sobre logs, não fazendo alterações de configuração.
Novamente, imediatamente antes e depois dos dois trechos de log:
postmap -q [email protected] mysql:/etc/postfix/mysql_virtual_alias_maps.cf
[email protected]
O servidor está sob carga baixa. Provavelmente cerca de 2-3 sessões SMTP por min .
Meus próprios testes à parte, vejo esse mesmo comportamento nos logs para destinatários válidos e remetentes válidos em que o acesso de retransmissão será negado algumas vezes (conforme o servidor SMTP upstream repete a entrega) e, de repente, bem-sucedido sem nenhuma intervenção da minha parte .
Eu defino meu status de rejeição como falha temporária (4xx) como uma medida temporária para que outros servidores SMTP tentem novamente com o passar do tempo.
Eu também configurei um cron job para fazer um postfix reload a cada cinco minutos, mas ainda assim observei que isso não ajudou.
Qualquer conselho sobre onde procurar em seguida será bem-vindo. Obrigado!
EDIT: A saída de 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