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 086B6782F0 for ; Thu, 29 Apr 2021 15:44:58 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id EBE101DE80 for ; Thu, 29 Apr 2021 15:44:27 +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 D51081DE71 for ; Thu, 29 Apr 2021 15:44:26 +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 58DD7464DA for ; Thu, 29 Apr 2021 15:38:22 +0200 (CEST) To: Mira Limbeck , pmg-devel@lists.proxmox.com References: <20210429132508.29570-1-m.limbeck@proxmox.com> From: Aaron Lauterer Message-ID: Date: Thu, 29 Apr 2021 15:38:20 +0200 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Thunderbird/78.10.0 MIME-Version: 1.0 In-Reply-To: <20210429132508.29570-1-m.limbeck@proxmox.com> Content-Type: text/plain; charset=utf-8; format=flowed Content-Language: en-US Content-Transfer-Encoding: 7bit X-SPAM-LEVEL: Spam detection results: 0 AWL 0.045 Adjusted score from AWL reputation of From: address KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment NICE_REPLY_A -0.001 Looks like a legit reply (A) SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record SPF_PASS -0.001 SPF: sender matches 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: Re: [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:44:58 -0000 seems to work well against some problematic logs from a customer that ran into this problem. So fwiw: Tested-By: Aaron Lauterer On 4/29/21 3:25 PM, Mira Limbeck wrote: > 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); > +} >