Date: 13 Aug 2006 23:29:42 -0000 From: Jos Backus <jos@catnook.com> To: FreeBSD-gnats-submit@FreeBSD.org Subject: bin/101979: tail -F fails to print remainder of old file Message-ID: <20060813232942.27529.qmail@lizzy.catnook.local> Resent-Message-ID: <200608132330.k7DNUHH0090780@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
>Number: 101979
>Category: bin
>Synopsis: tail -F fails to print remainder of old file
>Confidential: no
>Severity: non-critical
>Priority: medium
>Responsible: freebsd-bugs
>State: open
>Quarter:
>Keywords:
>Date-Required:
>Class: sw-bug
>Submitter-Id: current-users
>Arrival-Date: Sun Aug 13 23:30:16 GMT 2006
>Closed-Date:
>Last-Modified:
>Originator: Jos Backus
>Release: FreeBSD 7.0-CURRENT i386
>Organization:
CatNook
>Environment:
System: FreeBSD lizzy.catnook.local 7.0-CURRENT FreeBSD 7.0-CURRENT #27: Fri Aug 11 20:47:50 PDT 2006 root@lizzy.catnook.local:/usr/obj/usr/src/sys/LIZZY i386
>Description:
I am trying to use tail -F to follow a file that is rotated
occasionally. It appears that when tail -F notices that the dev/ino
combo associated with the filename has changed, it does not attempt to
print the remainder of the file before opening the new one. The patch
below attempts to address this by adding a -d (drain) option to tail
that works in conjunction with -F. When specified, tail makes one last
attempt to show the remainder of the file. This drastically reduces
(but does not eliminate completely) the number of lines skipped.
I have verified this using a testbed that employs djb's multilog,
tail'ing the `current' file it employs. When the `current' is deemed
full, multilog fsync's and close's the file, then renames it to
`previous' before reopening the file named 'current' that will then
receive new input. The fsync/close should guarantee that all lines hit
the fisk and thus are visible to the tail -F. Yet while the patch
below drastically reduces the skippage, it does not eleminate it
completely meaning there is still some race condition present
somewhere.
Details of the test setup (using sysutils/daemontools):
lizzy:/var/service# cat blabber/run
#!/usr/bin/perl -w
use strict;
my $counter = 0;
my $lastTime = 0;
while (1) {
print $counter++, ' - ', time(), ' - ',
substr(rand(1000) + 1000, 0, 4), $/;
}
lizzy:/var/service# cat blabber/log/run
#!/bin/sh
exec multilog t n100 s65536 ./main
lizzy:/var/service# cat tail-blabber/run
#!/bin/sh
/usr/bin/tail -F /service/blabber/log/main/current
lizzy:/var/service# cat tail-blabber/log/run
#!/bin/sh
exec ./bin/checktail > blabber.log
lizzy:/var/service# cat tail-blabber/log/bin/checktail
#!/usr/bin/perl -w
use strict;
my $counter = undef;
my $lastCounter = undef;
$| = 1;
while (<>) {
print, next if /^XXX/;
#@4000000044dd1b7007f88124 5814025 - 1155341158 - 1529
if (/^@/) {
my ($counter) = (split / /)[1];
if (defined($lastCounter)) {
my $diff = $counter - 1 - $lastCounter;
if ($diff != 0) {
print "Found $lastCounter != ($counter - 1) (diff = $diff)\n";
}
}
$lastCounter = $counter;
}
}
lizzy:/var/service#
The blabber script generates output; the checktail scripts verifies
that there are no gaps in the output by making sure the 2nd column
increases monotonically, and logging info when a gap is seen.
>How-To-Repeat:
Set up the above two services (blabber and tail-blabber) and watch
tail-blabber/log/blabber.log grow.
>Fix:
Partial fix:
--- extern.h.orig Sat Aug 12 08:29:54 2006
+++ extern.h Fri Aug 11 23:43:16 2006
@@ -72,5 +72,5 @@
int mapprint(struct mapinfo *, off_t, off_t);
int maparound(struct mapinfo *, off_t);
-extern int Fflag, fflag, qflag, rflag, rval, no_files;
+extern int dflag, Fflag, fflag, qflag, rflag, rval, no_files;
extern const char *fname;
--- forward.c.orig Fri Aug 11 21:12:37 2006
+++ forward.c Fri Aug 11 23:43:35 2006
@@ -355,6 +355,8 @@
if (sb2.st_ino != file->st.st_ino ||
sb2.st_dev != file->st.st_dev ||
sb2.st_nlink == 0) {
+ if (dflag)
+ show(file);
file->fp = freopen(file->file_name, "r", file->fp);
if (file->fp == NULL) {
ierr();
--- tail.c.orig Fri Aug 11 23:44:49 2006
+++ tail.c Fri Aug 11 23:44:07 2006
@@ -60,7 +60,7 @@
#include "extern.h"
-int Fflag, fflag, qflag, rflag, rval, no_files;
+int dflag, Fflag, fflag, qflag, rflag, rval, no_files;
const char *fname;
file_info_t *files;
@@ -125,6 +125,9 @@
case 'c':
ARG(1, FBYTES, RBYTES);
break;
+ case 'd':
+ dflag = 1;
+ break;
case 'f':
fflag = 1;
break;
@@ -332,7 +335,7 @@
usage(void)
{
(void)fprintf(stderr,
- "usage: tail [-F | -f | -r] [-q] [-b # | -c # | -n #]"
+ "usage: tail [-F | -f | -r] [-q] [-b # | -c # | -n #] [-d]"
" [file ...]\n");
exit(1);
}
--- tail.1.orig Sat Aug 12 08:31:49 2006
+++ tail.1 Sat Aug 12 08:34:54 2006
@@ -43,6 +43,7 @@
.Nd display the last part of a file
.Sh SYNOPSIS
.Nm
+.Op Fl d
.Oo
.Fl F |
.Fl f |
@@ -87,6 +88,15 @@
The location is
.Ar number
bytes.
+.It Fl d
+The
+.Fl d
+option causes
+.Nm
+to drain and show the old file before starting to follow the new file when the
+old file has been renamed or rotated. This can reduce the amount of lines that
+.Nm
+misses reading from the old file before switching to the new file.
.It Fl f
The
.Fl f
>Release-Note:
>Audit-Trail:
>Unformatted:
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20060813232942.27529.qmail>