[pmg-devel] [PATCH v2 log-tracker 1/2] after-queue: fix wrong DStatus if relay is 'removed' before 'lmtp' line

[Mira Limbeck]

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 at 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