[pmg-devel] [RFC pmg-log-tracker] do not assume constant year based on file index

[pmg-devel] [RFC pmg-log-tracker] do not assume constant year based on file index

[Stoiko Ivanov]

rather start with the current time at invocation and if the month in
the log is larger assume a year-wrap happened between logwriting and
invocation.

the old logic is flawed (but that can be said about parsing
traditional syslog timestamps (w/o year) in general) - it got worse
with the change in bullseye of rotating syslog weekly by default -
resulting in users losing one week of logs per day in the new year as
reported in https://forum.proxmox.com/threads/.102322/

Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
Tested against a production system's log which did not yield any data
for the past weeks without the patch.
Sending as RFC since I'm sure to have overlooked a corner-case the previous
logic handled better?
Might break the use-case of a time-jump after a fresh reboot (if e.g. the
hardware-clock is far in the past/future) - else the assumption that the
logs are written in the past should hold

 src/main.rs | 31 +++++++++++--------------------
 1 file changed, 11 insertions(+), 20 deletions(-)

diff --git a/src/main.rs b/src/main.rs
index daf0738..c5a723a 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -1722,7 +1722,7 @@ struct Parser {
     current_record_state: RecordState,
     rel_line_nr: u64,
 
-    current_year: [i64; 32],
+    current_year: i64,
     current_month: i64,
     current_file_index: usize,
 
@@ -1743,14 +1743,7 @@ struct Parser {
 
 impl Parser {
     fn new() -> Self {
-        let mut years: [i64; 32] = [0; 32];
-
-        for (i, year) in years.iter_mut().enumerate() {
-            let mut ts = time::get_time();
-            ts.sec -= (3600 * 24 * i) as i64;
-            let ltime = time::at(ts);
-            *year = (ltime.tm_year + 1900) as i64;
-        }
+        let ltime = time::now();
 
         Self {
             sentries: HashMap::new(),
@@ -1760,8 +1753,8 @@ impl Parser {
             smtp_tls_log_by_pid: HashMap::new(),
             current_record_state: Default::default(),
             rel_line_nr: 0,
-            current_year: years,
-            current_month: 0,
+            current_year: (ltime.tm_year + 1900) as i64,
+            current_month: ltime.tm_mon as i64,
             current_file_index: 0,
             count: 0,
             buffered_stdout: BufWriter::with_capacity(4 * 1024 * 1024, std::io::stdout()),
@@ -1848,7 +1841,7 @@ impl Parser {
 
             let (time, line) = match parse_time(
                 line,
-                self.current_year[self.current_file_index],
+                self.current_year,
                 &mut self.current_month,
             ) {
                 Some(t) => t,
@@ -1938,7 +1931,7 @@ impl Parser {
                         }
                         if let Some((time, _)) = parse_time(
                             &buffer[0..size],
-                            self.current_year[i],
+                            self.current_year,
                             &mut self.current_month,
                         ) {
                             // found the earliest file in the time frame
@@ -1957,7 +1950,7 @@ impl Parser {
                         }
                         if let Some((time, _)) = parse_time(
                             &buffer[0..size],
-                            self.current_year[i],
+                            self.current_year,
                             &mut self.current_month,
                         ) {
                             if time < self.options.start {
@@ -2311,19 +2304,17 @@ fn parse_time<'a>(
     let mut ltime: libc::time_t;
     let mut year = cur_year;
 
-    if *cur_month == 11 && mon == 0 {
-        year += 1;
-    }
-    if mon > *cur_month {
-        *cur_month = mon;
+    // assume smaller month now than in log line means yearwrap
+    if *cur_month < mon {
+        year -= 1;
     }
 
     ltime = (year - 1970) * 365 + CAL_MTOD[mon as usize];
 
+    // leap year considerations
     if mon <= 1 {
         year -= 1;
     }
-
     ltime += (year - 1968) / 4;
     ltime -= (year - 1900) / 100;
     ltime += (year - 1600) / 400;
-- 
2.30.2

[pmg-devel] applied: [RFC pmg-log-tracker] do not assume constant year based on file index

[Stoiko Ivanov]

after review and a minor change (see inline) and off-list discussion with
Wolfgang (added his R-b)


On Mon,  3 Jan 2022 17:23:12 +0100
Stoiko Ivanov <s.ivanov@proxmox.com> wrote:

> rather start with the current time at invocation and if the month in
> the log is larger assume a year-wrap happened between logwriting and
> invocation.
> 
> the old logic is flawed (but that can be said about parsing
> traditional syslog timestamps (w/o year) in general) - it got worse
> with the change in bullseye of rotating syslog weekly by default -
> resulting in users losing one week of logs per day in the new year as
> reported in https://forum.proxmox.com/threads/.102322/
> 
> Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
> ---
> Tested against a production system's log which did not yield any data
> for the past weeks without the patch.
> Sending as RFC since I'm sure to have overlooked a corner-case the previous
> logic handled better?
> Might break the use-case of a time-jump after a fresh reboot (if e.g. the
> hardware-clock is far in the past/future) - else the assumption that the
> logs are written in the past should hold
> 
>  src/main.rs | 31 +++++++++++--------------------
>  1 file changed, 11 insertions(+), 20 deletions(-)
> 
> diff --git a/src/main.rs b/src/main.rs
> index daf0738..c5a723a 100644
> --- a/src/main.rs
> +++ b/src/main.rs
> @@ -1722,7 +1722,7 @@ struct Parser {
>      current_record_state: RecordState,
>      rel_line_nr: u64,
>  
> -    current_year: [i64; 32],
> +    current_year: i64,
>      current_month: i64,
>      current_file_index: usize,
>  
> @@ -1743,14 +1743,7 @@ struct Parser {
>  
>  impl Parser {
>      fn new() -> Self {
> -        let mut years: [i64; 32] = [0; 32];
> -
> -        for (i, year) in years.iter_mut().enumerate() {
> -            let mut ts = time::get_time();
> -            ts.sec -= (3600 * 24 * i) as i64;
> -            let ltime = time::at(ts);
> -            *year = (ltime.tm_year + 1900) as i64;
> -        }
> +        let ltime = time::now();
>  
>          Self {
>              sentries: HashMap::new(),
> @@ -1760,8 +1753,8 @@ impl Parser {
>              smtp_tls_log_by_pid: HashMap::new(),
>              current_record_state: Default::default(),
>              rel_line_nr: 0,
> -            current_year: years,
> -            current_month: 0,
> +            current_year: (ltime.tm_year + 1900) as i64,
> +            current_month: ltime.tm_mon as i64,
>              current_file_index: 0,
>              count: 0,
>              buffered_stdout: BufWriter::with_capacity(4 * 1024 * 1024, std::io::stdout()),
> @@ -1848,7 +1841,7 @@ impl Parser {
>  
>              let (time, line) = match parse_time(
>                  line,
> -                self.current_year[self.current_file_index],
> +                self.current_year,
>                  &mut self.current_month,
>              ) {
>                  Some(t) => t,
> @@ -1938,7 +1931,7 @@ impl Parser {
>                          }
>                          if let Some((time, _)) = parse_time(
>                              &buffer[0..size],
> -                            self.current_year[i],
> +                            self.current_year,
>                              &mut self.current_month,
>                          ) {
>                              // found the earliest file in the time frame
> @@ -1957,7 +1950,7 @@ impl Parser {
>                          }
>                          if let Some((time, _)) = parse_time(
>                              &buffer[0..size],
> -                            self.current_year[i],
> +                            self.current_year,
>                              &mut self.current_month,
>                          ) {
>                              if time < self.options.start {
> @@ -2311,19 +2304,17 @@ fn parse_time<'a>(
>      let mut ltime: libc::time_t;
>      let mut year = cur_year;
>  
> -    if *cur_month == 11 && mon == 0 {
> -        year += 1;
> -    }
> -    if mon > *cur_month {
> -        *cur_month = mon;
> +    // assume smaller month now than in log line means yearwrap
> +    if *cur_month < mon {
cur_month is not modified anymore - so I dropped the mut reference

> +        year -= 1;
>      }
>  
>      ltime = (year - 1970) * 365 + CAL_MTOD[mon as usize];
>  
> +    // leap year considerations
>      if mon <= 1 {
>          year -= 1;
>      }
> -
>      ltime += (year - 1968) / 4;
>      ltime -= (year - 1900) / 100;
>      ltime += (year - 1600) / 400;

Re: [pmg-devel] [RFC pmg-log-tracker] do not assume constant year based on file index

[Dietmar Maurer]

> the old logic is flawed (but that can be said about parsing
> traditional syslog timestamps (w/o year) in general) - it got worse
> with the change in bullseye of rotating syslog weekly by default -
> resulting in users losing one week of logs per day in the new year 

Daily syslog rotation is essential for high volume mail system. Else the log files gets far to big! 

So cant we simply change logfile rotation back to daily?

Re: [pmg-devel] [RFC pmg-log-tracker] do not assume constant year based on file index

[Stoiko Ivanov]

On Mon, 3 Jan 2022 18:39:15 +0100 (CET)
Dietmar Maurer <dietmar@proxmox.com> wrote:

> > the old logic is flawed (but that can be said about parsing
> > traditional syslog timestamps (w/o year) in general) - it got worse
> > with the change in bullseye of rotating syslog weekly by default -
> > resulting in users losing one week of logs per day in the new year   
> 
> Daily syslog rotation is essential for high volume mail system. Else the log files gets far to big! 
> 
> So cant we simply change logfile rotation back to daily?

We can consider that - but for most bullseye installations the ship
has sailed (assuming that most users do not diff the configs when debian
asks them to and simply press 'keep my version')

Additionally the one year per log-file really seems brittle to me, or
rather the patch should be independent of the logrotation settings.

On the other hand - the volume of the logfiles does not bother me too much:
* since quite a long while /var/log/mail.log (in debian's standard
  logrotate config, which we do not touch) was always rotated weekly and
  contains all relevant logs for PMG (as an additional copy to what's
  already in /var/log/syslog) - and I think most users did not notice it
* users actually running high-volume sites quickly find out that they
  want/need to adapt their logrotation schedule 
* Finally I've seen a few posts in our support channels where users
  actively use weekly rotation and a keep of 32 to get more logs parsed
  and available in the GUI
* comparing the weekly logs of a fairly active site here (50k - 82k
  mails/month) - we get < 100 MB logs/week

My idea for the longer run would be to:
* add a dedicated log for pmg, which logs time in ISO8601 (or if this
  proves too expensive to pase in unix-timestamps) and maybe the hostname
* make retention configurable via GUI
* either suggest in a wiki-page/the reference documentation or actually by
  shipping a modified config file - to drop /var/log/mail.log (and in the
  long run maybe also the mail facility logging from /var/log/syslog)