* [pmg-devel] [PATCH v2 log-tracker 1/2] after-queue: fix wrong DStatus if relay is 'removed' before 'lmtp' line
@ 2021-03-23 14:28 Mira Limbeck
2021-03-23 14:28 ` [pmg-devel] [PATCH v2 log-tracker 2/2] add test case for relay removed before lmtp Mira Limbeck
2021-03-24 10:41 ` [pmg-devel] applied: [PATCH v2 log-tracker 1/2] after-queue: fix wrong DStatus if relay is 'removed' before 'lmtp' line Stoiko Ivanov
0 siblings, 2 replies; 3+ messages in thread
From: Mira Limbeck @ 2021-03-23 14:28 UTC (permalink / raw)
To: pmg-devel
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@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
^ permalink raw reply [flat|nested] 3+ messages in thread
* [pmg-devel] [PATCH v2 log-tracker 2/2] add test case for relay removed before lmtp
2021-03-23 14:28 [pmg-devel] [PATCH v2 log-tracker 1/2] after-queue: fix wrong DStatus if relay is 'removed' before 'lmtp' line Mira Limbeck
@ 2021-03-23 14:28 ` Mira Limbeck
2021-03-24 10:41 ` [pmg-devel] applied: [PATCH v2 log-tracker 1/2] after-queue: fix wrong DStatus if relay is 'removed' before 'lmtp' line Stoiko Ivanov
1 sibling, 0 replies; 3+ messages in thread
From: Mira Limbeck @ 2021-03-23 14:28 UTC (permalink / raw)
To: pmg-devel
Signed-off-by: Mira Limbeck <m.limbeck@proxmox.com>
---
v2:
- rebased on faketime and outgoing TLS patches
- changed test to use faketime
.../test_input_after_queue_relay_before_lmtp | 19 ++++++++
.../test_output_after_queue_relay_before_lmtp | 44 +++++++++++++++++++
tests/tests_after_queue.rs | 23 ++++++++++
3 files changed, 86 insertions(+)
create mode 100644 tests/test_input_after_queue_relay_before_lmtp
create mode 100644 tests/test_output_after_queue_relay_before_lmtp
diff --git a/tests/test_input_after_queue_relay_before_lmtp b/tests/test_input_after_queue_relay_before_lmtp
new file mode 100644
index 0000000..3cb6e8b
--- /dev/null
+++ b/tests/test_input_after_queue_relay_before_lmtp
@@ -0,0 +1,19 @@
+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/qmgr[529]: DEF2520A69: from=<redacted:returnpath@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@mydomain.tld> (A673520AB5) (rule: default-accept)
+Jan 21 07:33:24 pmghost postfix/qmgr[529]: A673520AB5: from=<redacted:returnpath@domain.tld>, size=162287, nrcpt=1 (queue active)
+Jan 21 07:33:24 pmghost postfix/smtp[29376]: A673520AB5: to=<redacted:recipient@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@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_relay_before_lmtp b/tests/test_output_after_queue_relay_before_lmtp
new file mode 100644
index 0000000..c4d0fdf
--- /dev/null
+++ b/tests/test_output_after_queue_relay_before_lmtp
@@ -0,0 +1,44 @@
+# 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@domain.tld> to <redacted:recipient@mydomain.tld> (192.168.1.002[192.168.1.002]:25)
+SMTP:
+L00000009 Jan 21 07:33:24 pmghost postfix/smtpd[29375]: connect from localhost[127.0.0.1]
+L0000000A 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]
+L0000000C 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:
+L0000000B Jan 21 07:33:24 pmghost postfix/cleanup[29364]: A673520AB5: message-id=<redacted:msgid>
+L0000000E Jan 21 07:33:24 pmghost postfix/qmgr[529]: A673520AB5: from=<redacted:returnpath@domain.tld>, size=162287, nrcpt=1 (queue active)
+L0000000F Jan 21 07:33:24 pmghost postfix/smtp[29376]: A673520AB5: to=<redacted:recipient@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)
+L00000010 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@domain.tld> to <redacted:recipient@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]
+L00000006 Jan 21 07:33:21 pmghost postfix/smtpd[29361]: 1855220A70: client=pmghost.mydomain.tld[192.168.1.001]
+L00000007 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
+L00000005 Jan 21 07:33:21 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: new mail message-id=<redacted:msgid>#012
+L00000008 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)
+L0000000D Jan 21 07:33:24 pmghost pmg-smtp-filter[28437]: 20A9560092030F3374: accept mail to <redacted:recipient@mydomain.tld> (A673520AB5) (rule: default-accept)
+L00000011 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/qmgr[529]: DEF2520A69: from=<redacted:returnpath@domain.tld>, size=161138, nrcpt=1 (queue active)
+L00000012 Jan 21 07:33:24 pmghost postfix/lmtp[29365]: DEF2520A69: to=<redacted:recipient@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))
+L00000013 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 6918de7..2a8e637 100644
--- a/tests/tests_after_queue.rs
+++ b/tests/tests_after_queue.rs
@@ -149,3 +149,26 @@ fn after_queue_search_string_case_insensitive() {
let output_reader = BufReader::new(&output.stdout[..]);
utils::compare_output(output_reader, expected_output);
}
+
+#[test]
+fn after_queue_relay_before_lmtp() {
+ 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_relay_before_lmtp")
+ .output()
+ .expect("failed to execute pmg-log-tracker");
+
+ let expected_file = File::open("tests/test_output_after_queue_relay_before_lmtp")
+ .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
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [pmg-devel] applied: [PATCH v2 log-tracker 1/2] after-queue: fix wrong DStatus if relay is 'removed' before 'lmtp' line
2021-03-23 14:28 [pmg-devel] [PATCH v2 log-tracker 1/2] after-queue: fix wrong DStatus if relay is 'removed' before 'lmtp' line Mira Limbeck
2021-03-23 14:28 ` [pmg-devel] [PATCH v2 log-tracker 2/2] add test case for relay removed before lmtp Mira Limbeck
@ 2021-03-24 10:41 ` Stoiko Ivanov
1 sibling, 0 replies; 3+ messages in thread
From: Stoiko Ivanov @ 2021-03-24 10:41 UTC (permalink / raw)
To: Mira Limbeck; +Cc: pmg-devel
On Tue, 23 Mar 2021 15:28:22 +0100
Mira Limbeck <m.limbeck@proxmox.com> wrote:
> 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@proxmox.com>
applied both patches - thanks!
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2021-03-24 10:41 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-03-23 14:28 [pmg-devel] [PATCH v2 log-tracker 1/2] after-queue: fix wrong DStatus if relay is 'removed' before 'lmtp' line Mira Limbeck
2021-03-23 14:28 ` [pmg-devel] [PATCH v2 log-tracker 2/2] add test case for relay removed before lmtp Mira Limbeck
2021-03-24 10:41 ` [pmg-devel] applied: [PATCH v2 log-tracker 1/2] after-queue: fix wrong DStatus if relay is 'removed' before 'lmtp' line Stoiko Ivanov
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox