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.