NetBSD Problem Report #49028

From dholland@macaran.localdomain  Wed Jul 23 04:59:15 2014
Return-Path: <dholland@macaran.localdomain>
Received: from mail.netbsd.org (mail.netbsd.org [149.20.53.66])
	(using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
	(Client CN "mail.netbsd.org", Issuer "Postmaster NetBSD.org" (verified OK))
	by mollari.NetBSD.org (Postfix) with ESMTPS id A5C96A6EE2
	for <gnats-bugs@gnats.NetBSD.org>; Wed, 23 Jul 2014 04:59:15 +0000 (UTC)
Message-Id: <20140723045927.199A46E25B@macaran.localdomain>
Date: Wed, 23 Jul 2014 00:59:27 -0400 (EDT)
From: dholland@eecs.harvard.edu
Reply-To: dholland@eecs.harvard.edu
To: gnats-bugs@NetBSD.org
Subject: newsyslog(8) mishandles rarely-changing binary logs
X-Send-Pr-Version: 3.95

>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.

Home	PR Database Search