From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: 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 AEC9D782E2 for ; Thu, 29 Apr 2021 15:32:18 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id A39451D7FC for ; Thu, 29 Apr 2021 15:31:48 +0200 (CEST) Received: from proxmox-new.maurer-it.com (proxmox-new.maurer-it.com [94.136.29.106]) (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 9EDFD1D7F3 for ; Thu, 29 Apr 2021 15:31:47 +0200 (CEST) Received: from proxmox-new.maurer-it.com (localhost.localdomain [127.0.0.1]) by proxmox-new.maurer-it.com (Proxmox) with ESMTP id 05D16464B0 for ; Thu, 29 Apr 2021 15:25:13 +0200 (CEST) From: Mira Limbeck To: pmg-devel@lists.proxmox.com Date: Thu, 29 Apr 2021 15:25:08 +0200 Message-Id: <20210429132508.29570-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: 1 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 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] Subject: [pmg-devel] [PATCH log-tracker] fix mutable borrow panic on duplicate msgid X-BeenThere: pmg-devel@lists.proxmox.com X-Mailman-Version: 2.1.29 Precedence: list List-Id: Proxmox Mail Gateway development discussion List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 29 Apr 2021 13:32:18 -0000 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 --- 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= +Jan 21 07:33:20 pmghost postfix/cleanup[29364]: DEF2520A69: message-id= +Jan 21 07:33:20 pmghost postfix/qmgr[529]: DEF2520A69: from=, size=161138, nrcpt=1 (queue active) +Jan 21 07:33:21 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: new mail message-id=#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= +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 (A673520AB5) (rule: default-accept) +Jan 21 07:33:24 pmghost postfix/qmgr[529]: A673520AB5: from=, size=162287, nrcpt=1 (queue active) +Jan 21 07:33:24 pmghost postfix/smtp[29376]: A673520AB5: to=, 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=, 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: +TO:5E26A944:A673520AB5:2: from to (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= +L0000000F Jan 21 07:33:24 pmghost postfix/qmgr[529]: A673520AB5: from=, size=162287, nrcpt=1 (queue active) +L00000010 Jan 21 07:33:24 pmghost postfix/smtp[29376]: A673520AB5: to=, 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: +TO:5E26A944:DEF2520A69:A: from to (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=#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 (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= +L00000004 Jan 21 07:33:20 pmghost postfix/cleanup[29364]: DEF2520A69: message-id= +L00000005 Jan 21 07:33:20 pmghost postfix/qmgr[529]: DEF2520A69: from=, size=161138, nrcpt=1 (queue active) +L00000013 Jan 21 07:33:24 pmghost postfix/lmtp[29365]: DEF2520A69: to=, 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