On 10/15/20 10:45 PM, Andrey Lelikov wrote:
On 10/14/20 7:21 PM, Dominic Raferd wrote:
The X-Original-To header is normally added by the postfix delivery
agent (local, smtp, virtual etc). Are you sure it isn't being stripped
by something bespoke in your system?
Ok, I should have made myself more clear. Postfix obviously can add
X-Original-To header and this header can be propagated to the delivery
agent (dovecot). But. When it is set up the "regular" way, not with
amavisd relaying the (filtered) mail.
With amavisd this logic is broken. Here is what happens:
A single mailbox [email protected] exist for the domain domain.xxx . I
send the message to an address [email protected] .
Expected result - message is delivered to [email protected] with
[email protected] .
Observed result - either on X-Original-To header or
[email protected]
The lifetime of message:
1. Message is received by postfix smtpd process. cleanup receives
message and sends it to amavisd.
Note: the postfix setting enable_original_recipient is ignored at this
point. The X-Original-To is not added to the message being sent to
amavisd. Don't know why, could be part of content_filter logic
Oct 14 21:33:41 mail postfix/submission/smtpd[21036]: connect from
unknown[5.181.209.236]
Oct 14 21:33:41 mail postfix/submission/smtpd[21036]: Anonymous TLS
connection established from unknown[5.181.209.236]: TLSv1.3 with
cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X255
19 server-signature RSA-PSS (2048 bits) server-digest SHA256
Oct 14 21:33:41 mail postfix/submission/smtpd[21036]: 4CBLdx20P9z3xGP:
client=unknown[5.181.209.236], sasl_method=PLAIN,
[email protected]
Oct 14 21:33:41 mail postfix/cleanup[20982]: 4CBLdx20P9z3xGP:
message-id=<[email protected]>
Oct 14 21:33:41 mail postfix/qmgr[5574]: 4CBLdx20P9z3xGP:
from=<[email protected]>, size=587, nrcpt=1 (queue active)
Oct 14 21:33:41 mail postfix/submission/smtpd[21036]: disconnect from
unknown[5.181.209.236] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=1
quit=1 commands=8
2. amavisd gets the message. Te recipient is already [email protected]
with original recipient passed as ORCPT=rfc822;[email protected]\r\n
Oct 14 21:33:41 mail amavis[21032]: Net::Server: 2020/10/14-21:33:41
CONNECT TCP Peer: "[127.0.0.1]:51998" Local: "[127.0.0.1]:10026"
Oct 14 21:33:41 mail amavis[21032]: (21032-01) SMTP> 220 [127.0.0.1]
ESMTP amavisd-new service ready
Oct 14 21:33:41 mail amavis[21032]: (21032-01) SMTP< EHLO
mail.lelik.us\r\n
Oct 14 21:33:41 mail amavis[21032]: (21032-01) ESMTP> 250 2.1.0 Sender
<[email protected]> OK
Oct 14 21:33:41 mail amavis[21032]: (21032-01) ESMTP< RCPT
TO:<[email protected]> ORCPT=rfc822;[email protected]\r\n
Oct 14 21:33:41 mail amavis[21032]: (21032-01) ESMTP [127.0.0.1]:10026
/var/lib/amavis/tmp/amavis-20201014T213341-21032-JCBsztrH:
<[email protected]> -> <[email protected]> Received: from mail.lelik.us
([127.0.0.1]) by mail.lelik.us (mail.lelik.us [127.0.0.1])
(amavisd-new, port 10026) with ESMTP for <[email protected]>; Wed, 14
Oct 2020 21:33:41 +0300 (MSK)
Oct 14 21:33:41 mail amavis[21032]: (21032-01) ESMTP> 354 End data
with <CR><LF>.<CR><LF>
3. amavisd does a lot of magic on message
Oct 14 21:33:41 mail amavis[21032]: (21032-01) sql: preparing and
executing (11 args): INSERT INTO msgs (partition_tag, mail_id,
secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size,
host) VALUES (?,?,?,?,?,?,?,?,?,?,?)
Oct 14 21:33:41 mail amavis[21032]: (21032-01) sql commit
Oct 14 21:33:41 mail amavis[21032]: (21032-01) Checking: 9PZLryXflv1x
ORIGINATING [5.181.209.236] <[email protected]> -> <[email protected]>
Oct 14 21:33:41 mail amavis[21032]: (21032-01) 2822.From:
<[email protected]>
Oct 14 21:33:41 mail amavis[21032]: (21032-01) headers CLUSTERING: NEW
CLUSTER <[email protected]>: score=-1, tag=0, tag2=0, local=1, bl=, s=,
mangle=
Oct 14 21:33:41 mail amavis[21032]: (21032-01) header encoded
(all-ASCII): X-Virus-Scanned: Debian amavisd-new at mail.lelik.us
Oct 14 21:33:41 mail amavis[21032]: (21032-01) header:
X-Virus-Scanned: Debian amavisd-new at mail.lelik.us\n
Oct 14 21:33:41 mail amavis[21032]: (21032-01) header encoded
(all-ASCII): Received: from mail.lelik.us ([127.0.0.1])\n by
mail.lelik.us (mail.lelik.us [127.0.0.1]) (amavisd-new, port 10026)\n
with ESMTP\n id 9PZLryXflv1x\n for <[email protected]>;\n Wed, 14 Oct
2020 21:33:41 +0300 (MSK)
Oct 14 21:33:41 mail amavis[21032]: (21032-01) header: Received: from
mail.lelik.us ([127.0.0.1])\n\tby mail.lelik.us (mail.lelik.us
[127.0.0.1]) (amavisd-new, port 10026)\n\twith ESMTP id 9PZLryXflv1x
for <[email protected]>;\n\tWed, 14 Oct 2020 21:33:41 +0300 (MSK)\n
Oct 14 21:33:41 mail amavis[21032]: (21032-01) smtp session: setting
up a new session
Oct 14 21:33:41 mail amavis[21032]: (21032-01) new socket using
IO::Socket::IP to [127.0.0.1]:10025, timeout 35
4. amavisd re-submits the message to postfix, to another smtpd process
on port 10025 (filtered pickup) , to the same recipient and with the
same ORCPT
Oct 14 21:33:41 mail postfix/10025/smtpd[20989]: connect from
localhost[127.0.0.1]
Oct 14 21:33:41 mail amavis[21032]: (21032-01) connected to
[127.0.0.1]:10025 successfully
Oct 14 21:33:41 mail amavis[21032]: (21032-01) rw_loop sent 102> MAIL
FROM:<[email protected]> BODY=7BIT\r\nRCPT TO:<[email protected]>
ORCPT=rfc822;[email protected]\r\nDATA\r\n
Oct 14 21:33:41 mail postfix/qmgr[5574]: 4CBLdx69N3z40j7:
from=<[email protected]>, size=1812, nrcpt=1 (queue active)
Oct 14 21:33:41 mail postfix/10025/smtpd[20989]: disconnect from
localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 14 21:33:41 mail amavis[21032]: (21032-01) ESMTP> 250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4CBLdx69N3z40j7
Oct 14 21:33:41 mail amavis[21032]: (21032-01) switch_to_client_time
480 s, smtp response sent
Oct 14 21:33:41 mail amavis[21032]: (21032-01) rmdir_recursively:
/var/lib/amavis/tmp/amavis-20201014T213341-21032-JCBsztrH/parts, excl=1
Oct 14 21:33:41 mail postfix/amavis/smtp[20987]: 4CBLdx20P9z3xGP:
to=<[email protected]>, orig_to=<[email protected]>,
relay=127.0.0.1[127.0.0.1]:10026, delay=0.68, delays=0.07/0/0.04/0.58,
dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025):
250 2.0.0 Ok: queued as 4CBLdx69N3z40j7)
Oct 14 21:33:41 mail postfix/qmgr[5574]: 4CBLdx20P9z3xGP: removed
This is where original envelope to information is lost forever.
amavisd re-sends it as ORCPT=rfc822;[email protected] header, but
postfix smtpd just ignores it. I do not know why (checked obvious
things like DSN not being disabled). The cleanup and pipe get only
regular "to" address.
5. postfix queues and submits it to dovecot. original_from is lost at
this point.
Oct 14 21:33:41 mail postfix/qmgr[5574]: 4CBLdx69N3z40j7:
from=<[email protected]>, size=1812, nrcpt=1 (queue active)
Oct 14 21:33:41 mail postfix/10025/smtpd[20989]: disconnect from
localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 14 21:33:41 mail amavis[21032]: (21032-01) ESMTP> 250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4CBLdx69N3z40j7
Oct 14 21:33:41 mail amavis[21032]: (21032-01) switch_to_client_time
480 s, smtp response sent
Oct 14 21:33:41 mail amavis[21032]: (21032-01) rmdir_recursively:
/var/lib/amavis/tmp/amavis-20201014T213341-21032-JCBsztrH/parts, excl=1
Oct 14 21:33:41 mail , delay=0.68, delays=0.07/0/0.04/0.58, dsn=2.0.0,
status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok:
queued as 4CBLdx69N3z40j7)
Oct 14 21:33:41 mail postfix/qmgr[5574]: 4CBLdx20P9z3xGP: removed
Oct 14 21:33:42 mail postfix/pipe[20990]: 4CBLdx69N3z40j7:
to=<[email protected]>, relay=dovecot, delay=0.15, delays=0.01/0/0/0.14,
dsn=2.0.0, status=sent (delivered via dovecot service)
Oct 14 21:33:42 mail postfix/qmgr[5574]: 4CBLdx69N3z40j7: removed
No way I'm going to read/hack postfix sources. I still see adding a
header inside amavisd as the easiest fix. So, I'll repeat my question:
I'm using a debian system, and my understanding is that it is possible
to add a hook to amavis/conf.d/something that would modify actions
inside add_forwarding_header_edits_common without hacking original
script in /usr/sbin ?
Thanks!
