Debian Bug report logs - #548439
coreutils: tail -F (or --follow=name --retry) does not follow file replaces anymore

version graph

Package: coreutils; Maintainer for coreutils is Michael Stone <mstone@debian.org>; Source for coreutils is src:coreutils.

Reported by: Sven Koch <haegar@sdinet.de>

Date: Sat, 26 Sep 2009 12:24:02 UTC

Severity: normal

Found in version coreutils/7.5-6

Fixed in versions coreutils/8.1-1, coreutils/8.0-2

Done: <mstone@debian.org>

Bug is archived. No further changes may be made.

Toggle useless messages

View this report as an mbox folder, status mbox, maintainer mbox


Report forwarded to debian-bugs-dist@lists.debian.org, Michael Stone <mstone@debian.org>:
Bug#548439; Package coreutils. (Sat, 26 Sep 2009 12:24:05 GMT) Full text and rfc822 format available.

Acknowledgement sent to Sven Koch <haegar@sdinet.de>:
New Bug report received and forwarded. Copy sent to Michael Stone <mstone@debian.org>. (Sat, 26 Sep 2009 12:24:05 GMT) Full text and rfc822 format available.

Message #5 received at submit@bugs.debian.org (full text, mbox):

From: Sven Koch <haegar@sdinet.de>
To: Debian Bug Tracking System <submit@bugs.debian.org>
Subject: coreutils: tail -F (or --follow=name --retry) does not follow file replaces anymore
Date: Sat, 26 Sep 2009 14:02:23 +0200
Package: coreutils
Version: 7.5-6
Severity: normal


hallo,

When running
  tail -F /var/log/syslog
over night, the display ends at the time of the log rotation with
  tail: `/var/log/syslog' has been replaced;  following end of new file

But it does not follow the new file when it becomes available, it just
stops displaying at this point.


-- System Information:
Debian Release: squeeze/sid
  APT prefers unstable
  APT policy: (500, 'unstable'), (500, 'stable'), (101, 'experimental')
Architecture: i386 (i686)

Kernel: Linux 2.6.27-sdinet59-aurora (SMP w/2 CPU cores)
Locale: LANG=en_US.ISO-8859-1, LC_CTYPE=de_DE.ISO-8859-1 (charmap=ISO-8859-1)
Shell: /bin/sh linked to /bin/bash

Versions of packages coreutils depends on:
ii  libacl1                       2.2.48-1   Access control list shared library
ii  libattr1                      1:2.4.44-1 Extended attribute shared library
ii  libc6                         2.9-26     GNU C Library: Shared libraries
ii  libselinux1                   2.0.85-4   SELinux runtime shared libraries

coreutils recommends no packages.

coreutils suggests no packages.

-- debconf-show failed




Information forwarded to debian-bugs-dist@lists.debian.org, Michael Stone <mstone@debian.org>:
Bug#548439; Package coreutils. (Sat, 14 Nov 2009 10:33:06 GMT) Full text and rfc822 format available.

Acknowledgement sent to Arjan Opmeer <arjan.opmeer@gmail.com>:
Extra info received and forwarded to list. Copy sent to Michael Stone <mstone@debian.org>. (Sat, 14 Nov 2009 10:33:06 GMT) Full text and rfc822 format available.

Message #10 received at 548439@bugs.debian.org (full text, mbox):

From: Arjan Opmeer <arjan.opmeer@gmail.com>
To: 548439@bugs.debian.org
Subject: Inotify support breaks tail -F on syslog
Date: Sat, 14 Nov 2009 11:16:06 +0100
Since coreutils 7.5 tail uses inotify. However it is not capable to follow
the sequence of file operations that happen when /var/log/syslog is rotated
by its daily cron job. This means that 'tail -F /var/log/syslog' will stop
producing output as soon as the file is rotated.

Let me give a demonstration. Open two terminal windows and enter the
following commands:

Terminal 1                              Terminal 2
----------                              ----------

echo "line 1" > somefile
tail -F somefile

                                        echo "line 2" >> somefile
                                        savelog -m 640 -c 7 somefile
                                        echo "line 3" >> somefile
                                        echo "line 4" >> somefile

This results in the following output from the tail command:

line 1
line 2
tail: `somefile' has been replaced;  following end of new file

Notice that tail fails to follow the newly created somefile and never shows
lines 3 and 4. That this is caused by the new inotify code can be
demonstrated by using the latest git checkout of coreutils. This version
still fails the above scenario, but by supplying the undocumented
'---disable-inotify' flag the inotify code is disabled and the old polling
behaviour is used. This old behaviour can cope with the logrotate sequence
and will correctly show the contents of the new file.

Could you use this information to file a bug report for GNU coreutils to
have the inotify implementation of tail fixed? In the meantime should the
Debian version of tail maybe be build without inotify support because it no
longer functions the way that users have come to expect?


Arjan




Information forwarded to debian-bugs-dist@lists.debian.org, Michael Stone <mstone@debian.org>:
Bug#548439; Package coreutils. (Sun, 15 Nov 2009 13:18:03 GMT) Full text and rfc822 format available.

Acknowledgement sent to Jim Meyering <jim@meyering.net>:
Extra info received and forwarded to list. Copy sent to Michael Stone <mstone@debian.org>. (Sun, 15 Nov 2009 13:18:03 GMT) Full text and rfc822 format available.

Message #15 received at 548439@bugs.debian.org (full text, mbox):

From: Jim Meyering <jim@meyering.net>
To: Arjan Opmeer <arjan.opmeer@gmail.com>
Cc: 548439@bugs.debian.org, bug-coreutils@gnu.org
Subject: Re: Bug#548439: Inotify support breaks tail -F on syslog
Date: Sun, 15 Nov 2009 14:04:51 +0100
Arjan Opmeer wrote:
> Since coreutils 7.5 tail uses inotify. However it is not capable to follow
> the sequence of file operations that happen when /var/log/syslog is rotated
> by its daily cron job. This means that 'tail -F /var/log/syslog' will stop
> producing output as soon as the file is rotated.
>
> Let me give a demonstration. Open two terminal windows and enter the
> following commands:
>
> Terminal 1                              Terminal 2
> ----------                              ----------
>
> echo "line 1" > somefile
> tail -F somefile
>
>                                         echo "line 2" >> somefile
>                                         savelog -m 640 -c 7 somefile
>                                         echo "line 3" >> somefile
>                                         echo "line 4" >> somefile
>
> This results in the following output from the tail command:
>
> line 1
> line 2
> tail: `somefile' has been replaced;  following end of new file
>
> Notice that tail fails to follow the newly created somefile and never shows
> lines 3 and 4. That this is caused by the new inotify code can be
> demonstrated by using the latest git checkout of coreutils. This version
> still fails the above scenario, but by supplying the undocumented
> '---disable-inotify' flag the inotify code is disabled and the old polling
> behaviour is used. This old behaviour can cope with the logrotate sequence
> and will correctly show the contents of the new file.
>
> Could you use this information to file a bug report for GNU coreutils to
> have the inotify implementation of tail fixed? In the meantime should the
> Debian version of tail maybe be build without inotify support because it no
> longer functions the way that users have come to expect?

Thanks a lot for that bug report.
At first I thought it must have been fixed, because a few
attempts to reproduce it showed no problem.
However, with repeated tests, I'd see a failure in ~1 of 7 trials
on one system, and about 1 of 4 on another.  Those were multi-core
systems.  I found it much easier to trigger the failure on a slower,
single-core system.


touch k x && timeout 1 strace -o log-$(date +%j.%T) ./tail -F k & \
echo b >> k; sleep .1; env mv x k; sleep .1; echo ok >> k

Here's output from a hacked tail.c that decodes the events
and demonstrates the problem.  The first one worked, and the
following one, run just a couple of seconds later failed:

=============================  ok  ============================
read(4, "\2\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\4\0\0\0\0\0\0\0\0\0\0", 36) = 32
write(2, "IN_ATTRIB 0\n", 12)           = 12
write(2, "name: ***\n", 10)             = 10
write(2, "IN_DELETE_SELF 0\n", 17)      = 17
write(2, "name: ***\n", 10)             = 10
read(4, "\2\0\0\0\0\200\0\0\0\0\0\0\0\0\0\0", 36) = 16
write(2, "IN_IGNORED 0\n", 13)          = 13
write(2, "name: ***\n", 10)             = 10
read(4, "\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 36) = 16
write(2, "IN_MODIFY 0\n", 12)           = 12
write(2, "name: k\n", 8)                = 8
fstat(5, {st_mode=S_IFREG|0644, st_size=3, ...}) = 0
read(5, "ok\n", 8192)                   = 3
write(1, "ok\n", 3)                     = 3
read(5, "", 8192)                       = 0
read(4, 0x12d21a0, 36)                  = -1 EINTR (Interrupted system call)

=============================  bad  ============================
read(4, "\2\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0", 36) = 16
write(2, "IN_ATTRIB 0\n", 12)           = 12
write(2, "name: ***\n", 10)             = 10
read(4, "\3\0\0\0\0\10\0\0\0\0\0\0\0\0\0\0", 36) = 16
write(2, "IN_MOVE_SELF 0\n", 15)        = 15
write(2, "name: k\n", 8)                = 8
inotify_rm_watch(4, 3)                  = 0
open("k", O_RDONLY|O_NONBLOCK)          = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
close(3)                                = 0
read(4, "\3\0\0\0\0\200\0\0\0\0\0\0\0\0\0\0", 36) = 16
write(2, "IN_IGNORED 0\n", 13)          = 13
write(2, "name: ***\n", 10)             = 10
read(4, "\2\0\0\0\0\4\0\0\0\0\0\0\0\0\0\0", 36) = 16
write(2, "IN_DELETE_SELF 0\n", 17)      = 17
write(2, "name: ***\n", 10)             = 10
read(4, "\2\0\0\0\0\200\0\0\0\0\0\0\0\0\0\0", 36) = 16
write(2, "IN_IGNORED 0\n", 13)          = 13
write(2, "name: ***\n", 10)             = 10
read(4, 0x13f91a0, 36)                  = -1 EINTR (Interrupted system call)

Here's a patch that fixes it.
I'll write a test before pushing the result.
So far, I've used this:

#!/bin/sh
for i in $(seq 1000); do
  d=d-$i
  mkdir $d
  ( cd $d
    :>k && :>x && timeout 1 ../tail -F k > out 2>/dev/null &
    echo b >> k; sleep .01; env mv x k; sleep .01; echo ok >> k
    sleep .01; grep ok out > /dev/null && ok=. || ok=X; printf $ok
  )
  rm -rf $d
done

Interestingly, on one system (modern, quad-core), it printed this for the
unpatched version of tail (replacing ../tail above): "X" represents failure
........................X.....................................................\
........X...............................XX....................................\
....................................XX......................X.................\
...................X...................XX.............X.............X.......X.\
.................................X..............................X.....X.......\
............................X.......X...X................................X....\
..............................................................................\
..........................................X...................................\
..X...................................X.......................................\
.X..................................................X.....................X.X.\
.......X..............................X.......................................\
......................X....X...........................X......................\
.................X....X.XX.......X......X.....................X.


Running the same script on an aging uniprocessor system gave this:

XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX\
X.XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX\
XXXXXXXXXXXXXXXXXXXXXXXX......X.....X....XXX.X........................XXXXXXXX\
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX\
XXXXX.....XXX.XXXXXXXXX.XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX\
X.XXXXXXXXXXXXXXXXXXXXXXX.XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX\
X.XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX.X\
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX.....\
XXXXXXXXXXXXXXXXXX.XXXXXXXXXXX.XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX\
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX\
XX.XXXXXXXXXXXXXXXXXXXX..XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX.X.....X\
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX..X....X.XXXXXXXXXXXXXXXXXXXXXXXXXX\
XXXXXXXXXXXXXXXX.......XXXXXXXXXXXXXXXXXXXX.XX..XXXXXXXXXX.XXXXX


From 203d51c2425f87811bd388c654466b7d24d1f1a1 Mon Sep 17 00:00:00 2001
From: Jim Meyering <meyering@redhat.com>
Date: Sun, 15 Nov 2009 09:25:29 +0100
Subject: [PATCH] tail -F: fix a bug in the inotify-based code

Tailing forever and by-name (--follow=name, -F), tail would
sometimes fail to follow a file that had been removed via rename.
* src/tail.c (tail_forever_inotify): When tailing by name (-F),
do not un-watch a file upon receipt of the IN_MOVE_SELF event.
Reported by Arjan Opmeer in http://bugs.debian.org/548439.
* NEWS (Bug fixes): Mention it.
---
 NEWS       |    5 +++++
 THANKS     |    3 ++-
 src/tail.c |    8 +++++++-
 3 files changed, 14 insertions(+), 2 deletions(-)

diff --git a/NEWS b/NEWS
index c9fe6ca..e3763cd 100644
--- a/NEWS
+++ b/NEWS
@@ -48,6 +48,11 @@ GNU coreutils NEWS                                    -*- outline -*-
   were first renamed or unlinked or never modified.
   [The race was introduced in coreutils-7.5]

+  tail -F (inotify-enabled) now consistently tails a file that has been
+  replaced via renaming.  That operation provokes either of two sequences
+  of inotify events.  The less common sequence is now handled as well.
+  [The bug came with the implementation change in coreutils-7.5]
+
   timeout now doesn't exit unless the command it is monitoring does,
   for any specified signal. [bug introduced in coreutils-7.0].

diff --git a/THANKS b/THANKS
index 7955da7..f9bc476 100644
--- a/THANKS
+++ b/THANKS
@@ -52,6 +52,7 @@ Andy Longton                        alongton@metamark.com
 Anthony Thyssen                     anthony@griffith.edu.au
 Antonio Rendas                      ajrendas@yahoo.com
 Ariel Faigon                        ariel@cthulhu.engr.sgi.com
+Arjan Opmeer                        arjan.opmeer@gmail.com
 Arne H. Juul                        arnej@solan.unit.no
 Arne Henrik Juul                    arnej@imf.unit.no
 Arnold Robbins                      arnold@skeeve.com
@@ -401,7 +402,7 @@ Max Chang                           maxchang@ucla.edu
 Meelis Roos                         mroos@tartu.cyber.ee
 Michael                             michael@aplatform.com
 Michael ???                         michael@roka.net
-Michael Bacarella                   mbac@netgraft.com>
+Michael Bacarella                   mbac@netgraft.com
 Michael Deutschmann                 michael@talamasca.ocis.net
 Michael Elizabeth Chastain          mec.gnu@mindspring.com
 Michael Gaughen                     mgaughen@polyserve.com
diff --git a/src/tail.c b/src/tail.c
index 09afeec..9a2f5ae 100644
--- a/src/tail.c
+++ b/src/tail.c
@@ -1404,7 +1404,13 @@ tail_forever_inotify (int wd, struct File_spec *f, size_t n_files,

       if (ev->mask & (IN_ATTRIB | IN_DELETE_SELF | IN_MOVE_SELF))
         {
-          if (ev->mask & (IN_DELETE_SELF | IN_MOVE_SELF))
+          /* For IN_DELETE_SELF, we always want to remove the watch.
+             However, for IN_MOVE_SELF (the file we're watching has
+             been clobbered via a rename), when tailing by NAME, we
+             must continue to watch the file.  It's only when following
+             by file descriptor that we must remove the watch.  */
+          if ((ev->mask & IN_DELETE_SELF)
+              || ((ev->mask & IN_MOVE_SELF) && follow_mode == Follow_descriptor))
             {
               inotify_rm_watch (wd, f[i].wd);
               hash_delete (wd_table, &(f[i]));
--
1.6.5.2.372.gc0502




Reply sent to <mstone@debian.org>:
You have taken responsibility. (Mon, 16 Nov 2009 01:06:07 GMT) Full text and rfc822 format available.

Notification sent to Sven Koch <haegar@sdinet.de>:
Bug acknowledged by developer. (Mon, 16 Nov 2009 01:06:07 GMT) Full text and rfc822 format available.

Message #20 received at 548439-close@bugs.debian.org (full text, mbox):

From: <mstone@debian.org>
To: 548439-close@bugs.debian.org
Subject: Bug#548439: fixed in coreutils 8.0-2
Date: Mon, 16 Nov 2009 01:02:16 +0000
Source: coreutils
Source-Version: 8.0-2

We believe that the bug you reported is fixed in the latest version of
coreutils, which is due to be installed in the Debian FTP archive:

coreutils_8.0-2.diff.gz
  to main/c/coreutils/coreutils_8.0-2.diff.gz
coreutils_8.0-2.dsc
  to main/c/coreutils/coreutils_8.0-2.dsc
coreutils_8.0-2_i386.deb
  to main/c/coreutils/coreutils_8.0-2_i386.deb
coreutils_8.0.orig.tar.gz
  to main/c/coreutils/coreutils_8.0.orig.tar.gz
mktemp_8.0-2_all.deb
  to main/c/coreutils/mktemp_8.0-2_all.deb



A summary of the changes between this version and the previous one is
attached.

Thank you for reporting the bug, which will now be closed.  If you
have further comments please address them to 548439@bugs.debian.org,
and the maintainer will reopen the bug report if appropriate.

Debian distribution maintenance software
pp.
mstone@debian.org (supplier of updated coreutils package)

(This message was generated automatically at their request; if you
believe that there is a problem with it please contact the archive
administrators by mailing ftpmaster@debian.org)


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Format: 1.8
Date: Sun, 15 Nov 2009 11:17:42 -0500
Source: coreutils
Binary: coreutils mktemp
Architecture: source all i386
Version: 8.0-2
Distribution: unstable
Urgency: low
Maintainer: Michael Stone <mstone@debian.org>
Changed-By: mstone@debian.org
Description: 
 coreutils  - GNU core utilities
 mktemp     - coreutils mktemp transitional package
Closes: 548439
Changes: 
 coreutils (8.0-2) unstable; urgency=low
 .
   * inotify tail -F works (Closes: #548439)
Checksums-Sha1: 
 123a0ecfdc652639b3cbe61a3cc5dc0fdedf3ee1 1262 coreutils_8.0-2.dsc
 4a73d235717d0f0b6359f30bb46bb231f3e4c7ce 10236285 coreutils_8.0.orig.tar.gz
 3831c60df1c854180c7411aa20dc810ea6c823c7 19917 coreutils_8.0-2.diff.gz
 168dce7fbaf40c982c040f78bfd69236f8edcb8b 14556 mktemp_8.0-2_all.deb
 eba60d9bae24a187a76e7fc389810f5090064a8a 4106492 coreutils_8.0-2_i386.deb
Checksums-Sha256: 
 34d3aeec5170ca9f5b79203c2cd58ed3d9816d0d1a10d509451d60d9610d82eb 1262 coreutils_8.0-2.dsc
 a1433bc5f75be65cbdc561d60e2b055c32206cb859f79bc942095380b27e7129 10236285 coreutils_8.0.orig.tar.gz
 728c0eee4336f05ae65762ef4cb13378e1592cc0109afa409d86dde59415e320 19917 coreutils_8.0-2.diff.gz
 e5e63ae8988dddb09d90af3a219e0edb56ed9a9e6f5587aa23831c0ad89854f1 14556 mktemp_8.0-2_all.deb
 dca8c6013a9ca8e1bb02daa868ca67fca5754f607839fe60f4cba8990500e9b1 4106492 coreutils_8.0-2_i386.deb
Files: 
 b4d618f655b5c471eb02895c5495a6d0 1262 utils required coreutils_8.0-2.dsc
 962261ac8d07bab2250da08f42ba49cc 10236285 utils required coreutils_8.0.orig.tar.gz
 9a7fb63f27311c6d401680d7979d335e 19917 utils required coreutils_8.0-2.diff.gz
 ad5c9da31a3138d1607d3e9466d044ca 14556 oldlibs extra mktemp_8.0-2_all.deb
 3df7f72c3bda7205c589a68087db1e7f 4106492 utils required coreutils_8.0-2_i386.deb

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (GNU/Linux)

iQCVAwUBSwCh+Q0hVr09l8FJAQJUGwP/bNtc4d/VM2Agnh8BZ4SD8f/87Qi9nZVm
6iNbNOwe8O+5aVyDGDr1w9kuSgZfycwMYMQCtBVhe1g4PBQGFPg3nI3O+QyeteKv
Z7xi81i66f3TEoWmXBoiJU0ZxGBXgmhMcZ1yPzdPf3ZYhhByVw924iumq/A+Cz+W
r2hVgoHI25I=
=QIIn
-----END PGP SIGNATURE-----





Marked as fixed in versions coreutils/8.1-1. Request was from Andreas Beckmann <anbe@debian.org> to control@bugs.debian.org. (Mon, 25 Nov 2013 03:03:32 GMT) Full text and rfc822 format available.

Bug archived. Request was from Debbugs Internal Request <owner@bugs.debian.org> to internal_control@bugs.debian.org. (Mon, 23 Dec 2013 07:34:25 GMT) Full text and rfc822 format available.

Send a report that this bug log contains spam.


Debian bug tracking system administrator <owner@bugs.debian.org>. Last modified: Sat Apr 19 07:40:44 2014; Machine Name: buxtehude.debian.org

Debian Bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.