[pmg-devel] [PATCH log-tracker] fix mutable borrow panic on duplicate msgid
Mira Limbeck
m.limbeck at proxmox.com
Thu Apr 29 15:25:08 CEST 2021
Because of the relay before lmtp issue we now add and remove QEntrys
based on their message-id. But if the cleanup line containing the
message-id appears twice in the log for the same QEntry it keeps a weak
reference to itself which leads to a panic because of a mutable borrow
while it is already mutably borrowed in the 'finalize' function.
To circumvent this we check after the lookup if it is the same QEntry
and if so, insert it again with that message-id in the lookup table and
don't add the weak reference.
Signed-off-by: Mira Limbeck <m.limbeck at proxmox.com>
---
src/main.rs | 11 ++++-
tests/test_input_after_queue_duplicate_msgid | 20 +++++++++
tests/test_output_after_queue_duplicate_msgid | 45 +++++++++++++++++++
tests/tests_after_queue.rs | 23 ++++++++++
4 files changed, 97 insertions(+), 2 deletions(-)
create mode 100644 tests/test_input_after_queue_duplicate_msgid
create mode 100644 tests/test_output_after_queue_duplicate_msgid
diff --git a/src/main.rs b/src/main.rs
index 33a13a5..b1d4f8c 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -765,9 +765,16 @@ fn handle_cleanup_message(msg: &[u8], parser: &mut Parser, complete_line: &[u8])
// 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));
+ let q_clone = Weak::clone(&q);
if let Some(q) = q.upgrade() {
- q.borrow_mut().aq_qentry = Some(Rc::downgrade(&qe));
+ // check to make sure it's not the same QEntry
+ // this can happen if the cleanup line is duplicated in the log
+ if Rc::ptr_eq(&q, &qe) {
+ parser.msgid_lookup.insert(msgid.into(), q_clone);
+ } else {
+ qe.borrow_mut().aq_qentry = Some(q_clone);
+ q.borrow_mut().aq_qentry = Some(Rc::downgrade(&qe));
+ }
}
}
else {
diff --git a/tests/test_input_after_queue_duplicate_msgid b/tests/test_input_after_queue_duplicate_msgid
new file mode 100644
index 0000000..b159f51
--- /dev/null
+++ b/tests/test_input_after_queue_duplicate_msgid
@@ -0,0 +1,20 @@
+Jan 21 07:33:20 pmghost postfix/smtpd[29361]: connect from pmghost.mydomain.tld[192.168.1.001]
+Jan 21 07:33:20 pmghost postfix/smtpd[29361]: DEF2520A69: client=pmghost.mydomain.tld[192.168.1.001]
+Jan 21 07:33:20 pmghost postfix/cleanup[29364]: DEF2520A69: message-id=<redacted:msgid>
+Jan 21 07:33:20 pmghost postfix/cleanup[29364]: DEF2520A69: message-id=<redacted:msgid>
+Jan 21 07:33:20 pmghost postfix/qmgr[529]: DEF2520A69: from=<redacted:returnpath at domain.tld>, size=161138, nrcpt=1 (queue active)
+Jan 21 07:33:21 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: new mail message-id=<redacted:msgid>#012
+Jan 21 07:33:21 pmghost postfix/smtpd[29361]: 1855220A70: client=pmghost.mydomain.tld[192.168.1.001]
+Jan 21 07:33:21 pmghost postfix/smtpd[29361]: disconnect from pmghost.mydomain.tld[192.168.1.001] ehlo=1 mail=2 rcpt=2 data=2 quit=1 commands=8
+Jan 21 07:33:24 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: SA score=1/5 time=3.500 bayes=undefined autolearn=no autolearn_force=no hits=AWL(0.270),DKIM_SIGNED(0.1),DKIM_VALID(-0.1),DKIM_VALID_AU(-0.1),HTML_EMBEDS(0.001),HTML_FONT_LOW_CONTRAST(0.001),HTML_IMAGE_RATIO_02(0.001),HTML_MESSAGE(0.001),KAM_LOTSOFHASH(0.25),MPART_ALT_DIFF_COUNT(1.483),SPF_HELO_NONE(0.001),SPF_PASS(-0.001)
+Jan 21 07:33:24 pmghost postfix/smtpd[29375]: connect from localhost[127.0.0.1]
+Jan 21 07:33:24 pmghost postfix/smtpd[29375]: A673520AB5: client=localhost[127.0.0.1], orig_client=pmghost.mydomain.tld[192.168.1.001]
+Jan 21 07:33:24 pmghost postfix/cleanup[29364]: A673520AB5: message-id=<redacted:msgid>
+Jan 21 07:33:24 pmghost postfix/smtpd[29375]: disconnect from localhost[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 commands=5
+Jan 21 07:33:24 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: accept mail to <redacted:recipient at mydomain.tld> (A673520AB5) (rule: default-accept)
+Jan 21 07:33:24 pmghost postfix/qmgr[529]: A673520AB5: from=<redacted:returnpath at domain.tld>, size=162287, nrcpt=1 (queue active)
+Jan 21 07:33:24 pmghost postfix/smtp[29376]: A673520AB5: to=<redacted:recipient at mydomain.tld>, relay=192.168.1.002[192.168.1.002]:25, delay=0.07, delays=0.06/0/0/0.01, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as B6B682E547)
+Jan 21 07:33:24 pmghost postfix/qmgr[529]: A673520AB5: removed
+Jan 21 07:33:24 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: processing time: 3.748 seconds (3.5, 0.137, 0)
+Jan 21 07:33:24 pmghost postfix/lmtp[29365]: DEF2520A69: to=<redacted:recipient at mydomain.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=3.9, delays=0.05/0.04/0.01/3.8, dsn=2.5.0, status=sent (250 2.5.0 OK (20A9560092030F3374))
+Jan 21 07:33:24 pmghost postfix/qmgr[529]: DEF2520A69: removed
diff --git a/tests/test_output_after_queue_duplicate_msgid b/tests/test_output_after_queue_duplicate_msgid
new file mode 100644
index 0000000..80e29dd
--- /dev/null
+++ b/tests/test_output_after_queue_duplicate_msgid
@@ -0,0 +1,45 @@
+# LogReader: 4815
+# Query options
+# Start: 2020-01-21 00:00:00 (1579564800)
+# End: 2021-02-19 11:07:50 (1613732870)
+# End Query Options
+
+QENTRY: A673520AB5
+CTIME: 5E26A944
+SIZE: 162287
+CLIENT: localhost[127.0.0.1],
+MSGID: <redacted:msgid>
+TO:5E26A944:A673520AB5:2: from <redacted:returnpath at domain.tld> to <redacted:recipient at mydomain.tld> (192.168.1.002[192.168.1.002]:25)
+SMTP:
+L0000000A Jan 21 07:33:24 pmghost postfix/smtpd[29375]: connect from localhost[127.0.0.1]
+L0000000B Jan 21 07:33:24 pmghost postfix/smtpd[29375]: A673520AB5: client=localhost[127.0.0.1], orig_client=pmghost.mydomain.tld[192.168.1.001]
+L0000000D Jan 21 07:33:24 pmghost postfix/smtpd[29375]: disconnect from localhost[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 commands=5
+QMGR:
+L0000000C Jan 21 07:33:24 pmghost postfix/cleanup[29364]: A673520AB5: message-id=<redacted:msgid>
+L0000000F Jan 21 07:33:24 pmghost postfix/qmgr[529]: A673520AB5: from=<redacted:returnpath at domain.tld>, size=162287, nrcpt=1 (queue active)
+L00000010 Jan 21 07:33:24 pmghost postfix/smtp[29376]: A673520AB5: to=<redacted:recipient at mydomain.tld>, relay=192.168.1.002[192.168.1.002]:25, delay=0.07, delays=0.06/0/0/0.01, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as B6B682E547)
+L00000011 Jan 21 07:33:24 pmghost postfix/qmgr[529]: A673520AB5: removed
+
+QENTRY: DEF2520A69
+CTIME: 5E26A944
+SIZE: 161138
+CLIENT: pmghost.mydomain.tld[192.168.1.001]
+MSGID: <redacted:msgid>
+TO:5E26A944:DEF2520A69:A: from <redacted:returnpath at domain.tld> to <redacted:recipient at mydomain.tld> (A673520AB5)
+SMTP:
+L00000001 Jan 21 07:33:20 pmghost postfix/smtpd[29361]: connect from pmghost.mydomain.tld[192.168.1.001]
+L00000002 Jan 21 07:33:20 pmghost postfix/smtpd[29361]: DEF2520A69: client=pmghost.mydomain.tld[192.168.1.001]
+L00000007 Jan 21 07:33:21 pmghost postfix/smtpd[29361]: 1855220A70: client=pmghost.mydomain.tld[192.168.1.001]
+L00000008 Jan 21 07:33:21 pmghost postfix/smtpd[29361]: disconnect from pmghost.mydomain.tld[192.168.1.001] ehlo=1 mail=2 rcpt=2 data=2 quit=1 commands=8
+FILTER: 20A9560092030F3374
+L00000006 Jan 21 07:33:21 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: new mail message-id=<redacted:msgid>#012
+L00000009 Jan 21 07:33:24 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: SA score=1/5 time=3.500 bayes=undefined autolearn=no autolearn_force=no hits=AWL(0.270),DKIM_SIGNED(0.1),DKIM_VALID(-0.1),DKIM_VALID_AU(-0.1),HTML_EMBEDS(0.001),HTML_FONT_LOW_CONTRAST(0.001),HTML_IMAGE_RATIO_02(0.001),HTML_MESSAGE(0.001),KAM_LOTSOFHASH(0.25),MPART_ALT_DIFF_COUNT(1.483),SPF_HELO_NONE(0.001),SPF_PASS(-0.001)
+L0000000E Jan 21 07:33:24 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: accept mail to <redacted:recipient at mydomain.tld> (A673520AB5) (rule: default-accept)
+L00000012 Jan 21 07:33:24 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: processing time: 3.748 seconds (3.5, 0.137, 0)
+QMGR:
+L00000003 Jan 21 07:33:20 pmghost postfix/cleanup[29364]: DEF2520A69: message-id=<redacted:msgid>
+L00000004 Jan 21 07:33:20 pmghost postfix/cleanup[29364]: DEF2520A69: message-id=<redacted:msgid>
+L00000005 Jan 21 07:33:20 pmghost postfix/qmgr[529]: DEF2520A69: from=<redacted:returnpath at domain.tld>, size=161138, nrcpt=1 (queue active)
+L00000013 Jan 21 07:33:24 pmghost postfix/lmtp[29365]: DEF2520A69: to=<redacted:recipient at mydomain.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=3.9, delays=0.05/0.04/0.01/3.8, dsn=2.5.0, status=sent (250 2.5.0 OK (20A9560092030F3374))
+L00000014 Jan 21 07:33:24 pmghost postfix/qmgr[529]: DEF2520A69: removed
+
diff --git a/tests/tests_after_queue.rs b/tests/tests_after_queue.rs
index 2a8e637..5349889 100644
--- a/tests/tests_after_queue.rs
+++ b/tests/tests_after_queue.rs
@@ -172,3 +172,26 @@ fn after_queue_relay_before_lmtp() {
let output_reader = BufReader::new(&output.stdout[..]);
utils::compare_output(output_reader, expected_output);
}
+
+#[test]
+fn after_queue_duplicate_msgid() {
+ let output = Command::new("faketime")
+ .arg("2020-12-31 23:59:59")
+ .arg(utils::log_tracker_path())
+ .arg("-vv")
+ .arg("-s")
+ .arg("2020-01-21 07:30:00")
+ .arg("-e")
+ .arg("2020-01-21 07:35:00")
+ .arg("-i")
+ .arg("tests/test_input_after_queue_duplicate_msgid")
+ .output()
+ .expect("failed to execute pmg-log-tracker");
+
+ let expected_file = File::open("tests/test_output_after_queue_duplicate_msgid")
+ .expect("failed to open test_output");
+
+ let expected_output = BufReader::new(&expected_file);
+ let output_reader = BufReader::new(&output.stdout[..]);
+ utils::compare_output(output_reader, expected_output);
+}
--
2.20.1
More information about the pmg-devel
mailing list