[pmg-devel] [PATCH log-tracker 1/2] add support for bookworm syslog time format

[pmg-devel] [PATCH log-tracker 1/2] add support for bookworm syslog time format

[Mira Limbeck]

Adds `proxmox-time` as dependency to parse the timestamp

Since parse_rfc3339 can't handle microseconds, we try to remove the dot
followed by 6 digits of microseconds before passing it to parse_rfc3339.

A fallback to the previous format is used when when it fails to parse
the new format.

Signed-off-by: Mira Limbeck <m.limbeck@proxmox.com>
---
 Cargo.toml  |  1 +
 src/main.rs | 36 ++++++++++++++++++++++++++++++++++++
 2 files changed, 37 insertions(+)

diff --git a/Cargo.toml b/Cargo.toml
index b484137..6d92253 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -14,3 +14,4 @@ anyhow = "1"
 clap = { version = "3.2.23", features = ["cargo"] }
 flate2 = "1.0"
 libc = "0.2"
+proxmox-time = "1.1"
diff --git a/src/main.rs b/src/main.rs
index 20d8404..e7bffd8 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -2236,6 +2236,42 @@ fn parse_number(data: &[u8], max_digits: usize) -> Option<(usize, &[u8])> {
 
 /// Parse time. Returns a tuple of (parsed_time, remaining_text) or None.
 fn parse_time(data: &'_ [u8], cur_year: i64, cur_month: i64) -> Option<(time_t, &'_ [u8])> {
+    parse_time_with_year(data).or_else(|| parse_time_no_year(data, cur_year, cur_month))
+}
+
+fn parse_time_with_year(data: &'_ [u8]) -> Option<(time_t, &'_ [u8])> {
+    let mut timestamp_buffer = [0u8; 25];
+
+    let count = data.iter().take_while(|b| **b != b' ').count();
+    if count != 27 && count != 32 {
+        return None;
+    }
+    let (timestamp, data) = data.split_at(count);
+    // remove whitespace
+    let data = &data[1..];
+
+    // microseconds: .123456 -> 7 bytes
+    let microseconds_idx = timestamp.iter().take_while(|b| **b != b'.').count();
+
+    // YYYY-MM-DDTHH:MM:SS
+    let year_time = &timestamp[0..microseconds_idx];
+    let year_time_len = year_time.len();
+    // Z | +HH:MM | -HH:MM
+    let timezone = &timestamp[microseconds_idx + 7..];
+    let timezone_len = timezone.len();
+    let timestamp_len = year_time_len + timezone_len;
+    timestamp_buffer[0..year_time_len].copy_from_slice(year_time);
+    timestamp_buffer[year_time_len..timestamp_len].copy_from_slice(timezone);
+
+    match proxmox_time::parse_rfc3339(unsafe {
+        std::str::from_utf8_unchecked(&timestamp_buffer[0..timestamp_len])
+    }) {
+        Ok(ltime) => Some((ltime, data)),
+        Err(_err) => None,
+    }
+}
+
+fn parse_time_no_year(data: &'_ [u8], cur_year: i64, cur_month: i64) -> Option<(time_t, &'_ [u8])> {
     if data.len() < 15 {
         return None;
     }
-- 
2.30.2

[pmg-devel] [PATCH log-tracker 2/2] tests: add rfc3339 timestamp test

[Mira Limbeck]

for this test `faketime` is not required since the year is part of the
timestamp

Signed-off-by: Mira Limbeck <m.limbeck@proxmox.com>
---
 tests/test_input_time_rfc3339_mixed  | 67 ++++++++++++++++++++
 tests/test_output_time_rfc3339_mixed | 94 ++++++++++++++++++++++++++++
 tests/tests_time_rfc3339.rs          | 26 ++++++++
 3 files changed, 187 insertions(+)
 create mode 100644 tests/test_input_time_rfc3339_mixed
 create mode 100644 tests/test_output_time_rfc3339_mixed
 create mode 100644 tests/tests_time_rfc3339.rs

diff --git a/tests/test_input_time_rfc3339_mixed b/tests/test_input_time_rfc3339_mixed
new file mode 100644
index 0000000..62467ee
--- /dev/null
+++ b/tests/test_input_time_rfc3339_mixed
@@ -0,0 +1,67 @@
+2023-06-23T14:26:29.324152+02:00 pmg1 postfix/postscreen[1180]: CONNECT from [192.168.1.001]:58320 to [192.168.1.001]:25
+2023-06-23T14:26:29.324181+02:00 pmg1 postfix/postscreen[1180]: WHITELISTED [192.168.1.001]:58320
+2023-06-23T14:26:29.324224+02:00 pmg1 postfix/postscreen[1180]: using backwards-compatible default setting respectful_logging=no for client [192.168.1.001]:58320
+2023-06-23T14:26:29.331019+02:00 pmg1 postfix/smtpd[1181]: connect from pmghost.mydomain.tld[192.168.1.001]
+2023-06-23T14:26:29.336189+02:00 pmg1 postfix/smtpd[1181]: 520C9C0192: client=pmghost.mydomain.tld[192.168.1.001]
+2023-06-23T14:26:29.377880+02:00 pmg1 postfix/cleanup[1184]: 520C9C0192: message-id=<redacted:msgid>
+2023-06-23T14:26:29.390150+02:00 pmg1 postfix/qmgr[1136]: 520C9C0192: from=<redacted:returnpath@domain.tld>, size=1902, nrcpt=2 (queue active)
+2023-06-23T14:26:29.392121+02:00 pmg1 postfix/smtpd[1181]: disconnect from pmghost.mydomain.tld[192.168.1.001] ehlo=1 mail=1 rcpt=2 data=1 commands=5
+2023-06-23T14:26:29.395191+02:00 pmg1 pmg-smtp-filter[945]: 2023/06/23-14:26:29 CONNECT TCP Peer: "[127.0.0.1]:47134" Local: "[127.0.0.1]:10024"
+2023-06-23T14:26:29.395261+02:00 pmg1 pmg-smtp-filter[945]: reloading configuration Proxmox_ruledb
+2023-06-23T14:26:29.452836+02:00 pmg1 pmg-smtp-filter[945]: C019B64958F756CDA5: new mail message-id=<redacted:msgid>#012
+2023-06-23T14:26:33.403125+02:00 pmg1 pmg-smtp-filter[945]: C019B64958F756CDA5: SA score=999/5 time=3.932 bayes=undefined autolearn=disabled hits=DKIM_ADSP_NXDOMAIN(0.8),GTUBE(1000),HEADER_FROM_DIFFERENT_DOMAINS(0.25),KAM_DMARC_STATUS(0.01),RCVD_IN_DNSWL_MED(-2.3),RCVD_IN_MSPIKE_H3(-0.01),RCVD_IN_MSPIKE_WL(-0.01),SPF_HELO_NONE(0.001),SUBJ_ALL_CAPS(0.5),T_TVD_MIME_NO_HEADERS(0.01)
+2023-06-23T14:26:33.414170+02:00 pmg1 pmg-smtp-filter[945]: C019B64958F756CDA5: moved mail for <test@mydomain.tld> to spam quarantine - C01C264958F7962FEA (rule: quarall)
+2023-06-23T14:26:33.414342+02:00 pmg1 pmg-smtp-filter[945]: C019B64958F756CDA5: moved mail for <user@domain2.tld> to spam quarantine - C01C264958F7962FEA (rule: quarall)
+2023-06-23T14:26:33.418457+02:00 pmg1 pmg-smtp-filter[945]: C019B64958F756CDA5: processing time: 3.968 seconds (3.932, 0.015, 0)
+2023-06-23T14:26:33.418637+02:00 pmg1 postfix/lmtp[1186]: 520C9C0192: to=<test@mydomain.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=4.1, delays=0.06/0/0.05/4, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958F756CDA5))
+2023-06-23T14:26:33.461645+02:00 pmg1 postfix/lmtp[1186]: 520C9C0192: to=<user@domain2.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=4.1, delays=0.06/0/0.05/4, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958F756CDA5))
+2023-06-23T14:26:33.461834+02:00 pmg1 postfix/qmgr[1136]: 520C9C0192: removed
+2023-06-23T14:27:23.513591+02:00 pmg1 pmg-smtp-filter[905]: starting database maintenance
+2023-06-23T14:27:23.542354+02:00 pmg1 pmg-smtp-filter[905]: end database maintenance (28 ms)
+2023-06-23T14:27:33.001794+02:00 pmg1 systemd[1]: Started session-9.scope - Session 9 of User root.
+2023-06-23T14:27:33.051280+02:00 pmg1 systemd[1]: session-9.scope: Deactivated successfully.
+2023-06-23T14:27:40.550321Z pmg1 postfix/postscreen[1180]: CONNECT from [192.168.1.001]:39892 to [192.168.1.001]:25
+2023-06-23T14:27:40.550394Z pmg1 postfix/postscreen[1180]: WHITELISTED [192.168.1.001]:39892
+2023-06-23T14:27:40.550478Z pmg1 postfix/smtpd[1181]: connect from pmghost.mydomain.tld[192.168.1.001]
+2023-06-23T14:27:40.550799Z pmg1 postfix/smtpd[1181]: 866B7C0192: client=pmghost.mydomain.tld[192.168.1.001]
+2023-06-23T14:27:40.552674Z pmg1 postfix/cleanup[1184]: 866B7C0192: message-id=<redacted:msgid>
+2023-06-23T14:27:40.600303Z pmg1 postfix/qmgr[1136]: 866B7C0192: from=<redacted:returnpath@domain.tld>, size=44585, nrcpt=2 (queue active)
+2023-06-23T14:27:40.600340Z pmg1 postfix/smtpd[1181]: disconnect from pmghost.mydomain.tld[192.168.1.001] ehlo=1 mail=1 rcpt=2 data=1 commands=5
+2023-06-23T14:27:40.600582Z pmg1 pmg-smtp-filter[946]: 2023/06/23-14:27:40 CONNECT TCP Peer: "[127.0.0.1]:33362" Local: "[127.0.0.1]:10024"
+2023-06-23T14:27:40.600623Z pmg1 pmg-smtp-filter[946]: reloading configuration Proxmox_ruledb
+2023-06-23T14:27:40.657572Z pmg1 pmg-smtp-filter[946]: C019B64958FBC9EA20: new mail message-id=<redacted:msgid>#012
+2023-06-23T14:27:41.350786Z pmg1 pmg-smtp-filter[946]: C019B64958FBC9EA20: SA score=0/5 time=0.583 bayes=undefined autolearn=disabled hits=ALL_TRUSTED(-1),HEADER_FROM_DIFFERENT_DOMAINS(0.25),KAM_DMARC_STATUS(0.01),SUBJ_ALL_CAPS(0.5),T_SPF_HELO_TEMPERROR(0.01)
+2023-06-23T14:27:41.376794Z pmg1 pmg-smtp-filter[946]: C019B64958FBC9EA20: moved mail for <test@mydomain.tld> to spam quarantine - C01C364958FBD55D53 (rule: quarall)
+2023-06-23T14:27:41.376848Z pmg1 pmg-smtp-filter[946]: C019B64958FBC9EA20: moved mail for <user@domain2.tld> to spam quarantine - C01C364958FBD55D53 (rule: quarall)
+2023-06-23T14:27:41.385561Z pmg1 pmg-smtp-filter[946]: C019B64958FBC9EA20: processing time: 0.726 seconds (0.583, 0.106, 0)
+2023-06-23T14:27:41.385756Z pmg1 postfix/lmtp[1186]: 866B7C0192: to=<test@mydomain.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.84, delays=0.05/0/0.05/0.74, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958FBC9EA20))
+2023-06-23T14:27:41.429627Z pmg1 postfix/lmtp[1186]: 866B7C0192: to=<user@domain2.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.88, delays=0.05/0/0.05/0.78, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958FBC9EA20))
+2023-06-23T14:27:41.429803Z pmg1 postfix/qmgr[1136]: 866B7C0192: removed
+2023-06-23T14:28:17.609713Z pmg1 systemd[1]: Started session-10.scope - Session 10 of User root.
+2023-06-23T14:28:17.659597Z pmg1 systemd[1]: session-10.scope: Deactivated successfully.
+2023-06-23T14:28:23.806414-02:00 pmg1 postfix/postscreen[1180]: CONNECT from [192.168.1.001]:51308 to [192.168.1.001]:25
+2023-06-23T14:28:23.806488-02:00 pmg1 postfix/postscreen[1180]: WHITELISTED [192.168.1.001]:51308
+2023-06-23T14:28:23.806586-02:00 pmg1 postfix/smtpd[1181]: connect from pmghost.mydomain.tld[192.168.1.001]
+2023-06-23T14:28:23.806755-02:00 pmg1 postfix/smtpd[1181]: C4EC9C0192: client=pmghost.mydomain.tld[192.168.1.001]
+2023-06-23T14:28:23.807109-02:00 pmg1 postfix/cleanup[1184]: C4EC9C0192: message-id=<redacted:msgid>
+2023-06-23T14:28:23.862979-02:00 pmg1 postfix/qmgr[1136]: C4EC9C0192: from=<redacted:returnpath@domain.tld>, size=130922, nrcpt=2 (queue active)
+2023-06-23T14:28:23.863025-02:00 pmg1 postfix/smtpd[1181]: disconnect from pmghost.mydomain.tld[192.168.1.001] ehlo=1 mail=1 rcpt=2 data=1 commands=5
+2023-06-23T14:28:23.863110-02:00 pmg1 pmg-smtp-filter[945]: 2023/06/23-14:28:23 CONNECT TCP Peer: "[127.0.0.1]:47888" Local: "[127.0.0.1]:10024"
+2023-06-23T14:28:23.912017-02:00 pmg1 pmg-smtp-filter[945]: C019B64958FE7DD4C6: new mail message-id=<redacted:msgid>#012
+2023-06-23T14:28:26.162626-02:00 pmg1 pmg-smtp-filter[945]: C019B64958FE7DD4C6: SA score=1/5 time=2.195 bayes=undefined autolearn=disabled hits=DKIM_INVALID(0.1),DKIM_SIGNED(0.1),HEADER_FROM_DIFFERENT_DOMAINS(0.25),HTML_MESSAGE(0.001),KAM_DMARC_STATUS(0.01),KAM_EU(0.5),KAM_NUMSUBJECT(0.5),KAM_SOMETLD_ARE_BAD_TLD(5),MAILING_LIST_MULTI(-1),RCVD_IN_DNSWL_NONE(-0.0001),RCVD_IN_HOSTKARMA_W(-2.5),RCVD_IN_MSPIKE_H5(-1),RCVD_IN_MSPIKE_WL(-0.01),SPF_HELO_PASS(-0.001),SPF_PASS(-0.001)
+2023-06-23T14:28:26.189001-02:00 pmg1 pmg-smtp-filter[945]: C019B64958FE7DD4C6: moved mail for <test@mydomain.tld> to spam quarantine - C01D364958FEA2A254 (rule: quarall)
+2023-06-23T14:28:26.189075-02:00 pmg1 pmg-smtp-filter[945]: C019B64958FE7DD4C6: moved mail for <user@domain2.tld> to spam quarantine - C01D364958FEA2A254 (rule: quarall)
+2023-06-23T14:28:26.193461-02:00 pmg1 pmg-smtp-filter[945]: C019B64958FE7DD4C6: processing time: 2.281 seconds (2.195, 0.053, 0)
+2023-06-23T14:28:26.193813-02:00 pmg1 postfix/lmtp[1186]: C4EC9C0192: to=<test@mydomain.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.4, delays=0.06/0/0.04/2.3, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958FE7DD4C6))
+2023-06-23T14:28:26.241632-02:00 pmg1 postfix/lmtp[1186]: C4EC9C0192: to=<user@domain2.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.4, delays=0.06/0/0.04/2.3, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958FE7DD4C6))
+2023-06-23T14:28:26.242140-02:00 pmg1 postfix/qmgr[1136]: C4EC9C0192: removed
+2023-06-23T14:28:30.738265-02:00 pmg1 pmgpolicy[891]: starting policy database maintenance (greylist, rbl)
+2023-06-23T14:28:30.762153-02:00 pmg1 pmgpolicy[891]: end policy database maintenance (21 ms, 0 ms)
+2023-06-23T14:28:42.463301-02:00 pmg1 postfix/smtpd[1274]: connect from localhost.localdomain[127.0.0.1]
+2023-06-23T14:28:42.463813-02:00 pmg1 postfix/smtpd[1274]: 71386C0192: client=localhost.localdomain[127.0.0.1]
+2023-06-23T14:28:42.465704-02:00 pmg1 postfix/cleanup[1184]: 71386C0192: message-id=<redacted:msgid>
+2023-06-23T14:28:42.478211-02:00 pmg1 postfix/qmgr[1136]: 71386C0192: from=<postmaster@pmghost.mydomain.tld>, size=129347, nrcpt=1 (queue active)
+2023-06-23T14:28:42.478483-02:00 pmg1 postfix/smtpd[1274]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 commands=4
+2023-06-23T14:28:42.480451-02:00 pmg1 pmgdaemon[927]: delivered quarantined mail 'C0R3T189970205' (/var/spool/pmg/spam/54/C01D364958FEA2A254)
+2023-06-23T14:28:49.391726-02:00 pmg1 postfix/smtp[1275]: 71386C0192: to=<user@domain2.tld>, relay=relay.domain3.tld[192.168.1.002]:25, delay=6.9, delays=0.01/0/1/5.9, dsn=2.5.0, status=sent (250 2.5.0 OK (42FC464958FFB88ED3))
+2023-06-23T14:28:49.391940-02:00 pmg1 postfix/qmgr[1136]: 71386C0192: removed
diff --git a/tests/test_output_time_rfc3339_mixed b/tests/test_output_time_rfc3339_mixed
new file mode 100644
index 0000000..6c597d9
--- /dev/null
+++ b/tests/test_output_time_rfc3339_mixed
@@ -0,0 +1,94 @@
+# LogReader: 6673
+# Query options
+# Start: 2023-06-23 00:00:00 (1687478400)
+# End: 2023-06-23 23:59:59 (1687564799)
+# End Query Options
+
+QENTRY: 520C9C0192
+CTIME: 64958F79
+SIZE: 1902
+CLIENT: pmghost.mydomain.tld[192.168.1.001]
+MSGID: <redacted:msgid>
+TO:64958F79:520C9C0192:Q: from <redacted:returnpath@domain.tld> to <user@domain2.tld> (C01C264958F7962FEA)
+TO:64958F79:520C9C0192:Q: from <redacted:returnpath@domain.tld> to <test@mydomain.tld> (C01C264958F7962FEA)
+SMTP:
+L00000004 2023-06-23T14:26:29.331019+02:00 pmg1 postfix/smtpd[1181]: connect from pmghost.mydomain.tld[192.168.1.001]
+L00000005 2023-06-23T14:26:29.336189+02:00 pmg1 postfix/smtpd[1181]: 520C9C0192: client=pmghost.mydomain.tld[192.168.1.001]
+L00000008 2023-06-23T14:26:29.392121+02:00 pmg1 postfix/smtpd[1181]: disconnect from pmghost.mydomain.tld[192.168.1.001] ehlo=1 mail=1 rcpt=2 data=1 commands=5
+FILTER: C019B64958F756CDA5
+L0000000B 2023-06-23T14:26:29.452836+02:00 pmg1 pmg-smtp-filter[945]: C019B64958F756CDA5: new mail message-id=<redacted:msgid>#012
+L0000000C 2023-06-23T14:26:33.403125+02:00 pmg1 pmg-smtp-filter[945]: C019B64958F756CDA5: SA score=999/5 time=3.932 bayes=undefined autolearn=disabled hits=DKIM_ADSP_NXDOMAIN(0.8),GTUBE(1000),HEADER_FROM_DIFFERENT_DOMAINS(0.25),KAM_DMARC_STATUS(0.01),RCVD_IN_DNSWL_MED(-2.3),RCVD_IN_MSPIKE_H3(-0.01),RCVD_IN_MSPIKE_WL(-0.01),SPF_HELO_NONE(0.001),SUBJ_ALL_CAPS(0.5),T_TVD_MIME_NO_HEADERS(0.01)
+L0000000D 2023-06-23T14:26:33.414170+02:00 pmg1 pmg-smtp-filter[945]: C019B64958F756CDA5: moved mail for <test@mydomain.tld> to spam quarantine - C01C264958F7962FEA (rule: quarall)
+L0000000E 2023-06-23T14:26:33.414342+02:00 pmg1 pmg-smtp-filter[945]: C019B64958F756CDA5: moved mail for <user@domain2.tld> to spam quarantine - C01C264958F7962FEA (rule: quarall)
+L0000000F 2023-06-23T14:26:33.418457+02:00 pmg1 pmg-smtp-filter[945]: C019B64958F756CDA5: processing time: 3.968 seconds (3.932, 0.015, 0)
+QMGR:
+L00000006 2023-06-23T14:26:29.377880+02:00 pmg1 postfix/cleanup[1184]: 520C9C0192: message-id=<redacted:msgid>
+L00000007 2023-06-23T14:26:29.390150+02:00 pmg1 postfix/qmgr[1136]: 520C9C0192: from=<redacted:returnpath@domain.tld>, size=1902, nrcpt=2 (queue active)
+L00000010 2023-06-23T14:26:33.418637+02:00 pmg1 postfix/lmtp[1186]: 520C9C0192: to=<test@mydomain.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=4.1, delays=0.06/0/0.05/4, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958F756CDA5))
+L00000011 2023-06-23T14:26:33.461645+02:00 pmg1 postfix/lmtp[1186]: 520C9C0192: to=<user@domain2.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=4.1, delays=0.06/0/0.05/4, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958F756CDA5))
+L00000012 2023-06-23T14:26:33.461834+02:00 pmg1 postfix/qmgr[1136]: 520C9C0192: removed
+
+QENTRY: 866B7C0192
+CTIME: 6495ABDD
+SIZE: 44585
+CLIENT: pmghost.mydomain.tld[192.168.1.001]
+MSGID: <redacted:msgid>
+TO:6495ABDD:866B7C0192:Q: from <redacted:returnpath@domain.tld> to <user@domain2.tld> (C01C364958FBD55D53)
+TO:6495ABDD:866B7C0192:Q: from <redacted:returnpath@domain.tld> to <test@mydomain.tld> (C01C364958FBD55D53)
+SMTP:
+L00000019 2023-06-23T14:27:40.550478Z pmg1 postfix/smtpd[1181]: connect from pmghost.mydomain.tld[192.168.1.001]
+L0000001A 2023-06-23T14:27:40.550799Z pmg1 postfix/smtpd[1181]: 866B7C0192: client=pmghost.mydomain.tld[192.168.1.001]
+L0000001D 2023-06-23T14:27:40.600340Z pmg1 postfix/smtpd[1181]: disconnect from pmghost.mydomain.tld[192.168.1.001] ehlo=1 mail=1 rcpt=2 data=1 commands=5
+FILTER: C019B64958FBC9EA20
+L00000020 2023-06-23T14:27:40.657572Z pmg1 pmg-smtp-filter[946]: C019B64958FBC9EA20: new mail message-id=<redacted:msgid>#012
+L00000021 2023-06-23T14:27:41.350786Z pmg1 pmg-smtp-filter[946]: C019B64958FBC9EA20: SA score=0/5 time=0.583 bayes=undefined autolearn=disabled hits=ALL_TRUSTED(-1),HEADER_FROM_DIFFERENT_DOMAINS(0.25),KAM_DMARC_STATUS(0.01),SUBJ_ALL_CAPS(0.5),T_SPF_HELO_TEMPERROR(0.01)
+L00000022 2023-06-23T14:27:41.376794Z pmg1 pmg-smtp-filter[946]: C019B64958FBC9EA20: moved mail for <test@mydomain.tld> to spam quarantine - C01C364958FBD55D53 (rule: quarall)
+L00000023 2023-06-23T14:27:41.376848Z pmg1 pmg-smtp-filter[946]: C019B64958FBC9EA20: moved mail for <user@domain2.tld> to spam quarantine - C01C364958FBD55D53 (rule: quarall)
+L00000024 2023-06-23T14:27:41.385561Z pmg1 pmg-smtp-filter[946]: C019B64958FBC9EA20: processing time: 0.726 seconds (0.583, 0.106, 0)
+QMGR:
+L0000001B 2023-06-23T14:27:40.552674Z pmg1 postfix/cleanup[1184]: 866B7C0192: message-id=<redacted:msgid>
+L0000001C 2023-06-23T14:27:40.600303Z pmg1 postfix/qmgr[1136]: 866B7C0192: from=<redacted:returnpath@domain.tld>, size=44585, nrcpt=2 (queue active)
+L00000025 2023-06-23T14:27:41.385756Z pmg1 postfix/lmtp[1186]: 866B7C0192: to=<test@mydomain.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.84, delays=0.05/0/0.05/0.74, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958FBC9EA20))
+L00000026 2023-06-23T14:27:41.429627Z pmg1 postfix/lmtp[1186]: 866B7C0192: to=<user@domain2.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.88, delays=0.05/0/0.05/0.78, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958FBC9EA20))
+L00000027 2023-06-23T14:27:41.429803Z pmg1 postfix/qmgr[1136]: 866B7C0192: removed
+
+QENTRY: C4EC9C0192
+CTIME: 6495C82A
+SIZE: 130922
+CLIENT: pmghost.mydomain.tld[192.168.1.001]
+MSGID: <redacted:msgid>
+TO:6495C82A:C4EC9C0192:Q: from <redacted:returnpath@domain.tld> to <user@domain2.tld> (C01D364958FEA2A254)
+TO:6495C82A:C4EC9C0192:Q: from <redacted:returnpath@domain.tld> to <test@mydomain.tld> (C01D364958FEA2A254)
+SMTP:
+L0000002C 2023-06-23T14:28:23.806586-02:00 pmg1 postfix/smtpd[1181]: connect from pmghost.mydomain.tld[192.168.1.001]
+L0000002D 2023-06-23T14:28:23.806755-02:00 pmg1 postfix/smtpd[1181]: C4EC9C0192: client=pmghost.mydomain.tld[192.168.1.001]
+L00000030 2023-06-23T14:28:23.863025-02:00 pmg1 postfix/smtpd[1181]: disconnect from pmghost.mydomain.tld[192.168.1.001] ehlo=1 mail=1 rcpt=2 data=1 commands=5
+FILTER: C019B64958FE7DD4C6
+L00000032 2023-06-23T14:28:23.912017-02:00 pmg1 pmg-smtp-filter[945]: C019B64958FE7DD4C6: new mail message-id=<redacted:msgid>#012
+L00000033 2023-06-23T14:28:26.162626-02:00 pmg1 pmg-smtp-filter[945]: C019B64958FE7DD4C6: SA score=1/5 time=2.195 bayes=undefined autolearn=disabled hits=DKIM_INVALID(0.1),DKIM_SIGNED(0.1),HEADER_FROM_DIFFERENT_DOMAINS(0.25),HTML_MESSAGE(0.001),KAM_DMARC_STATUS(0.01),KAM_EU(0.5),KAM_NUMSUBJECT(0.5),KAM_SOMETLD_ARE_BAD_TLD(5),MAILING_LIST_MULTI(-1),RCVD_IN_DNSWL_NONE(-0.0001),RCVD_IN_HOSTKARMA_W(-2.5),RCVD_IN_MSPIKE_H5(-1),RCVD_IN_MSPIKE_WL(-0.01),SPF_HELO_PASS(-0.001),SPF_PASS(-0.001)
+L00000034 2023-06-23T14:28:26.189001-02:00 pmg1 pmg-smtp-filter[945]: C019B64958FE7DD4C6: moved mail for <test@mydomain.tld> to spam quarantine - C01D364958FEA2A254 (rule: quarall)
+L00000035 2023-06-23T14:28:26.189075-02:00 pmg1 pmg-smtp-filter[945]: C019B64958FE7DD4C6: moved mail for <user@domain2.tld> to spam quarantine - C01D364958FEA2A254 (rule: quarall)
+L00000036 2023-06-23T14:28:26.193461-02:00 pmg1 pmg-smtp-filter[945]: C019B64958FE7DD4C6: processing time: 2.281 seconds (2.195, 0.053, 0)
+QMGR:
+L0000002E 2023-06-23T14:28:23.807109-02:00 pmg1 postfix/cleanup[1184]: C4EC9C0192: message-id=<redacted:msgid>
+L0000002F 2023-06-23T14:28:23.862979-02:00 pmg1 postfix/qmgr[1136]: C4EC9C0192: from=<redacted:returnpath@domain.tld>, size=130922, nrcpt=2 (queue active)
+L00000037 2023-06-23T14:28:26.193813-02:00 pmg1 postfix/lmtp[1186]: C4EC9C0192: to=<test@mydomain.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.4, delays=0.06/0/0.04/2.3, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958FE7DD4C6))
+L00000038 2023-06-23T14:28:26.241632-02:00 pmg1 postfix/lmtp[1186]: C4EC9C0192: to=<user@domain2.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.4, delays=0.06/0/0.04/2.3, dsn=2.5.0, status=sent (250 2.5.0 OK (C019B64958FE7DD4C6))
+L00000039 2023-06-23T14:28:26.242140-02:00 pmg1 postfix/qmgr[1136]: C4EC9C0192: removed
+
+QENTRY: 71386C0192
+CTIME: 6495C841
+SIZE: 129347
+CLIENT: localhost.localdomain[127.0.0.1]
+MSGID: <redacted:msgid>
+TO:6495C841:71386C0192:2: from <postmaster@pmghost.mydomain.tld> to <user@domain2.tld> (relay.domain3.tld[192.168.1.002]:25)
+SMTP:
+L0000003C 2023-06-23T14:28:42.463301-02:00 pmg1 postfix/smtpd[1274]: connect from localhost.localdomain[127.0.0.1]
+L0000003D 2023-06-23T14:28:42.463813-02:00 pmg1 postfix/smtpd[1274]: 71386C0192: client=localhost.localdomain[127.0.0.1]
+L00000040 2023-06-23T14:28:42.478483-02:00 pmg1 postfix/smtpd[1274]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 commands=4
+QMGR:
+L0000003E 2023-06-23T14:28:42.465704-02:00 pmg1 postfix/cleanup[1184]: 71386C0192: message-id=<redacted:msgid>
+L0000003F 2023-06-23T14:28:42.478211-02:00 pmg1 postfix/qmgr[1136]: 71386C0192: from=<postmaster@pmghost.mydomain.tld>, size=129347, nrcpt=1 (queue active)
+L00000042 2023-06-23T14:28:49.391726-02:00 pmg1 postfix/smtp[1275]: 71386C0192: to=<user@domain2.tld>, relay=relay.domain3.tld[192.168.1.002]:25, delay=6.9, delays=0.01/0/1/5.9, dsn=2.5.0, status=sent (250 2.5.0 OK (42FC464958FFB88ED3))
+L00000043 2023-06-23T14:28:49.391940-02:00 pmg1 postfix/qmgr[1136]: 71386C0192: removed
+
diff --git a/tests/tests_time_rfc3339.rs b/tests/tests_time_rfc3339.rs
new file mode 100644
index 0000000..874a332
--- /dev/null
+++ b/tests/tests_time_rfc3339.rs
@@ -0,0 +1,26 @@
+use std::fs::File;
+use std::io::BufReader;
+use std::process::Command;
+
+mod utils;
+
+#[test]
+fn after_queue_time_rfc3339_mixed() {
+    let output = Command::new(utils::log_tracker_path())
+        .arg("-vv")
+        .arg("-s")
+        .arg("2023-06-23 00:00:00")
+        .arg("-e")
+        .arg("2023-06-23 23:59:00")
+        .arg("-i")
+        .arg("tests/test_input_time_rfc3339_mixed")
+        .output()
+        .expect("failed to execute pmg-log-tracker");
+
+    let expected_file =
+        File::open("tests/test_output_time_rfc3339_mixed").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.30.2

Re: [pmg-devel] [PATCH log-tracker 1/2] add support for bookworm syslog time format

[Dominik Csapak]

One nit inline, but aside from that consider these two patches:

Reviewed-by: Dominik Csapak <d.csapak@proxmox.com>
Tested-by: Dominik Csapak <d.csapak@proxmox.com>

On 6/26/23 12:41, Mira Limbeck wrote:
> Adds `proxmox-time` as dependency to parse the timestamp
> 
> Since parse_rfc3339 can't handle microseconds, we try to remove the dot
> followed by 6 digits of microseconds before passing it to parse_rfc3339.
> 
> A fallback to the previous format is used when when it fails to parse
> the new format.
> 
> Signed-off-by: Mira Limbeck <m.limbeck@proxmox.com>
> ---
>   Cargo.toml  |  1 +
>   src/main.rs | 36 ++++++++++++++++++++++++++++++++++++
>   2 files changed, 37 insertions(+)
> 
> diff --git a/Cargo.toml b/Cargo.toml
> index b484137..6d92253 100644
> --- a/Cargo.toml
> +++ b/Cargo.toml
> @@ -14,3 +14,4 @@ anyhow = "1"
>   clap = { version = "3.2.23", features = ["cargo"] }
>   flate2 = "1.0"
>   libc = "0.2"
> +proxmox-time = "1.1"
> diff --git a/src/main.rs b/src/main.rs
> index 20d8404..e7bffd8 100644
> --- a/src/main.rs
> +++ b/src/main.rs
> @@ -2236,6 +2236,42 @@ fn parse_number(data: &[u8], max_digits: usize) -> Option<(usize, &[u8])> {
>   
>   /// Parse time. Returns a tuple of (parsed_time, remaining_text) or None.
>   fn parse_time(data: &'_ [u8], cur_year: i64, cur_month: i64) -> Option<(time_t, &'_ [u8])> {
> +    parse_time_with_year(data).or_else(|| parse_time_no_year(data, cur_year, cur_month))
> +}
> +
> +fn parse_time_with_year(data: &'_ [u8]) -> Option<(time_t, &'_ [u8])> {
> +    let mut timestamp_buffer = [0u8; 25];
> +
> +    let count = data.iter().take_while(|b| **b != b' ').count();

nit: wouldn't also a '.position(" ")' work?
could be a bit faster, since rust would not have to create another iterator?
(or maybe rust is smart enough to compile it out anyway?)

> +    if count != 27 && count != 32 {
> +        return None;
> +    }
> +    let (timestamp, data) = data.split_at(count);
> +    // remove whitespace
> +    let data = &data[1..];
> +
> +    // microseconds: .123456 -> 7 bytes
> +    let microseconds_idx = timestamp.iter().take_while(|b| **b != b'.').count();
> +
> +    // YYYY-MM-DDTHH:MM:SS
> +    let year_time = &timestamp[0..microseconds_idx];
> +    let year_time_len = year_time.len();
> +    // Z | +HH:MM | -HH:MM
> +    let timezone = &timestamp[microseconds_idx + 7..];
> +    let timezone_len = timezone.len();
> +    let timestamp_len = year_time_len + timezone_len;
> +    timestamp_buffer[0..year_time_len].copy_from_slice(year_time);
> +    timestamp_buffer[year_time_len..timestamp_len].copy_from_slice(timezone);
> +
> +    match proxmox_time::parse_rfc3339(unsafe {
> +        std::str::from_utf8_unchecked(&timestamp_buffer[0..timestamp_len])
> +    }) {
> +        Ok(ltime) => Some((ltime, data)),
> +        Err(_err) => None,
> +    }
> +}
> +
> +fn parse_time_no_year(data: &'_ [u8], cur_year: i64, cur_month: i64) -> Option<(time_t, &'_ [u8])> {
>       if data.len() < 15 {
>           return None;
>       }

[pmg-devel] applied: [PATCH log-tracker 1/2] add support for bookworm syslog time format

[Thomas Lamprecht]

Am 26/06/2023 um 12:41 schrieb Mira Limbeck:
> Adds `proxmox-time` as dependency to parse the timestamp
> 
> Since parse_rfc3339 can't handle microseconds, we try to remove the dot
> followed by 6 digits of microseconds before passing it to parse_rfc3339.
> 
> A fallback to the previous format is used when when it fails to parse
> the new format.
> 
> Signed-off-by: Mira Limbeck <m.limbeck@proxmox.com>
> ---
>  Cargo.toml  |  1 +
>  src/main.rs | 36 ++++++++++++++++++++++++++++++++++++
>  2 files changed, 37 insertions(+)
> 
>

applied both patches, thanks! (but forgot ameding them with Dominik's R-b, T-b, sorry!)