Postfix sometime ignoring transport map

Maxime Gaudreault

unread,

Jun 12, 2012, 10:26:02 AM6/12/12

to

Hi

I posted this message on Baruwa and Postfix mailing list since I don't know where the problem is

Postfix is set to use a relayhost and a mysql based transport map for some domain that are not hosted on the same server

/etc/postfix/main.cf:

transport_maps = mysql:/etc/postfix/mysql-transports.cf

relayhost = 10.0.1.11

/etc/postfix/mysql-transport.cf:

#mysql-transports

user = baruwa

password = ******

dbname = baruwa

query = select concat('smtp:[', mail_hosts.address, ']', ':', port) 'transport' from mail_hosts, user_addresses where user_addresses.address = '%s' AND user_addresses.id = mail_hosts.useraddress_id;

hosts = 127.0.0.1

I have two domains in the transport map. Postfix is "sometime" ignoring the transport map for ONE domain and send emails through the default relayhost. Most of the emails received for this domain go through the right server. I'd say 80% are OK.

Look at the mail.log entry for a mail that is sent through the wrong server.

Jun 11 16:56:14 mx01 postfix/smtpd[855]: connect from rfmnotes.fossnational.com[66.212.175.2]

Jun 11 16:56:15 mx01 postfix/smtpd[855]: NOQUEUE: reject: RCPT from rfmnotes.fossnational.com[66.212.175.2]: 550 5.1.1 < recipient @domain.ca>: Recipient address rejected: undeliverable address: host 10.0.1.11[10.0.1.11] said: 550 not local host domain.ca, not a gateway (in reply to RCPT TO command); from=<sen...@anotherdomain.com> to=<reci...@domain.ca> proto=ESMTP helo=<rfmnotes.fossnational.com> ***IT SEND THROUGH THE WRONG SERVER (10.0.1.11) ***

Jun 11 16:56:15 mx01 postfix/cleanup[662]: 2093E56006D: message-id=<2012061120561...@mx01.reference.qc.ca>

Jun 11 16:56:15 mx01 postfix/qmgr[28563]: 2093E56006D: from=<double...@reference.qc.ca>, size=246, nrcpt=1 (queue active)

Jun 11 16:56:15 mx01 postfix/smtp[800]: 2093E56006D: to=<reci...@domain.ca>, relay=192.168.100.9[192.168.100.9]:25, delay=0.01, delays=0/0/0/0, dsn=2.1.5, status=deliverable (250 2.1.5 Recipient <reci...@domain.ca> ok (local)) ***IT CHECK RECIPIENT VALIDITY WITH THE RIGHT SERVER (192.168.100.9) (reject_unverified_recipient in main.cf) ***

Jun 11 16:56:15 mx01 postfix/qmgr[28563]: 2093E56006D: removed

Jun 11 16:56:15 mx01 postfix/smtpd[855]: disconnect from rfmnotes.fossnational.com[66.212.175.2]

I tried to set a text transport map and postmap'd it instead of mysql and I get the same issue.

Any help is greatly appreciated

Max

Maxime Gaudreault

unread,

Jun 12, 2012, 10:40:58 AM6/12/12

to

Wietse Venema

unread,

Jun 12, 2012, 10:45:42 AM6/12/12

to

Maxime Gaudreault:

> I tried to set a text transport map and postmap'd it instead of mysql
> and I get the same issue.

Please show "postconf -n" output with the text transport maop, and
logging for a "good" delivery and for a "bad" delivery. Please
indicate which delivery is "good" and which is "bad".

Wietse

Maxime Gaudreault

unread,

Jun 12, 2012, 11:02:40 AM6/12/12

to

root@mx01:~# postconf -n
address_verify_map = btree:/var/lib/postfix/verify
alias_database = hash:/etc/aliases
alias_maps = hash:/etc/aliases
append_dot_mydomain = no
biff = no
config_directory = /etc/postfix
disable_vrfy_command = yes
hash_queue_names = ""
header_checks = regexp:/etc/postfix/header_checks
inet_interfaces = all
inet_protocols = ipv4
local_recipient_maps =
local_transport = error:No local mail delivery
mailbox_size_limit = 0
message_size_limit = 10485760
mydestination =
myhostname = mx01.reference.qc.ca
mynetworks = 127.0.0.0/8, 10.0.1.0/24
myorigin = reference.qc.ca
readme_directory = no
recipient_delimiter = +
relay_domains = mysql:/etc/postfix/mysql-relay_domains.cf
relay_recipient_maps = mysql:/etc/postfix/mysql-relay_recipients.cf
relayhost = 10.0.1.11
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache
smtpd_banner = $myhostname ESMTP $mail_name
smtpd_client_restrictions = permit_sasl_authenticated,
permit_mynetworks, permit
smtpd_data_restrictions = permit_mynetworks,
permit_sasl_authenticated, reject_unauth_pipelining
smtpd_delay_reject = yes
smtpd_helo_required = yes
smtpd_helo_restrictions = permit_sasl_authenticated,
permit_mynetworks, permit
smtpd_recipient_limit = 100
smtpd_recipient_restrictions = permit_mynetworks,
permit_sasl_authenticated, reject_unknown_recipient_domain,
reject_unauth_destination, reject_unverified_recipient,
whitelist_policy, rbl_policy, spf_policy, permit
smtpd_restriction_classes = spf_policy, rbl_policy,
whitelist_policy
smtpd_sender_restrictions = permit_mynetworks,
permit_sasl_authenticated, reject_non_fqdn_sender,
reject_unknown_sender_domain, permit
smtpd_tls_cert_file = /etc/ssl/certs/ssl-cert-snakeoil.pem
smtpd_tls_key_file = /etc/ssl/private/ssl-cert-snakeoil.key
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
smtpd_use_tls = yes
strict_rfc821_envelopes = no
transport_maps = mysql:/etc/postfix/mysql-transports.cf
unverified_recipient_reject_code = 550
virtual_alias_maps = hash:/etc/postfix/virtual

Good mail:
Jun 11 17:06:56 mx01 postfix/smtpd[1004]: connect from
mail-yw0-f52.google.com[209.85.213.52]
Jun 11 17:06:57 mx01 postfix/policy-spf[1189]: : SPF pass (Mechanism
'ip4:209.85.128.0/17' matched): Envelope-from: scap...@gmail.com
Jun 11 17:06:57 mx01 postfix/policy-spf[1189]: handler
sender_policy_framework: is decisive.
Jun 11 17:06:57 mx01 postfix/policy-spf[1189]: : Policy action=PREPEND
Received-SPF: pass (gmail.com ... _spf.google.com: 209.85.213.52 is
authorized to use 'scap...@gmail.com' in 'mfrom' identity (mechanism
'ip4:209.85.128.0/17' matched)) receiver=mx01.reference.qc.ca;
identity=mailfrom; envelope-from="scap...@gmail.com";
helo=mail-yw0-f52.google.com; client-ip=209.85.213.52
Jun 11 17:06:57 mx01 postfix/smtpd[1004]: 8334656006D:
client=mail-yw0-f52.google.com[209.85.213.52]
Jun 11 17:06:57 mx01 postfix/cleanup[1005]: 8334656006D: hold: header
Received: from mail-yw0-f52.google.com (mail-yw0-f52.google.com
[209.85.213.52])??by mx01.reference.qc.ca (Postfix) with ESMTPS id
8334656006D??for <reci...@domain.ca>; Mon, 11 Jun 2012 17:06 from
mail-yw0-f52.google.com[209.85.213.52]; from=<scap...@gmail.com> to=<
reci...@domain.ca > proto=ESMTP helo=<mail-yw0-f52.google.com>
Jun 11 17:06:57 mx01 postfix/cleanup[1005]: 8334656006D:
message-id=<CAPCv32TaWXKXgKa4cqbA7TdMXR02A2rvMARuoJjHC10ifkCP=w...@mail.gma
il.com>
Jun 11 17:06:57 mx01 MailScanner[24341]: New Batch: Scanning 1 messages,
3749 bytes
Jun 11 17:06:58 mx01 MailScanner[24341]: Virus and Content Scanning:
Starting
Jun 11 17:06:59 mx01 MailScanner[24341]: Baruwa: spam score setting
refresh time reached
Jun 11 17:06:59 mx01 MailScanner[24341]: Baruwa: Populating spam score
settings
Jun 11 17:06:59 mx01 MailScanner[24341]: Baruwa: no spam score settings
found using defaults
Jun 11 17:06:59 mx01 MailScanner[24341]: Baruwa: high spam score setting
refresh time reached
Jun 11 17:06:59 mx01 MailScanner[24341]: Baruwa: Populating high spam
score settings
Jun 11 17:06:59 mx01 MailScanner[24341]: Baruwa: no high spam score
settings found using defaults
Jun 11 17:07:00 mx01 MailScanner[24341]: Requeue: 8334656006D.A773F to
61C50561039
Jun 11 17:07:00 mx01 MailScanner[24341]: Uninfected: Delivered 1
messages
Jun 11 17:07:00 mx01 postfix/qmgr[28563]: 61C50561039:
from=<scap...@gmail.com>, size=3015, nrcpt=1 (queue active)
Jun 11 17:07:00 mx01 MailScanner[24341]: Deleted 1 messages from
processing-database
Jun 11 17:07:00 mx01 MailScanner[24341]: Baruwa: Logging message
8334656006D.A773F to SQL
Jun 11 17:07:00 mx01 postfix/smtp[2003]: 61C50561039: to=<
reci...@domain.ca>, relay=192.168.100.9[192.168.100.9]:25, delay=3.4,
delays=3.4/0/0/0, dsn=2.0.0, status=sent (250 2.0.0 4fd65e47-000321f5
Message accepted for delivery)
Jun 11 17:07:00 mx01 MailScanner[28694]: Baruwa: 8334656006D.A773F:
Logged to SQL
Jun 11 17:07:00 mx01 postfix/qmgr[28563]: 61C50561039: removed

Bad mail:

Jun 11 16:56:14 mx01 postfix/smtpd[855]: connect from
rfmnotes.fossnational.com[66.212.175.2]
Jun 11 16:56:15 mx01 postfix/smtpd[855]: NOQUEUE: reject: RCPT from
rfmnotes.fossnational.com[66.212.175.2]: 550 5.1.1 < recipient
@domain.ca>: Recipient address rejected: undeliverable address: host
10.0.1.11[10.0.1.11] said: 550 not local host domain.ca, not a gateway
(in reply to RCPT TO command); from=<sen...@anotherdomain.com>
to=<reci...@domain.ca> proto=ESMTP helo=<rfmnotes.fossnational.com>

Jun 11 16:56:15 mx01 postfix/cleanup[662]: 2093E56006D:
message-id=<2012061120561...@mx01.reference.qc.ca>
Jun 11 16:56:15 mx01 postfix/qmgr[28563]: 2093E56006D:
from=<double...@reference.qc.ca>, size=246, nrcpt=1 (queue active)
Jun 11 16:56:15 mx01 postfix/smtp[800]: 2093E56006D:
to=<reci...@domain.ca>, relay=192.168.100.9[192.168.100.9]:25,
delay=0.01, delays=0/0/0/0, dsn=2.1.5, status=deliverable (250 2.1.5
Recipient <reci...@domain.ca> ok (local))

Jun 11 16:56:15 mx01 postfix/qmgr[28563]: 2093E56006D: removed
Jun 11 16:56:15 mx01 postfix/smtpd[855]: disconnect from
rfmnotes.fossnational.com[66.212.175.2]

Wietse Venema

unread,

Jun 12, 2012, 11:43:07 AM6/12/12

to

Maxime Gaudreault:

> Jun 11 17:07:00 mx01 postfix/smtp[2003]: 61C50561039: to=<
> reci...@domain.ca>, relay=192.168.100.9[192.168.100.9]:25, delay=3.4,
> delays=3.4/0/0/0, dsn=2.0.0, status=sent (250 2.0.0 4fd65e47-000321f5
> Message accepted for delivery)

This appears to be a real email message.

> from=<double...@reference.qc.ca>, size=246, nrcpt=1 (queue active)
> Jun 11 16:56:15 mx01 postfix/smtp[800]: 2093E56006D:
> to=<reci...@domain.ca>, relay=192.168.100.9[192.168.100.9]:25,
> delay=0.01, delays=0/0/0/0, dsn=2.1.5, status=deliverable (250 2.1.5
> Recipient <reci...@domain.ca> ok (local))

This appears to be an "address verification" message.

Both messages are routed via relay=192.168.100.9[192.168.100.9]:25.

Why is one delivery "good", and one delivery "bad"?

Wietse

Maxime Gaudreault

unread,

Jun 12, 2012, 11:46:20 AM6/12/12

to

Bad delivery tries to send through 10.0.1.11 but verify the recipient
with 192.168.100.9.
10.0.1.11 can't accept mail for this domain

The good delivery send through 192.168.100.9

-----Original Message-----
From: owner-pos...@postfix.org
[mailto:owner-pos...@postfix.org] On Behalf Of Wietse Venema
Sent: June-12-12 11:43 AM
To: Postfix users
Subject: Re: Postfix sometime ignoring transport map

Wietse Venema

unread,

Jun 12, 2012, 11:55:12 AM6/12/12

to

Maxime Gaudreault:
> Jun 11 17:07:00 mx01 postfix/smtp[2003]: 61C50561039: to=<
> reci...@domain.ca>, relay=192.168.100.9[192.168.100.9]:25,
> delay=3.4, delays=3.4/0/0/0, dsn=2.0.0, status=sent (250 2.0.0
> 4fd65e47-000321f5 Message accepted for delivery)

Wietse:

> This appears to be a real email message.

Maxime Gaudreault:

> from=<double...@reference.qc.ca>, size=246, nrcpt=1 (queue active)
> Jun 11 16:56:15 mx01 postfix/smtp[800]: 2093E56006D:
> to=<reci...@domain.ca>, relay=192.168.100.9[192.168.100.9]:25,
> delay=0.01, delays=0/0/0/0, dsn=2.1.5, status=deliverable (250 2.1.5
> Recipient <reci...@domain.ca> ok (local))

Wietse:

> This appears to be an "address verification" message.
>
> Both messages are routed via relay=192.168.100.9[192.168.100.9]:25.
> Why is one delivery "good", and one delivery "bad"?

Maxime Gaudreault:

> Bad delivery tries to send through 10.0.1.11 but verify the recipient
> with 192.168.100.9.
> 10.0.1.11 can't accept mail for this domain

The logfile evidence shows that BOTH ARE ROUTED VIA 192.168.100.9.

The REJECT message involving 10.0.1.11 comes from the address
verification CACHE. This CACHE uses historical information.
Apparently, you made some configuration error that has been
fixed in the meantime.

Wietse

Maxime Gaudreault

unread,

Jun 12, 2012, 5:08:44 PM6/12/12

to

Good answer ;)

But, I just did some test, and more than 24 hours after the I first
noticed the issue, it still relay emails through the default relayhost:

Jun 12 16:43:03 mx01 postfix/smtpd[30843]: connect from
mailrelay7.megamailservers.com[209.235.143.13]
Jun 12 16:43:13 mx01 postfix/smtpd[30843]: NOQUEUE: reject: RCPT from
mailrelay7.megamailservers.com[209.235.143.13]: 550 5.1.1
<reci...@domain.ca>: Recipient address rejected: undeliverable

address: host 10.0.1.11[10.0.1.11] said: 550 not local host domain.ca,
not a gateway (in reply to RCPT TO command);

from=<promoapa...@megawebservers.com> to=< reci...@domain.ca >
proto=ESMTP helo=<mailrelay7.megamailservers.com>
Jun 12 16:43:13 mx01 postfix/cleanup[30845]: B5281560068:
message-id=<2012061220431...@mx01.reference.qc.ca>
Jun 12 16:43:13 mx01 postfix/qmgr[7521]: B5281560068:

from=<double...@reference.qc.ca>, size=246, nrcpt=1 (queue active)

Jun 12 16:43:13 mx01 postfix/smtp[30902]: B5281560068: to=<

reci...@domain.ca >, relay=192.168.100.9[192.168.100.9]:25,
delay=0.01, delays=0/0/0/0, dsn=2.1.5, status=deliverable (250 2.1.5
Recipient < reci...@domain.ca > ok (local))

Jun 12 16:43:13 mx01 postfix/qmgr[7521]: B5281560068: removed

And it's not all emails that goes through the wrong server..

-----Original Message-----
From: wie...@porcupine.org [mailto:wie...@porcupine.org]
Sent: June-12-12 2:34 PM
To: Maxime Gaudreault
Cc: wie...@porcupine.org
Subject: Re: Postfix sometime ignoring transport map

Maxime Gaudreault:

> How do you know it came from the cache ?

because I wrote the code that produced that message in your logfile.

> How do I reset this cache ?

This is not needed. The bad entry expires after four hours.

Wietse
> Max

>
>
> -----Original Message-----
> From: wie...@porcupine.org [mailto:wie...@porcupine.org]
> Sent: June-12-12 11:55 AM
> To: Maxime Gaudreault
> Cc: Postfix users
> Subject: Re: Postfix sometime ignoring transport map
>

Wietse Venema

unread,

Jun 12, 2012, 8:50:59 PM6/12/12

to

Maxime Gaudreault:

> Good answer ;)
>
> But, I just did some test, and more than 24 hours after the I first
> noticed the issue, it still relay emails through the default relayhost:

No, it doesn't.

> Jun 12 16:43:03 mx01 postfix/smtpd[30843]: connect from
> mailrelay7.megamailservers.com[209.235.143.13]
> Jun 12 16:43:13 mx01 postfix/smtpd[30843]: NOQUEUE: reject: RCPT from
> mailrelay7.megamailservers.com[209.235.143.13]: 550 5.1.1
> <reci...@domain.ca>: Recipient address rejected: undeliverable
> address: host 10.0.1.11[10.0.1.11] said: 550 not local host domain.ca,
> not a gateway (in reply to RCPT TO command);

This is an OLD result from your address verification cache.

Apparently, you have a corrupted cache file, or you have messed
with the address_verify expiration times.

Remove the cache file and do "postfix reload".

> Jun 12 16:43:13 mx01 postfix/cleanup[30845]: B5281560068:
> message-id=<2012061220431...@mx01.reference.qc.ca>
> Jun 12 16:43:13 mx01 postfix/qmgr[7521]: B5281560068:
> from=<double...@reference.qc.ca>, size=246, nrcpt=1 (queue active)
> Jun 12 16:43:13 mx01 postfix/smtp[30902]: B5281560068: to=<
> reci...@domain.ca >, relay=192.168.100.9[192.168.100.9]:25,
> delay=0.01, delays=0/0/0/0, dsn=2.1.5, status=deliverable (250 2.1.5
> Recipient < reci...@domain.ca > ok (local))

This is a NEW ADDRESS VERIFICATION PROBE that is sent to the right
relay host.

Wietse

Maxime Gaudreault

unread,

Jun 12, 2012, 9:58:49 PM6/12/12

to

I deleted /var/lib/postfix/verify.db and reloaded postfix.. It seems ok
now

Thanks a lot for that !

I noticed a lot of these warning in mail.log:
Jun 12 21:48:25 mx01 postfix/verify[12799]: close database
/var/lib/postfix/verify.db: No such file or directory (possible Berkeley
DB bug)

Do you think it is related ? I googled the warning and it seems like a
non-issue..

-----Original Message-----
From: owner-pos...@postfix.org
[mailto:owner-pos...@postfix.org] On Behalf Of Wietse Venema