bin/49028: newsyslog(8) mishandles rarely-changing binary logs

[dholland%eecs.harvard.edu@localhost]

>Number:         49028
>Category:       bin
>Synopsis:       newsyslog(8) mishandles rarely-changing binary logs
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    bin-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Wed Jul 23 05:00:00 +0000 2014
>Originator:     David A. Holland
>Release:        NetBSD 6.99.47 (20140722)
>Organization:
>Environment:
System: NetBSD amberdon 6.99.47 NetBSD 6.99.47 (AMBERDON) #12: Tue Jul 22 
23:00:30 EDT 2014  root@amberdon:/usr/src/sys/arch/amd64/compile/AMBERDON amd64
Architecture: x86_64
Machine: amd64
>Description:

If a binary log file (notably, wtmp) is routinely not touched within
the configured turnover period, newsyslog ends up turning it over
roughly twice as often as is configured.

What happens is as follows:
        1. Suppose the configured turnover period is 7 days (168 hours).
        2. Suppose when wtmp was last turned over on July 1 at 06:00,
           someone logs in on July 1 at 14:00. So the mtimes are:
                wtmp            July 1 14:00
                wtmp.0.gz       July 1 06:00
        3. newsyslog decides when to turn over a log file (when it's
           by time period) by comparing the current time with the mtime
           of the .0 generation.
        4. So on July 8 at 06:00, it's been 168 hours and it's time to
           turn over the logs.
        5. newsyslog turns over wtmp. Because the file's tagged as
           binary, it doesn't append a notice, so the mtime is unchanged.
           So the mtimes are:
                wtmp            July 8 06:00
                wtmp.0.gz       July 1 14:00
                wtmp.1.gz       July 1 06:00
        6. Now because wtmp.0.gz is nearly a week old, on July 8 at
           14:00, it's once again 168 hours since the mtime of the .0
           generation and it's time to turn over the log.
                wtmp            July 8 14:00
                wtmp.0.gz       July 8 06:00
                wtmp.1.gz       July 1 14:00
                wtmp.2.gz       July 1 06:00

Repeat for a while and you get a strange-looking pattern of two log
turnovers in quick succession separated by nearly the intended week.

I found this pattern tonight in my wtmps and it took quite a while to
figure out what was up and that it wasn't some more serious problem.

>How-To-Repeat:

As above.

>Fix:

I'm not sure. Maybe for binary log files it should touch the file in
place of appending a notice to it, rather than doing nothing. That
would eliminate this behavior; but I'm not sure it's desirable.

We could also teach it to write "log turned over" wtmp entries, but
that would only hide the underlying problem, not solve it.