bin/101979: tail -F fails to print remainder of old file

[Jos Backus]

>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 at 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: