[pmg-devel] [PATCH log-tracker] fix mutable borrow panic on duplicate msgid
Aaron Lauterer
a.lauterer at proxmox.com
Thu Apr 29 15:38:20 CEST 2021
seems to work well against some problematic logs from a customer that ran into this problem.
So fwiw:
Tested-By: Aaron Lauterer <a.lauterer at proxmox.com>
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 <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);
> +}
>
More information about the pmg-devel
mailing list