Score:1

after postfix 3.5.6 upgrade, virtual alias maps to multiple recipients are treated as single names containing a comma

de flag

Just upgraded to debian bullseye postfix 3.5.6 from debian wheezy postfix 2.9.6.

We use virtual alias maps to multiple recipients, like this one:

[email protected] @theidsp-network.inter-realm.net,[email protected]

Thereby, mails sent to [email protected] are forwarded both to [email protected] and to [email protected]. It has been functioning correctly for years.

We previously learned from http://www.postfix.org/virtual.5.html that the order of the multiple recipients is important. "When the result has the form @otherdomain, the result becomes the same user in otherdomain. This works only for the first address in a multi-address lookup result." So we put the wildcard @ recipient first.

After the postfix upgrade, the smtpd seems to be attempting to forward to a single recipient "[email protected],jim"@space-port-pros.com.

Since the user does not exist, this mail is dropping to the catchall.

Here is some output from the mail.log:

Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: connect to subsystem private/proxymap
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: send attr request = lookup
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: send attr table = mysql:/etc/postfix/mysql-virtual_forwardings.cf
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: send attr flags = 540736
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: send attr key = [email protected]
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: private/proxymap socket: wanted attribute: status
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: input attribute name: status
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: input attribute value: 0
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: private/proxymap socket: wanted attribute: value
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: input attribute name: value
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: input attribute value: @theidsp-network.inter-realm.net,[email protected]
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: private/proxymap socket: wanted attribute: (list terminator)
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: input attribute name: (end)
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: dict_proxy_lookup: table=mysql:/etc/postfix/mysql-virtual_forwardings.cf flags=lock|fold_fix|utf8_request
 [email protected] -> status=0 [email protected],[email protected]
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: maps_find: virtual_alias_maps: proxy:mysql:/etc/postfix/mysql-virtual_forwardings.cf(0,lock|fold_fix|utf8
_request): [email protected] = @theidsp-network.inter-realm.net,[email protected]
Apr 14 10:45:17 mail7-057 sslmx/smtpd[8640]: mail_addr_find: [email protected] -> @theidsp-network.inter-realm.net,[email protected]
...
Apr 14 10:45:17 mail7-057 postfix/smtp[8669]: 55E65C895: to=<"[email protected],jim"@space-port-pros.com>, orig_to=<jimays@theids
p.net>, relay=mail7-052.idsp56.net[192.168.56.52]:52025, delay=0.06, delays=0.01/0.02/0.01/0.02, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5F628
A882)

Here are snippets from a log from June showing that the forward previously resulted in two distinct lines with status=sent, one via smtp transport to [email protected] and one via lmtp-g transport to [email protected].

Jun 20 06:30:58 mail7-057 sslmx/smtpd[28956]: connect from mail7-055.idsp56.net[192.168.56.55]
Jun 20 06:30:58 mail7-057 sslmx/smtpd[28956]: Anonymous TLS connection established from mail7-055.idsp56.net[192.168.56.55]: TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)
Jun 20 06:30:58 mail7-057 sslmx/smtpd[28956]: B91A42BE4: client=mail7-055.idsp56.net[192.168.56.55]
Jun 20 06:30:58 mail7-057 cleanup-srs/cleanup[28963]: B91A42BE4: message-id=<[email protected]>
Jun 20 06:30:58 mail7-057 postfix/qmgr[19327]: B91A42BE4: from=<SRS0=Z5tX=LO=connect.match.com=bounces-MA-1-858-ea0868c4-498f-401a-b6f1-c3ce593994a7@trumail7.inter-dimensional-space-port.net>, size=47942, nrcpt=2 (queue active)
Jun 20 06:30:58 mail7-057 sslmx/smtpd[28956]: disconnect from mail7-055.idsp56.net[192.168.56.55]
Jun 20 06:30:58 mail7-057 postfix/smtp[28966]: Anonymous TLS connection established to mail7-052.idsp56.net[192.168.56.52]:52025: TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)
Jun 20 06:30:58 mail7-057 lmtp-g/lmtp[28965]: Trusted TLS connection established to lmtp7-g.inter-dimensional-space-port.net[216.184.19.228]:64007: TLSv1 with cipher AES256-SHA (256/256 bits)
Jun 20 06:30:58 mail7-057 postfix/smtp[28966]: B91A42BE4: to=<[email protected]>, relay=mail7-052.idsp56.net[192.168.56.52]:52025, delay=0.16, delays=0.04/0.02/0.02/0.08, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C66855B94)
Jun 20 06:30:59 mail7-057 sslmx/smtpd[28956]: connect from mail7-055.idsp56.net[192.168.56.55]
Jun 20 06:30:59 mail7-057 sslmx/smtpd[28956]: Anonymous TLS connection established from mail7-055.idsp56.net[192.168.56.55]: TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)
Jun 20 06:30:59 mail7-057 sslmx/smtpd[28956]: 9D1D12CA5: client=mail7-055.idsp56.net[192.168.56.55]
Jun 20 06:30:59 mail7-057 cleanup-srs/cleanup[28963]: 9D1D12CA5: message-id=<[email protected]>
Jun 20 06:30:59 mail7-057 postfix/qmgr[19327]: 9D1D12CA5: from=<SRS0=Z5tX=LO=connect.match.com=bounces-MA-1-858-ea0868c4-498f-401a-b6f1-c3ce593994a7@trumail7.inter-dimensional-space-port.net>, size=50423, nrcpt=1 (queue active)
Jun 20 06:30:59 mail7-057 sslmx/smtpd[28956]: disconnect from mail7-055.idsp56.net[192.168.56.55]
Jun 20 06:31:07 mail7-057 lmtp-g/lmtp[28965]: B91A42BE4: to=<[email protected]>, relay=lmtp7-g.inter-dimensional-space-port.net[216.184.19.228]:64007, delay=8.9, delays=0.04/0.02/0.12/8.7, dsn=2.0.0, status=sent (250 Ok)
Jun 20 06:31:07 mail7-057 postfix/qmgr[19327]: B91A42BE4: removed

The http://www.postfix.org/COMPATIBILITY_README.html did not mention anything specific about a behavior change in virtual alias maps.

mysql-virtual_forwardings.cf is in a standard format created by ISPConfig.

user = ispconfig
password = redacted
dbname = idsp_mail7_062
table = mail_forwarding
select_field = destination
where_field = source
additional_conditions = and active = 'y' and server_id = 81
hosts = 192.168.56.121

The pertinent piece of main.cf which invokes the file is:

virtual_alias_maps = regexp:/etc/postfix/regexp-virtual_forwardings__admin.cf, proxy:mysql:/etc/postfix/mysql-virtual_forwardings.cf, proxy:mysql:/etc
/postfix/mysql-virtual_email2email.cf

The virtual_forwardings table looks like:

MariaDB [idsp_mail7_057]> select * from mail_forwarding where source='[email protected]';
+---------------+------------+-------------+---------------+----------------+----------------+-----------+--------------------+---------------------------------------------+---------+--------+
| forwarding_id | sys_userid | sys_groupid | sys_perm_user | sys_perm_group | sys_perm_other | server_id | source             | destination                                              | type    | active |
+---------------+------------+-------------+---------------+----------------+----------------+-----------+--------------------+---------------------------------------------+---------+--------+
|           201 |          2 |           2 | riud          | riud           |                |        69 | [email protected] | @theidsp-network.inter-realm.net,[email protected] | forward | y      |
+---------------+------------+-------------+---------------+----------------+----------------+-----------+--------------------+---------------------------------------------+---------+--------+
1 row in set (0.001 sec)

Increased logging to smtpd -v -v and this shows in the log:

dict_proxy_lookup: table=mysql:/etc/postfix/mysql-virtual_forwardings.cf flags=lock|fold_fix|utf8_request
 [email protected] -> status=0 [email protected],[email protected]
Apr 20 16:44:37 mail7-057 sslmx/smtpd[9561]: maps_find: virtual_alias_maps: proxy:mysql:/etc/postfix/mysql-virtual_forwardings.cf(0,lock|fold_fix|utf8
_request): [email protected] = @theidsp-network.inter-realm.net,[email protected]
Apr 20 16:44:37 mail7-057 sslmx/smtpd[9561]: mail_addr_find: [email protected] -> @theidsp-network.inter-realm.net,[email protected]

so it appears the lookup is happening correctly, and then still only one dispatch happens instead of two.

Jim At Your Service avatar
de flag
Now posted this issue to upstream, see https://bugs.launchpad.net/postfix/+bug/2010895
Jim At Your Service avatar
de flag
Hi @anx. Wondering if you are suggesting there is a bug in postfix smtpd. We have many records which use this ATotherdomain,somewhereATsomespecific.com format, to forward both to ATotherdomain plus to some specific email address. Wondering if you are seeing a specific workaround to that.
Jim At Your Service avatar
de flag
@anx. Confirmed that things work correctly if I replace the entry with jimaysATtheidsp-network.inter-realm.net,jimATspace-port-pros.com, so indeed I am considering your idea of changing all our entries as a workaround. But hmm, what actually happened here?
anx avatar
fr flag
anx
Though I have not digged into specifics, I believe even just any perceived or real documentation *ambiguity* about how unquoted address lists are treated are worthy of being considered a bug. Please do report this upstream, you may be able to create a shorter reproducer using the (sqlite, not mysql) steps I outlined below.
Score:0
fr flag
anx

It ran into it when and only when using the "@otherdomain" form, so it could be worked around:

  1. by migrating from the deprecated table/select_field/.. form to specifying query in your mysql-*.cf file and mimic in SQL what postfix no longer does, or
  2. by permanently changing your table to expand those aliases to the full user@domain form.

Both workaround would involve a query containing something like CASE WHEN destination LIKE "@%" THEN SUBSTR(source,1,INSTR(source,"@"))||destination ELSE destination END to let SQL just concatenate the source mailbox if the lookup starts with @. Carefully consider what should happen to address extensions like user+extensions@onedomain, if you are using those!

When searching for possible reasons for the changed behaviour I came across some rfc822 quote/unquote rework that may be relevant, CHANGELOG mentions:

correctly propagate an address extension

from "aa bb+ext"@example.com to "cc dd+ext"@other.example

Though one could equally argue that the whole feature that only works when executed on the first entry in an address list thing is a bug in the first place. Such post-processing step should be applied to all elements of the result set without any possible ambiguity between mailbox/extension/delimiter.


I was able to replicate that list/mailbox type confusion in Postfix 3.4.13 (as distributed by Ubuntu) using either query and table/select_field/.., with or without proxymap, and with either multi-row result or single comma-separated result. You may be able to work the following almost-working steps into a working reproducer to report upstream. Obviously only run these steps on a test box.

exit 1  # DATA LOSS! ONLY RUN ON VIRTUAL MACHINE FOR TESTING!
postconf virtual_transport=error
postconf virtual_alias_maps=proxy:sqlite:/etc/postfix/repro.cf
postconf virtual_alias_domains=e.invalid
postconf debug_peer_list=[::1]
sqlite3 /etc/postfix/repro.sqlite3 <<'EOF'
CREATE TABLE repro(s text, d text);
INSERT INTO repro(s,d) VALUES ("[email protected]", "@e.invalid,[email protected]");
INSERT INTO repro(s,d) VALUES ("[email protected]", "[email protected],[email protected]");
EOF
cat >/etc/postfix/repro.cf <<'EOF'
dbpath=/etc/postfix/repro.sqlite3
query=SELECT d FROM repro WHERE s='%s'
EOF
# send test mail (smtp not setuid, because smtp produces nicer logs)
printf %b 'import smtplib;\nsmtplib.SMTP("::1").sendmail("","[email protected]", "")' | python3
printf %b 'import smtplib;\nsmtplib.SMTP("::1").sendmail("","[email protected]", "")' | python3
# check logs
Jim At Your Service avatar
de flag
Your answer is thorough and useful and has been absorbed with gratitude, will get to upstream in due course with a reference to here. Your workaround is most useful personally to me and our team right now, as it shows a path forward to get the mail flowing again, just change ATdomain to be a full userATdomain. We can run an SQL update to do that all at once. Then all we have to do is go through our catchall mailbox and redistribute all that mail for the last couple weeks.... Thanks. This is my first post and wondering how to mark solved.
Jim At Your Service avatar
de flag
Our mail server is now fixed thanks to @anx and to lib_mysqludf_preg: `update mail_forwarding set destination=concat(regexp_replace(source,'@.*$',''),destination) where destination like '@%';`
Jim At Your Service avatar
de flag
...tried to click the checkmark, need 15 reputation points... your answer certainly did solve our issue thanks
mangohost

Post an answer

Most people don’t grasp that asking a lot of questions unlocks learning and improves interpersonal bonding. In Alison’s studies, for example, though people could accurately recall how many questions had been asked in their conversations, they didn’t intuit the link between questions and liking. Across four studies, in which participants were engaged in conversations themselves or read transcripts of others’ conversations, people tended not to realize that question asking would influence—or had influenced—the level of amity between the conversationalists.