Wrong received line - Githubissues

florianstieglbauer commented 9 months ago

Hello,

I have identified an issue that I unfortunately cannot resolve on my own. I hope to find a solution here.

The Amavisd filter is generating a faulty Received line, and I am unsure why this is happening. This results in display issues in Outlook. Interestingly, this behavior occurs only with emails from some senders, while other email providers such as Google, Yahoo, T-Online, etc., have no problems with the correct generation of the Received line.

It's worth noting that the problem does not occur when the Amavisd-Milter is deactivated on the server.

Mail headers with the Amavisd-Milter enabled:

>>>> Received: by smtp-relay.sendinblue.com with ESMTP id d098fe76-d56e-4ab5-a1e5-d536be8534f0; Fri, 17 November 2023 10:38:14 +0000 (UTC)
Authentication-Results: myhostname.de;
    dkim=pass header.d=blauergockel.de;
    spf=pass (sender IP is 77.32.148.25) smtp.mailfrom=bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com smtp.helo=gy.d.sender-sib.com
Received-SPF: pass (myhostname.de: domain of gy.d.sender-sib.com designates 77.32.148.25 as permitted sender) client-ip=77.32.148.25; envelope-from=bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com; helo=gy.d.sender-sib.com;
Authentication-Results: myhostname.de (amavisd-new);
    dkim=pass (1024-bit key) header.d=blauergockel.de
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=blauergockel.de;
 q=dns/txt; s=mail; bh=GyhP5mkK9gNFmIUIdwxpg/L7Z57ARgFlGTCqCt5pINk=;
 h=from:sender:reply-to:subject:date:to:mime-version:content-type:list-unsubscribe:x-csa-complaints:list-unsubscribe-post;
        b=N6F5AnhDaprG1uknknOwZHyFcweMGp5gcwuApkz1oKC2pLJ8zzXtIhKxLo4O4Sii1479/8M2L8Fw
        8rcKxHDy0Q1N+Pyt9frqx6uxxwJDq2oNAzhbEx0hfFIyt32wddRSOSGmNuFLHafnWKnI3jdAhnVO
        Rnr2mDa+fvZ4caejemw=
Received: by smtp-relay.sendinblue.com with ESMTP id d098fe76-d56e-4ab5-a1e5-d536be8534f0; Fri, 17 November 2023 10:38:14 +0000 (UTC)
X-Mailin-EID: MTY0NjcyMDAyfmluZm9AYmVydGxob2YuZGV%2BPDZhYWI5NmUyMDJlZDliNWU4N2ZjYWMyYTJlYjk0YWQ5QGVvLWJ1Y2h1bmcuZHIxLTEyLmViZXJsLW9ubGluZS5jbG91ZD5%2BZ3kuZC5zZW5kZXItc2liLmNvbQ%3D%3D
Date: Fri, 17 Nov 2023 11:38:16 +0100
Subject: =?UTF-8?Q?Buchungsanfrage_=C3=BCber_Landesverband_Blauer_Gockel_bzw._Ihre_Anbietergemeinschaft?=
Sender: info@blauergockel.de
Reply-To: test@domain.de
MIME-Version: 1.0
Content-Type: multipart/alternative; boundary="_=_swift_v4_1700217496_94d8eea061ad783cdc914b47144dc732_=_"
X-Mailer: TYPO3
Message-Id: <d098fe76-d56e-4ab5-a1e5-d536be8534f0@smtp-relay.sendinblue.com>
Origin-messageId: <6aab96e202ed9b5e87fcac2a2eb94ad9@eo-buchung.dr1-12.eberl-online.cloud>
To: <info@domain.de>
X-sib-id: aSzaAOv__3_qF4MLYkMBRmHu32VCEyB8jvG3AsIfdDHq7BNBVXl7ZS7JLW92RjmYPQ_nkDsnsAYIAwtYRl_gNpUhtxjSDcj6GT2xIBo8iivIH3bfhdk7g2Zshsh56A4hWaYgUmli0UzJyXwkRhdhCm_mVB6p7NA_LRA-N-RJ
X-CSA-Complaints: csa-complaints@eco.de
List-Unsubscribe-Post: List-Unsubscribe=One-Click
Feedback-ID: 77.32.148.25:4719436_-1:4719436:Sendinblue
From: <info@blauergockel.de>

Mail headers with the Amavisd-Milter disabled:

>>>> Received: from gy.d.sender-sib.com (gy.d.sender-sib.com [77.32.148.25])
    by myhostname.de (Postfix) with ESMTPS id 0019C258ED2
    for <info@domain.de>; Mon, 20 Nov 2023 11:26:53 +0100 (CET)
Authentication-Results: myhostname.de;
    dkim=pass header.d=blauergockel.de;
        spf=pass (sender IP is 77.32.148.25) smtp.mailfrom=bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com smtp.helo=gy.d.sender-sib.com
Received-SPF: pass (myhostname.de: domain of gy.d.sender-sib.com designates 77.32.148.25 as permitted sender) client-ip=77.32.148.25; envelope-from=bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com; helo=gy.d.sender-sib.com;
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=blauergockel.de;
 q=dns/txt; s=mail; bh=Rnjht6SXa8w8+1uD08bJIdexeDO5WD3KOF1YtKTaXi0=;
 h=from:sender:reply-to:subject:date:to:mime-version:content-type:list-unsubscribe:x-csa-complaints:list-unsubscribe-post;
        b=qLzGNVYawl4U1fGDIj/KCm+3G0YW0HY2LA+9/5RHZcDPyhsbGXl5QEIBIVw3ixmq2MA22rRlNlWD
        vni/XCjMgyui8GruaRwd35ID3wXPgdqtWk1GJ7yex07+PcRSGrSKKbhS2fcQXuQmp86VvAGsQNUm
        Nu1cj6n6ZmppjqdJhQc=
Received: by smtp-relay.sendinblue.com with ESMTP id 196dae9e-c4a2-4a95-acf1-900cbdf841dc; Mon, 20 November 2023 10:26:37 +0000 (UTC)
X-Mailin-EID: MTY0NjcyMDAyfmluZm9AYmVydGxob2YuZGV%2BPGU2MDNiY2QwMmQwNzZlODFmODVkMTFlNWVjMjUzODExQGVvLWJ1Y2h1bmcuZHIxLTEyLmViZXJsLW9ubGluZS5jbG91ZD5%2BZ3kuZC5zZW5kZXItc2liLmNvbQ%3D%3D
Date: Mon, 20 Nov 2023 11:26:42 +0100
Subject: =?UTF-8?Q?Buchungsanfrage_=C3=BCber_Landesverband_Blauer_Gockel_bzw._Ihre_Anbietergemeinschaft?=
Sender: info@blauergockel.de
Reply-To: test@domain.de
MIME-Version: 1.0
Content-Type: multipart/alternative; boundary="_=_swift_v4_1700476002_cf870adc93c9009c334e3439534e1fba_=_"
X-Mailer: TYPO3
Message-Id: <196dae9e-c4a2-4a95-acf1-900cbdf841dc@smtp-relay.sendinblue.com>
Origin-messageId: <e603bcd02d076e81f85d11e5ec253811@eo-buchung.dr1-12.eberl-online.cloud>
To: <info@domain.de>
X-sib-id: 92hTCpuR86llF-bQlepm-SOBeI9wqyDn5ByGsZDVxqmg0DSbPaEutiXa3flDoyLawxgiCpNEXmT2wVWpGEPYV2Y2sRqVwNwk6P7oqEVdGYAChlQp-fp5Lq2c2KBiL74PSL-rdMraLs7RXuPUMDOYkZBZYMTOyUh-QpFjkzy4
X-CSA-Complaints: csa-complaints@eco.de
List-Unsubscribe-Post: List-Unsubscribe=One-Click
Feedback-ID: 77.32.148.25:4719436_-1:4719436:Sendinblue
From: <info@blauergockel.de>

Thank you in advance for your assistance!

Best regards Florian

prehor commented 9 months ago

Amavisd-milter generates Received header in format:

Received: from <hello> (<rdns> [<ip>]) (authenticated bits=<bits>)
           by <hostname> (<rdns> [<ip>])
           with <protocol> (authenticated as <user>) id <qid>;
           <date>
           (envelope-from <sender>)

The Received header generated by amavisd-milter doesn't seem to appear in your sample message with amavisd-milter enabled because it always includes the from <hello> part. Are you sure you are using Postfix with amavisd-milter and not Postfix integration of amavisd-new?

Try running amavisd-milter with -d 3 parameter, the generated Received header will be logged in the maillog.

florianstieglbauer commented 9 months ago

Thank you for your feedback. I had to ask first. I use the "Warden Protection" software from Danami on my server.

Here is the answer: You should also note that Warden uses the amavisd-milter by default (not the content filter method that the author was asking about).

I have tried it with "-d 3", but unfortunately I cannot find a problem.

Amavisd-Milter is stopped:

2023-12-06` 11:29:37 postfix/smtpd client=gy.d.sender-sib.com[77.32.148.25] 2023-12-06 11:29:37 psa-pc-remote from=bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com to=info@domain.de 2023-12-06 11:29:37 psa-pc-remote grey: stderr: SKIP 2023-12-06 11:29:37 postfix/cleanup message-id=b4edb725-e255-42e0-a29d-a870aa3a5711@smtp-relay.sendinblue.com 2023-12-06 11:29:38 psa-pc-remote py-limit-out: stderr: INFO:main:No SMTP AUTH and not running in sendmail context (incoming or unrestricted outgoing mail). SKIP message. 2023-12-06 11:29:38 psa-pc-remote py-limit-out: stderr: SKIP 2023-12-06 11:29:38 psa-pc-remote check-quota: stderr: SKIP 2023-12-06 11:29:38 psa-pc-remote spf: stderr: PASS 2023-12-06 11:29:38 postfix/qmgr from=bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com, size=10468, nrcpt=1 (queue active) 2023-12-06 11:29:38 postfix-local from=bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com, to=info@domain.de, dirname=/var/qmail/mailnames 2023-12-06 11:29:38 postfix-local dk_check: stderr: PASS 2023-12-06 11:29:38 dovecot service=lda, user=info@domain.de, ip=[]. sieve: msgid=b4edb725-e255-42e0-a29d-a870aa3a5711@smtp-relay.sendinblue.com: stored mail into mailbox 'INBOX' 2023-12-06 11:29:38 postfix/pipe to=info@domain.de, relay=plesk_virtual, delay=3.1, delays=2.5/0/0/0.58, dsn=2.0.0, status=sent (delivered via plesk_virtual service) 2023-12-06 11:29:38 postfix/qmgr removed

Amavisd-Milter ist running:

2023-12-06 11:04:48 postfix/smtpd client=gy.d.sender-sib.com[77.32.148.25] 2023-12-06 11:04:48 psa-pc-remote from=bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com to=info@domain.de 2023-12-06 11:04:48 psa-pc-remote grey: stderr: SKIP 2023-12-06 11:04:48 postfix/cleanup message-id=36b5478e-139e-4554-a9db-86070c6ba5ec@smtp-relay.sendinblue.com 2023-12-06 11:04:48 amavisd-milter gy.d.sender-sib.com: HEADER: Message-Id: 36b5478e-139e-4554-a9db-86070c6ba5ec@smtp-relay.sendinblue.com 2023-12-06 11:04:48 amavisd-milter queue_id=B89501AE88B3 2023-12-06 11:04:48 amavis (15263-15) Passed CLEAN {AcceptedInbound}, AM.PDP-SOCK [77.32.148.25] [77.32.148.25] /AM.PDP bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com -> info@domain.de, (77.32.148.25), Queue-ID: B89501AE88B3, Message-ID: 36b5478e-139e-4554-a9db-86070c6ba5ec@smtp-relay.sendinblue.com, mailid: hhc4L9isrqbv, b: rB7RlJWuc, Hits: -, size: 10509, Subject: "Buchungsanfrage über Landesverband Blauer Gockel bzw. Ihre Anbietergemeinschaft (raw: =?UTF-8?Q?Buchungsanfrage=C3=BCber_Landesverband_Blauer_Gockel_bzw._Ihre_Anbietergemeinschaft?=)", From: info@blauergockel.de (dkim:AUTHOR), X-Mailer: TYPO3, helo=gy.d.sender-sib.com, dkim_i=@blauergockel.de, dkim_sd=mail:blauergockel.de, 75 ms 2023-12-06 11:04:48 amavisd-milter log_id=15263-15 2023-12-06 11:04:48 amavisd-milter insheader=0 Authentication-Results myhostname.de (amavisd-new);#012#011dkim=pass (1024-bit key) header.d=blauergockel.de 2023-12-06 11:04:48 amavisd-milter return_value=continue 2023-12-06 11:04:49 psa-pc-remote py-limit-out: stderr: INFO:main:No SMTP AUTH and not running in sendmail context (incoming or unrestricted outgoing mail). SKIP message. 2023-12-06 11:04:49 psa-pc-remote py-limit-out: stderr: SKIP 2023-12-06 11:04:49 psa-pc-remote check-quota: stderr: SKIP 2023-12-06 11:04:49 psa-pc-remote spf: stderr: PASS 2023-12-06 11:04:49 postfix/qmgr from=bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com, size=10496, nrcpt=1 (queue active) 2023-12-06 11:04:49 postfix-local from=bounces-164672002-info=blauergockel.de@gy.d.sender-sib.com, to=info@domain.de, dirname=/var/qmail/mailnames 2023-12-06 11:04:49 postfix-local dk_check: stderr: PASS 2023-12-06 11:04:50 dovecot service=lda, user=info@domain.de, ip=[]. sieve: msgid=36b5478e-139e-4554-a9db-86070c6ba5ec@smtp-relay.sendinblue.com: stored mail into mailbox 'INBOX' 2023-12-06 11:04:50 postfix/pipe to=info@domain.de, relay=plesk_virtual, delay=2.2, delays=1.7/0/0/0.43, dsn=2.0.0, status=sent (delivered via plesk_virtual service) 2023-12-06 11:04:50 postfix/qmgr removed

But the Received header is not correct, right? Received: by smtp-relay.sendinblue.com with ESMTP id d098fe76-d56e-4ab5-a1e5-d536be8534f0; Fri, 17 November 2023 10:38:14 +0000 (UTC)

Can the problem also be caused by the sender of the e-mails?

Best regards Florian

Gazoo commented 9 months ago

@prehor Just some additional information here. It seems to be happening with this specific sender only. I looked over other emails and the Received: from line is added correctly by the amavisd-milter. It seems that with this sender the Received: by smtp-relay.sendinblue.com header is duplicated instead of the amavisd-milter adding its own Received: from header.

prehor commented 8 months ago

The log appears to be incomplete. Amavisd-milter with -d 3 should write every detail about email processing. Please send all log entries of email processing.

All amavisd-milter log entries of a single email processing contain either amavisd-milter <CLIENT_HOST> before postfix assigns a queue id to the message or amavisd-milter <QUEUE_ID> right after it assigns it. Each milter function call is logged with its name in uppercase. This is, for example, a log entry from the mlfi_header function in your log:

2023-12-06 11:04:48 amavisd-milter gy.d.sender-sib.com: HEADER: Message-Id: 36b5478e-139e-4554-a9db-86070c6ba5ec@smtp-relay.sendinblue.com

The following log entry:

2023-12-06 11:04:48 amavisd-milter queue_id=B89501AE88B3

is logged in the mlfi_eom function and must be preceded by a log entry:

amavid-milter <CLIENT_HOST> CONTENT CHECK

which is missing as well as a number of other log entries written by the function mlfi_oem and others.

You can see the expected log entry sequence generated by the logqidmsg function in https://github.com/prehor/amavisd-milter/blob/master/amavisd-milter/mlfi.c

Gazoo commented 8 months ago

@prehor is right that you don't have debug enabled for the amavisd-milter. You can add the -d 3 to the Amavisd options line. Then remember to press the restart button or manually restart the amavisd-milter from the command line with systemctl restart amavisd-milter . (I have included a screenshot).

Then you can track the full debug output with:

tail -f /var/log/maillog | grep amavisd-milter

Example with the amavisd-milter debug enabled:


Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: CONNECT
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: client name: localhost.localdomain
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: host address: IPv6:::1
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: Daemon name: hungry-faraday.205-250-175-10.plesk.page
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: HELO: el9p18.example.com
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: CLEANUP MESSAGE CONTEXT
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: MAIL FROM: <sender@test.com>
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: create working directory /var/spool/amavisd/tmp/afXXXXTVgCVe
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: create message file /var/spool/amavisd/tmp/afXXXXTVgCVe/email.txt
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: ADDHDR: Received: from el9p18.example.com (localhost.localdomain [IPv6:::1])#012#011by hungry-faraday.205-250-175-10.plesk.page (amavisd-milter);#012#011Fri, 22 Dec 2023 15:10:19 -0700 (MST)#012#011(envelope-from <sender@test.com>)
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: RCPT TO: <test@example.com>
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: HEADER: Date: Fri, 22 Dec 2023 15:10:19 -0700
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: HEADER: From: sender@test.com
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: HEADER: To: test@example.com
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: HEADER: Subject: A/V test example
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: HEADER: Message-ID: <20231222221019.d5ml9%sender@test.com>
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: HEADER: User-Agent: s-nail v14.9.22
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: HEADER: MIME-Version: 1.0
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: HEADER: Content-Type: multipart/mixed;#012 boundary="=-=xCvMvxwXchUbHxQXXlsdpdJUKTGuPRyjqBvy=-="
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: MESSAGE BODY
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: body chunk: 65535
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: after CRLF to LF conversion: 64686
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: body chunk: 7884
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: after CRLF to LF conversion: 7781
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: CONTENT CHECK
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: close message file /var/spool/amavisd/tmp/afXXXXTVgCVe/email.txt
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: open amavisd communication socket /run/amavisd/amavisd.sock
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: AMAVISD REQUEST
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: localhost.localdomain: request=AM.PDP
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: queue_id=E69DC104C305
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: sender=<sender@test.com>
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: recipient=<test@example.com>
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: tempdir=/var/spool/amavisd/tmp/afXXXXTVgCVe
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: tempdir_removed_by=client
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: mail_file=/var/spool/amavisd/tmp/afXXXXTVgCVe/email.txt
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: delivery_care_of=client
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: client_address=IPv6:::1
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: client_name=localhost.localdomain
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: helo_name=el9p18.example.com
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: policy_bank=hungry-faraday.205-250-175-10.plesk.page
Dec 22 15:10:19 el9p18 amavisd-milter[2043509]: E69DC104C305: AMAVISD RESPONSE
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: version_server=2
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: log_id=2043511-01
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: setreply=250 2.5.0 Ok, id=2043511-01, continue delivery
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: chgheader=1 subject ***UNCHECKED*** A/V test example
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: insheader=0 X-Spam-Status No, score=0.978 tagged_above=-9999 required=7#012 tests=[ALL_TRUSTED=-1, KAM_DMARC_STATUS=0.01, KAM_OLEMACRO_ZIP_PW=2,#012 OLEMACRO_ZIP_PW=5, TXREP=-5.022, T_SCC_BODY_TEXT_LINE=-0.01]#012 autolearn=no autolearn_force=no
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: insheader=0 X-Spam-Level
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: insheader=0 X-Spam-Score 0.978
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: insheader=0 X-Spam-Flag NO
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: insheader=0 X-Virus-Scanned amavis at example.com
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: insheader=0 X-Quarantine-ID <oUKl53JlK_AL>
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: return_value=continue
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: exit_code=0
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: close amavisd communication socket
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: CLOSE
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: CLEANUP MESSAGE CONTEXT
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: unlink file /var/spool/amavisd/tmp/afXXXXTVgCVe/email.txt
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: unlink file /var/spool/amavisd/tmp/afXXXXTVgCVe/parts/p001
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: unlink file /var/spool/amavisd/tmp/afXXXXTVgCVe/parts/p005
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: remove directory /var/spool/amavisd/tmp/afXXXXTVgCVe/parts
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: remove directory /var/spool/amavisd/tmp/afXXXXTVgCVe
Dec 22 15:10:22 el9p18 amavisd-milter[2043509]: E69DC104C305: CLEANUP CONNECTION CONTEXT

prehor commented 8 months ago

It's been a long time since I programmed amavisd-milter and I haven't used it in many years. The log entries from @Gazoo reminded me how it works:

amavisd-milter adds the Received header only to a temporary file in which it stores the entire message and which is subsequently checked by amavisd-new.
amavisd-new tells what headers to add/change/delete after checking the message, which can be seen in the amavisd-milter log entries after AMAVISD RESPONSE. Usually, amavisd-new asks to add only the X-Spam-*, X-Virus-Scanned and X-Quarantine-ID headers, but not the Received header.

prehor / amavisd-milter

Wrong received line #20