[pmg-devel] [RFC pmg-log-tracker 0/2] fix rfc3339 output from logtracker

[pmg-devel] [RFC pmg-log-tracker 0/2] fix rfc3339 output from logtracker

[Stoiko Ivanov]

while upgrading a few systems we found a small glitch in the new timeformat
parsing: it did not account for the lack of timezone information in
the traditional syslog (which the API fixes up by subtracting its local
offset).
The mails were displayed in the log-tracker - but their times were UTC
(e.g. a mail from 19:37 was displayed at 17:37).

The 2 patches work around the issue as a stop-gap - by re-adding the offset
again to the parsed offset.
It seems like a better tradeoff than reworking the parsing of traditional
syslog format (which we want to drop soon anyways) - and adapting the API
(to trust the data from pmg-log-tracker)

Sending as RFC, because the code can benefit from some rework by people more
familiar with rust.

Stoiko Ivanov (2):
  rfc3339 timestamps: counter-offset timezone
  tests: update rfc3339 testoutput

 src/main.rs                          | 27 +++++++++++++++++++++++----
 tests/test_output_time_rfc3339_mixed | 20 ++++++++++----------
 2 files changed, 33 insertions(+), 14 deletions(-)

-- 
2.39.2

[pmg-devel] [RFC pmg-log-tracker 1/2] rfc3339 timestamps: counter-offset timezone

[Stoiko Ivanov]

the old time-format had no timezone-information so the API treats the
result as 'timezoned-epoch' and subtracts the timezone-offset

In order to support both formats add the timezone-offset to the
already offset time - so that the subtraction in the API is canceled
out.

This can luckily be dropped once we drop support for traditional
syslog format.

inspired by parse_rfc3339_do in proxmox-time

Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 src/main.rs | 27 +++++++++++++++++++++++----
 1 file changed, 23 insertions(+), 4 deletions(-)

diff --git a/src/main.rs b/src/main.rs
index e7bffd8..6c4a555 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -2263,12 +2263,31 @@ fn parse_time_with_year(data: &'_ [u8]) -> Option<(time_t, &'_ [u8])> {
     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 {
+    let epoch = match proxmox_time::parse_rfc3339(unsafe {
         std::str::from_utf8_unchecked(&timestamp_buffer[0..timestamp_len])
     }) {
-        Ok(ltime) => Some((ltime, data)),
-        Err(_err) => None,
-    }
+        Ok(ltime) => ltime,
+        Err(_err) => return None,
+    };
+
+    // FIXME: the traditional syslog format does not have timezone information, so the api-backend
+    // shifts the time by the offset (i.e. parse_time_no_year returns timestamps in local time)
+    // readd the TZ-offset here to match the broken format
+    // drop after legacy parsing is dropped.
+    let tz = timezone[0];
+    if tz == b'Z' {
+        return Some((epoch, data));
+    }
+
+    let hours = (timezone[1] as i32 - 48) * 10 + (timezone[2] as i32 - 48);
+    let mins = (timezone[4] as i32 - 48) * 10 + (timezone[5] as i32 - 48);
+    let offset = hours * 3600 + mins * 60;
+    let epoch = match tz {
+        b'+' => epoch + offset as i64,
+        b'-' => epoch - offset as i64,
+        _ => unreachable!(), // already checked in parse_rfc3339
+    };
+    Some((epoch, data))
 }
 
 fn parse_time_no_year(data: &'_ [u8], cur_year: i64, cur_month: i64) -> Option<(time_t, &'_ [u8])> {
-- 
2.39.2

Re: [pmg-devel] [RFC pmg-log-tracker 1/2] rfc3339 timestamps: counter-offset timezone

[Dominik Csapak]

High level comment:

isn't the api simply adding the local offset from 'now' ?
so here we add the offset depending on when it was logged,
meaning if the offset changed from the log to now it's still
off to what it was previously?

e.g.

log at 05:00 with +02:00 (epoch at 03:00 UTC)
gets converted to epoch at 05:00 UTC

now it's +01:00 (e.g. after summer/wintertime change)
result from the api is epoch at 04:00 UTC


so i guess we should either add the current timezone offset (since
that's what the api does, or fix it 'correct' by adding the timezone
info directly in the log-tracker for lines where we don't have the
info, and drop it in the api...

otherwise the code looks ok with one nit inline

On 6/27/23 21:46, Stoiko Ivanov wrote:
> the old time-format had no timezone-information so the API treats the
> result as 'timezoned-epoch' and subtracts the timezone-offset
> 
> In order to support both formats add the timezone-offset to the
> already offset time - so that the subtraction in the API is canceled
> out.
> 
> This can luckily be dropped once we drop support for traditional
> syslog format.
> 
> inspired by parse_rfc3339_do in proxmox-time
> 
> Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
> ---
>   src/main.rs | 27 +++++++++++++++++++++++----
>   1 file changed, 23 insertions(+), 4 deletions(-)
> 
> diff --git a/src/main.rs b/src/main.rs
> index e7bffd8..6c4a555 100644
> --- a/src/main.rs
> +++ b/src/main.rs
> @@ -2263,12 +2263,31 @@ fn parse_time_with_year(data: &'_ [u8]) -> Option<(time_t, &'_ [u8])> {
>       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 {
> +    let epoch = match proxmox_time::parse_rfc3339(unsafe {
>           std::str::from_utf8_unchecked(&timestamp_buffer[0..timestamp_len])
>       }) {
> -        Ok(ltime) => Some((ltime, data)),
> -        Err(_err) => None,
> -    }
> +        Ok(ltime) => ltime,
> +        Err(_err) => return None,
> +    };
> +
> +    // FIXME: the traditional syslog format does not have timezone information, so the api-backend
> +    // shifts the time by the offset (i.e. parse_time_no_year returns timestamps in local time)
> +    // readd the TZ-offset here to match the broken format
> +    // drop after legacy parsing is dropped.
> +    let tz = timezone[0];
> +    if tz == b'Z' {
> +        return Some((epoch, data));
> +    }
> +
> +    let hours = (timezone[1] as i32 - 48) * 10 + (timezone[2] as i32 - 48);
> +    let mins = (timezone[4] as i32 - 48) * 10 + (timezone[5] as i32 - 48);

nit: i guess it's copied but wouldn't it make more sense to use b'0' instead of 48 here?
at least it would it make more obvious what it does

> +    let offset = hours * 3600 + mins * 60;
> +    let epoch = match tz {
> +        b'+' => epoch + offset as i64,
> +        b'-' => epoch - offset as i64,
> +        _ => unreachable!(), // already checked in parse_rfc3339
> +    };
> +    Some((epoch, data))
>   }
>   
>   fn parse_time_no_year(data: &'_ [u8], cur_year: i64, cur_month: i64) -> Option<(time_t, &'_ [u8])> {

[pmg-devel] [RFC pmg-log-tracker 2/2] tests: update rfc3339 testoutput

[Stoiko Ivanov]

Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 tests/test_output_time_rfc3339_mixed | 20 ++++++++++----------
 1 file changed, 10 insertions(+), 10 deletions(-)

diff --git a/tests/test_output_time_rfc3339_mixed b/tests/test_output_time_rfc3339_mixed
index 6c597d9..ad7158c 100644
--- a/tests/test_output_time_rfc3339_mixed
+++ b/tests/test_output_time_rfc3339_mixed
@@ -1,16 +1,16 @@
-# LogReader: 6673
+# LogReader: 31272
 # Query options
 # Start: 2023-06-23 00:00:00 (1687478400)
-# End: 2023-06-23 23:59:59 (1687564799)
+# End: 2023-06-23 23:59:00 (1687564740)
 # End Query Options
 
 QENTRY: 520C9C0192
-CTIME: 64958F79
+CTIME: 6495AB99
 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)
+TO:6495AB99:520C9C0192:Q: from <redacted:returnpath@domain.tld> to <user@domain2.tld> (C01C264958F7962FEA)
+TO:6495AB99: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]
@@ -53,12 +53,12 @@ L00000026 2023-06-23T14:27:41.429627Z pmg1 postfix/lmtp[1186]: 866B7C0192: to=<u
 L00000027 2023-06-23T14:27:41.429803Z pmg1 postfix/qmgr[1136]: 866B7C0192: removed
 
 QENTRY: C4EC9C0192
-CTIME: 6495C82A
+CTIME: 6495AC0A
 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)
+TO:6495AC0A:C4EC9C0192:Q: from <redacted:returnpath@domain.tld> to <user@domain2.tld> (C01D364958FEA2A254)
+TO:6495AC0A: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]
@@ -77,11 +77,11 @@ L00000038 2023-06-23T14:28:26.241632-02:00 pmg1 postfix/lmtp[1186]: C4EC9C0192:
 L00000039 2023-06-23T14:28:26.242140-02:00 pmg1 postfix/qmgr[1136]: C4EC9C0192: removed
 
 QENTRY: 71386C0192
-CTIME: 6495C841
+CTIME: 6495AC21
 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)
+TO:6495AC21: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]
-- 
2.39.2