From owner-freebsd-bugs@FreeBSD.ORG Sun Aug 13 23:30:23 2006 Return-Path: X-Original-To: freebsd-bugs@hub.freebsd.org Delivered-To: freebsd-bugs@hub.freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 2A6D916A4DD for ; Sun, 13 Aug 2006 23:30:23 +0000 (UTC) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (freefall.freebsd.org [216.136.204.21]) by mx1.FreeBSD.org (Postfix) with ESMTP id 88C5243D49 for ; Sun, 13 Aug 2006 23:30:22 +0000 (GMT) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (gnats@localhost [127.0.0.1]) by freefall.freebsd.org (8.13.4/8.13.4) with ESMTP id k7DNUH9j090781 for ; Sun, 13 Aug 2006 23:30:17 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.13.4/8.13.4/Submit) id k7DNUHH0090780; Sun, 13 Aug 2006 23:30:17 GMT (envelope-from gnats) Resent-Date: Sun, 13 Aug 2006 23:30:17 GMT Resent-Message-Id: <200608132330.k7DNUHH0090780@freefall.freebsd.org> Resent-From: FreeBSD-gnats-submit@FreeBSD.org (GNATS Filer) Resent-To: freebsd-bugs@FreeBSD.org Resent-Reply-To: FreeBSD-gnats-submit@FreeBSD.org, Jos Backus Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 907DB16A4DA for ; Sun, 13 Aug 2006 23:29:21 +0000 (UTC) (envelope-from jos@catnook.com) Received: from 209-204-181-78.dsl.static.sonic.net (209-204-181-78.dsl.static.sonic.net [209.204.181.78]) by mx1.FreeBSD.org (Postfix) with SMTP id BE6C643D4C for ; Sun, 13 Aug 2006 23:29:20 +0000 (GMT) (envelope-from jos@catnook.com) Received: (qmail 27530 invoked by uid 1000); 13 Aug 2006 23:29:42 -0000 Message-Id: <20060813232942.27529.qmail@lizzy.catnook.local> Date: 13 Aug 2006 23:29:42 -0000 From: Jos Backus To: FreeBSD-gnats-submit@FreeBSD.org X-Send-Pr-Version: 3.113 X-Mailman-Approved-At: Sun, 13 Aug 2006 23:54:17 +0000 Cc: Subject: bin/101979: tail -F fails to print remainder of old file X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list Reply-To: Jos Backus List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 13 Aug 2006 23:30:23 -0000 >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: