prerving envelope address via X-Original-to

[amavis at lelik.org]

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 user at domain.xxx exist for the domain domain.xxx . I 
> send the message to an address catchall at domain.xxx .
>
> Expected result - message is delivered to user at domain.xxx with 
> X-Original-To=catchall at domain.xxx .
>
> Observed result - either on X-Original-To header or 
> X-Original-To=user at domain.xxx
>
>
> 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, 
> sasl_username=user at domain.xxx
> Oct 14 21:33:41 mail postfix/cleanup[20982]: 4CBLdx20P9z3xGP: 
> message-id=<506c077e-5bb6-130c-244a-9325365f8e09 at lelik.org>
> Oct 14 21:33:41 mail postfix/qmgr[5574]: 4CBLdx20P9z3xGP: 
> from=<user at domain.xxx>, 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 user at domain.xxx 
> with original recipient passed as ORCPT=rfc822;catchall at domain.xxx\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 
> <user at domain.xxx> OK
> Oct 14 21:33:41 mail amavis[21032]: (21032-01) ESMTP< RCPT 
> TO:<user at domain.xxx> ORCPT=rfc822;catchall at domain.xxx\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: 
> <user at domain.xxx> -> <user at domain.xxx> 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 <user at domain.xxx>; 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] <user at domain.xxx> -> <user at domain.xxx>
> Oct 14 21:33:41 mail amavis[21032]: (21032-01) 2822.From: 
> <user at domain.xxx>
> Oct 14 21:33:41 mail amavis[21032]: (21032-01) headers CLUSTERING: NEW 
> CLUSTER <user at domain.xxx>: 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 <user at domain.xxx>;\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 <user at domain.xxx>;\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:<user at domain.xxx> BODY=7BIT\r\nRCPT TO:<user at domain.xxx> 
> ORCPT=rfc822;catchall at domain.xxx\r\nDATA\r\n
> Oct 14 21:33:41 mail postfix/qmgr[5574]: 4CBLdx69N3z40j7: 
> from=<user at domain.xxx>, 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=<user at domain.xxx>, orig_to=<catchall at domain.xxx>, 
> 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;catchall at domain.xxx 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=<user at domain.xxx>, 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=<user at domain.xxx>, 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!
>
>