On Sun, Oct 06, 2024 at 05:18:18PM +0200, Otto Moerbeek wrote:
> On Sun, Oct 06, 2024 at 04:35:52PM +0200, Thomas wrote:
>
> > Hello everyone,
> >
> > I may have run into a corner case with newsyslog. Long story short, I set
> > up
> > a second pflog interface to capture all traffic coming to/from my phone to
> > investigate an issue.
> >
> > I want to keep 1-2 days of log. I have set-up /etc/newsyslog.conf as such:
> > /var/log/pflog1 600 24 * 2 ZB "rcctl reload pflogd1"
> >
> > When I put my phone in offline mode at night, there's no traffic, so the
> > only
> > mtime of the rotated files is its creation time. stat -f '%Sm%t%z%t%N'
> > gives:
> >
> > Oct 6 06:00:33 2024 44 pflog1.2.gz
> > Oct 6 05:00:33 2024 44 pflog1.3.gz
> > Oct 6 04:00:33 2024 44 pflog1.4.gz
> > Oct 6 03:00:34 2024 44 pflog1.5.gz
> > Oct 6 02:00:33 2024 44 pflog1.6.gz
> >
> > I had included newsyslog -v in cron and the logs sent by cron are:
> > Date: Sun, 6 Oct 2024 02:00:02 +0200 (CEST)
> > /var/log/pflog1 <24ZB>: age (hr): 2 [2] --> trimming log....
> > Date: Sun, 6 Oct 2024 03:00:03 +0200 (CEST)
> > /var/log/pflog1 <24ZB>: age (hr): 2 [2] --> trimming log....
> > Date: Sun, 6 Oct 2024 04:00:02 +0200 (CEST)
> > /var/log/pflog1 <24ZB>: age (hr): 2 [2] --> trimming log....
> > Date: Sun, 6 Oct 2024 05:00:02 +0200 (CEST)
> > /var/log/pflog1 <24ZB>: age (hr): 2 [2] --> trimming log....
> > Date: Sun, 6 Oct 2024 06:00:02 +0200 (CEST)
> > /var/log/pflog1 <24ZB>: age (hr): 2 [2] --> trimming log....
> >
> > So, it's always calculating 2 hours of duration (and trimming) although
> > it's only
> > been one hour. This issue does not happen during the day when the logs are
> > being filled with data.
> >
> > I'm no programmer, though looking through the source code of newsyslog shows
> > this formula: return ((int)(timenow - sb.mt_time + 1800) / 3600
> >
> > If mt_time is the modification time, my only explanation is newsyslog is
> > creating the file the same second, an hour later which would return 1.5:
> >
> > $ bc -e "scale = 3; ($(date -j +"%s" 0600.33) - $(date -j +"%s" 0500.33) +
> > 1800) / 3600" -e quit
> > $ 1.500
> >
> > And that this is rounded up to 2 hrs and triggers newsyslog... I am not sure
> > but cannot think of anything else
>
> That would suprise me, as the computation is done using integer
> arithmetic and no rounding up plays a role there.
>
> -Otto
>
> >
> > I think that I can work around this (and check the theory...) setting up
> > another
> > cron job to touch /var/log/pflog1 every hour so that the mtime of the
> > archive
> > cannot be exactly 5400 seconds later.
> > 59 * * * * /usr/bin/touch /var/log/pflog1
> >
> > Greetings,
> >
> > Thomas
> >
>
What is happening: the last mod time of the latest log file is
compared to the current time. In non B mode, a banner (logfile turned
over) is been written at rotation time, so that file always has time N
(rotation time). In B mode, that write does not happen, so if there
are also no log lines entries, written, it wil have time N-1 (in
hours). That's the reason why newsyslog thinks the current log file is
two hours old and it's time to rotate.
-Otto
