From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <mira@nena.proxmox.com>
Received: from firstgate.proxmox.com (firstgate.proxmox.com [212.224.123.68])
 (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
 key-exchange X25519 server-signature RSA-PSS (2048 bits))
 (No client certificate requested)
 by lists.proxmox.com (Postfix) with ESMTPS id 4B56869A45
 for <pmg-devel@lists.proxmox.com>; Tue, 23 Mar 2021 15:28:58 +0100 (CET)
Received: from firstgate.proxmox.com (localhost [127.0.0.1])
 by firstgate.proxmox.com (Proxmox) with ESMTP id 3FEED2FFA7
 for <pmg-devel@lists.proxmox.com>; Tue, 23 Mar 2021 15:28:28 +0100 (CET)
Received: from proxmox-new.maurer-it.com (proxmox-new.maurer-it.com
 [212.186.127.180])
 (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
 key-exchange X25519 server-signature RSA-PSS (2048 bits))
 (No client certificate requested)
 by firstgate.proxmox.com (Proxmox) with ESMTPS id 74DB22FF99
 for <pmg-devel@lists.proxmox.com>; Tue, 23 Mar 2021 15:28:26 +0100 (CET)
Received: from proxmox-new.maurer-it.com (localhost.localdomain [127.0.0.1])
 by proxmox-new.maurer-it.com (Proxmox) with ESMTP id 3E2DE4642A
 for <pmg-devel@lists.proxmox.com>; Tue, 23 Mar 2021 15:28:26 +0100 (CET)
From: Mira Limbeck <m.limbeck@proxmox.com>
To: pmg-devel@lists.proxmox.com
Date: Tue, 23 Mar 2021 15:28:22 +0100
Message-Id: <20210323142823.27616-1-m.limbeck@proxmox.com>
X-Mailer: git-send-email 2.20.1
MIME-Version: 1.0
Content-Transfer-Encoding: 8bit
X-SPAM-LEVEL: Spam detection results:  0
 AWL -0.235 Adjusted score from AWL reputation of From: address
 KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment
 KAM_LAZY_DOMAIN_SECURITY 1 Sending domain does not have any anti-forgery
 methods
 NO_DNS_FOR_FROM         0.379 Envelope sender has no MX or A DNS records
 RCVD_IN_DNSWL_MED        -2.3 Sender listed at https://www.dnswl.org/,
 medium trust
 SPF_HELO_NONE           0.001 SPF: HELO does not publish an SPF Record
 SPF_NONE                0.001 SPF: sender does not publish an SPF Record
 URIBL_BLOCKED 0.001 ADMINISTRATOR NOTICE: The query to URIBL was blocked. See
 http://wiki.apache.org/spamassassin/DnsBlocklists#dnsbl-block for more
 information. [main.rs, ietf.org]
Subject: [pmg-devel] [PATCH v2 log-tracker 1/2] after-queue: fix wrong
 DStatus if relay is 'removed' before 'lmtp' line
X-BeenThere: pmg-devel@lists.proxmox.com
X-Mailman-Version: 2.1.29
Precedence: list
List-Id: Proxmox Mail Gateway development discussion
 <pmg-devel.lists.proxmox.com>
List-Unsubscribe: <https://lists.proxmox.com/cgi-bin/mailman/options/pmg-devel>, 
 <mailto:pmg-devel-request@lists.proxmox.com?subject=unsubscribe>
List-Archive: <http://lists.proxmox.com/pipermail/pmg-devel/>
List-Post: <mailto:pmg-devel@lists.proxmox.com>
List-Help: <mailto:pmg-devel-request@lists.proxmox.com?subject=help>
List-Subscribe: <https://lists.proxmox.com/cgi-bin/mailman/listinfo/pmg-devel>, 
 <mailto:pmg-devel-request@lists.proxmox.com?subject=subscribe>
X-List-Received-Date: Tue, 23 Mar 2021 14:28:58 -0000

We only match a QEntry with the relay Qentry in the after-queue case
when we get to the 'lmtp' line. This is because it contains a reference
from the first QEntry to the filter, and the filter contains a reference
to the relay QEntry.

If the relay log entries are finished before the 'lmtp' line, there's no
way to match the relay to the first QEntry and we still assume it is
before-queue filtered.

To fix this we try to match the QEntries via message-id and add weak
references to each other. Then we wait with finalizing either until the
other is also 'removed' (finished).

The message-id matching might break if the same message-id is used for
different entries, so this is rather a 'hack' than a nice solution, but
there's no other info in the logs we could use to match both QEntries.

Signed-off-by: Mira Limbeck <m.limbeck@proxmox.com>
---
v2:
 - rebased on faketime and outgoing TLS patches

 src/main.rs | 51 ++++++++++++++++++++++++++++++++++++++++-----------
 1 file changed, 40 insertions(+), 11 deletions(-)

diff --git a/src/main.rs b/src/main.rs
index 9594b18..33a13a5 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -447,18 +447,8 @@ fn handle_lmtp_message(msg: &[u8], parser: &mut Parser, complete_line: &[u8]) {
         None => return,
     };
 
-    let mut dstatus = DStatus::Dsn(dsn);
+    let dstatus = DStatus::Dsn(dsn);
 
-    // the dsn (enhanced status code can only have a class of 2, 4 or 5
-    // see https://tools.ietf.org/html/rfc3463
-    if qe.borrow_mut().bq_filtered {
-        dstatus = match dsn {
-            2 => DStatus::BqPass,
-            4 => DStatus::BqDefer,
-            5 => DStatus::BqReject,
-            _ => return,
-        }
-    }
     qe.borrow_mut()
         .add_to_entry(to, relay, dstatus, parser.current_record_state.timestamp);
 
@@ -771,6 +761,18 @@ fn handle_cleanup_message(msg: &[u8], parser: &mut Parser, complete_line: &[u8])
             qe.borrow_mut().msgid = msgid.into();
         }
         qe.borrow_mut().cleanup = true;
+
+
+        // does not work correctly if there's a duplicate message id in the logfiles
+        if let Some(q) = parser.msgid_lookup.remove(msgid) {
+            qe.borrow_mut().aq_qentry = Some(Weak::clone(&q));
+            if let Some(q) = q.upgrade() {
+                q.borrow_mut().aq_qentry = Some(Rc::downgrade(&qe));
+            }
+        }
+        else {
+            parser.msgid_lookup.insert(msgid.into(), Rc::downgrade(&qe));
+        }
     }
 }
 
@@ -1225,6 +1227,7 @@ struct QEntry {
     bq_filtered: bool,
     // will differ from smtpd
     bq_sentry: Option<Rc<RefCell<SEntry>>>,
+    aq_qentry: Option<Weak<RefCell<QEntry>>>,
 }
 
 impl QEntry {
@@ -1254,6 +1257,16 @@ impl QEntry {
                 }
             }
 
+            if let Some(qe) = &self.aq_qentry {
+                if let Some(qe) = qe.upgrade() {
+                    if !qe.borrow().removed {
+                        return;
+                    }
+                    qe.borrow_mut().aq_qentry = None;
+                    qe.borrow_mut().finalize(parser);
+                }
+            }
+
             if let Some(fe) = self.filter.clone() {
                 // verify that the attached FEntry is finished if it is not
                 // before queue filtered
@@ -1492,12 +1505,26 @@ impl QEntry {
             self.print_qentry_boilerplate(parser, is_se_bq_sentry, se);
         }
 
+        if self.bq_filtered {
+            for to in self.to_entries.iter_mut() {
+                to.dstatus = match to.dstatus {
+                    // the dsn (enhanced status code can only have a class of 2, 4 or 5
+                    // see https://tools.ietf.org/html/rfc3463
+                    DStatus::Dsn(2) => DStatus::BqPass,
+                    DStatus::Dsn(4) => DStatus::BqDefer,
+                    DStatus::Dsn(5) => DStatus::BqReject,
+                    _ => to.dstatus,
+                };
+            }
+        }
+
         // rev() to match the C code iteration direction (linked list vs Vec)
         for to in self.to_entries.iter().rev() {
             if !to.to.is_empty() {
                 let final_rc;
                 let final_borrow;
                 let mut final_to: &ToEntry = to;
+
                 // if status == success and there's a filter attached that has
                 // a matching 'to' in one of the ToEntries, set the ToEntry to
                 // the one in the filter
@@ -1688,6 +1715,7 @@ struct Parser {
     sentries: HashMap<u64, Rc<RefCell<SEntry>>>,
     fentries: HashMap<Box<[u8]>, Rc<RefCell<FEntry>>>,
     qentries: HashMap<Box<[u8]>, Rc<RefCell<QEntry>>>,
+    msgid_lookup: HashMap<Box<[u8]>, Weak<RefCell<QEntry>>>,
 
     smtp_tls_log_by_pid: HashMap<u64, (Box<[u8]>, u64)>,
 
@@ -1728,6 +1756,7 @@ impl Parser {
             sentries: HashMap::new(),
             fentries: HashMap::new(),
             qentries: HashMap::new(),
+            msgid_lookup: HashMap::new(),
             smtp_tls_log_by_pid: HashMap::new(),
             current_record_state: Default::default(),
             rel_line_nr: 0,
-- 
2.20.1