Subject: Re: bug#23539: tail -f file name headings displayed too many times after suspend

From: Pádraig Brady <[email-masked]>
Date: Mon, 6 Feb 2017 23:42:27 -0800

unarchive 23539
close 23539
stop

On 20/05/16 05:08, Pádraig Brady wrote:
> On 15/05/16 00:06, Janne Snabb wrote:
>> The attached patch fixes this bug for me.
>>
>> The patch moves the write_header() call in the inotify case to
>> dump_remainder() where write_header() is called only if some file
>> content is going to be output.
>>
>> I am not sure if this is the best approach. Another approach would be to
>> change the inotify event handling so that all queued events are read at
>> once and duplicates are eliminated before acting on them. Now it reads
>> and acts on them one.
> 
> I'd prefer to handle this much like you've done in the patch.
> I.E. avoid more complications with inotify.
> However consider the case where a file is truncated,
> with your patch subsequent writes will not get a header. I.E.
> 
>    echo file1 > file1
>    echo file2 > file2
>    tail -f file1 file2
> 
> Then in parallel:
> 
>    > file1
>    echo file1 > file1
> 
> You'll get output like:
> 
>    ==> file1 <==
>    file1
> 
>    ==> file2 <==
>    file2
>    tail: file1: file truncated
>    file1

The attached variant also handles the case above, and includes a test.
I'll push in your name tomorrow.

sorry for the delay on this.

Pádraig
>From 1504dc0bb85422b8a8aa3d3a74a7db8c4b1f0578 Mon Sep 17 00:00:00 2001
From: Janne Snabb <[email-masked]>
Date: Mon, 6 Feb 2017 23:15:42 -0800
Subject: [PATCH] tail: fix output of redundant headers when resuming

* src/tail.c (check_fspec): Only enable printing of the file header
if we've actually read some data and this is a new file.  Also
move printing of the file header to...
(dump_remainder): ...here, to allow printing only when data read.
* tests/tail-2/overlay-headers.sh: A new test for suspension
and resumption of tail.
* tests/local.mk: Reference the new test.
* NEWS: Mention the fix.
Fixes http://bugs.gnu.org/23539
---
 NEWS                            |  4 ++
 src/tail.c                      | 39 ++++++++++++--------
 tests/local.mk                  |  1 +
 tests/tail-2/overlay-headers.sh | 81 +++++++++++++++++++++++++++++++++++++++++
 4 files changed, 109 insertions(+), 16 deletions(-)
 create mode 100755 tests/tail-2/overlay-headers.sh

diff --git a/NEWS b/NEWS
index 24082f5..9528f89 100644
--- a/NEWS
+++ b/NEWS
@@ -12,6 +12,10 @@ GNU coreutils NEWS                                    -*- outline -*-
   158909489063877810457 and 222087527029934481871.
   [bug introduced in coreutils-8.20]
 
+  tail no longer prints redundant file headers with interleaved inotify events,
+  which could be triggered especially when tail was suspended and resumed.
+  [bug introduced with inotify support added in coreutils-7.5]
+
   wc --bytes --files0-from now correctly reports byte counts.
   Previously it may have returned values that were too large,
   depending on the size of the first file processed.
diff --git a/src/tail.c b/src/tail.c
index 3023dd4..e060e99 100644
--- a/src/tail.c
+++ b/src/tail.c
@@ -399,7 +399,8 @@ xwrite_stdout (char const *buffer, size_t n_bytes)
    Return the number of bytes read from the file.  */
 
 static uintmax_t
-dump_remainder (const char *pretty_filename, int fd, uintmax_t n_bytes)
+dump_remainder (bool want_header, const char *pretty_filename, int fd,
+                uintmax_t n_bytes)
 {
   uintmax_t n_written;
   uintmax_t n_remaining = n_bytes;
@@ -419,6 +420,11 @@ dump_remainder (const char *pretty_filename, int fd, uintmax_t n_bytes)
         }
       if (bytes_read == 0)
         break;
+      if (want_header)
+        {
+          write_header (pretty_filename);
+          want_header = false;
+        }
       xwrite_stdout (buffer, bytes_read);
       n_written += bytes_read;
       if (n_bytes != COPY_TO_EOF)
@@ -528,7 +534,7 @@ file_lines (const char *pretty_filename, int fd, uintmax_t n_lines,
                  output the part that is after it.  */
               if (n != bytes_read - 1)
                 xwrite_stdout (nl + 1, bytes_read - (n + 1));
-              *read_pos += dump_remainder (pretty_filename, fd,
+              *read_pos += dump_remainder (false, pretty_filename, fd,
                                            end_pos - (pos + bytes_read));
               return true;
             }
@@ -540,7 +546,7 @@ file_lines (const char *pretty_filename, int fd, uintmax_t n_lines,
           /* Not enough lines in the file; print everything from
              start_pos to the end.  */
           xlseek (fd, start_pos, SEEK_SET, pretty_filename);
-          *read_pos = start_pos + dump_remainder (pretty_filename, fd,
+          *read_pos = start_pos + dump_remainder (false, pretty_filename, fd,
                                                   end_pos);
           return true;
         }
@@ -1224,7 +1230,7 @@ tail_forever (struct File_spec *f, size_t n_files, double sleep_interval)
           else
             bytes_to_read = COPY_TO_EOF;
 
-          bytes_read = dump_remainder (name, fd, bytes_to_read);
+          bytes_read = dump_remainder (false, name, fd, bytes_to_read);
 
           any_input |= (bytes_read != 0);
           f[i].size += bytes_read;
@@ -1337,7 +1343,8 @@ wd_comparator (const void *e1, const void *e2)
   return spec1->wd == spec2->wd;
 }
 
-/* Output (new) data for FSPEC->fd.  */
+/* Output (new) data for FSPEC->fd.
+   PREV_FSPEC records the last File_spec for which we output.  */
 static void
 check_fspec (struct File_spec *fspec, struct File_spec **prev_fspec)
 {
@@ -1372,18 +1379,18 @@ check_fspec (struct File_spec *fspec, struct File_spec **prev_fspec)
            && timespec_cmp (fspec->mtime, get_stat_mtime (&stats)) == 0)
     return;
 
-  if (fspec != *prev_fspec)
-    {
-      if (print_headers)
-        write_header (name);
-      *prev_fspec = fspec;
-    }
+  bool want_header = print_headers && (fspec != *prev_fspec);
 
-  uintmax_t bytes_read = dump_remainder (name, fspec->fd, COPY_TO_EOF);
+  uintmax_t bytes_read = dump_remainder (want_header, name, fspec->fd,
+                                         COPY_TO_EOF);
   fspec->size += bytes_read;
 
-  if (fflush (stdout) != 0)
-    die (EXIT_FAILURE, errno, _("write error"));
+  if (bytes_read)
+    {
+      *prev_fspec = fspec;
+      if (fflush (stdout) != 0)
+        die (EXIT_FAILURE, errno, _("write error"));
+    }
 }
 
 /* Attempt to tail N_FILES files forever, or until killed.
@@ -1793,7 +1800,7 @@ tail_bytes (const char *pretty_filename, int fd, uintmax_t n_bytes,
       *read_pos = current_pos;
     }
 
-  *read_pos += dump_remainder (pretty_filename, fd, n_bytes);
+  *read_pos += dump_remainder (false, pretty_filename, fd, n_bytes);
   return true;
 }
 
@@ -1817,7 +1824,7 @@ tail_lines (const char *pretty_filename, int fd, uintmax_t n_lines,
       int t = start_lines (pretty_filename, fd, n_lines, read_pos);
       if (t)
         return t < 0;
-      *read_pos += dump_remainder (pretty_filename, fd, COPY_TO_EOF);
+      *read_pos += dump_remainder (false, pretty_filename, fd, COPY_TO_EOF);
     }
   else
     {
diff --git a/tests/local.mk b/tests/local.mk
index 30d6d7c..2717024 100644
--- a/tests/local.mk
+++ b/tests/local.mk
@@ -248,6 +248,7 @@ all_tests =					\
   tests/misc/date-next-dow.pl			\
   tests/misc/ptx-overrun.sh			\
   tests/misc/xstrtol.pl				\
+  tests/tail-2/overlay-headers.sh		\
   tests/tail-2/pid.sh				\
   tests/misc/od.pl				\
   tests/misc/od-endian.sh			\
diff --git a/tests/tail-2/overlay-headers.sh b/tests/tail-2/overlay-headers.sh
new file mode 100755
index 0000000..cc4f789
--- /dev/null
+++ b/tests/tail-2/overlay-headers.sh
@@ -0,0 +1,81 @@
+#!/bin/sh
+# inotify-based tail would output redundant headers for
+# overlapping inotify events while it was suspended
+
+# Copyright (C) 2017 Free Software Foundation, Inc.
+
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+
+# You should have received a copy of the GNU General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+
+. "${srcdir=.}/tests/init.sh"; path_prepend_ ./src
+print_ver_ tail sleep
+
+# Function to count number of lines from tail
+# while ignoring transient errors due to resource limits
+countlines_ ()
+{
+  grep -Ev 'inotify (resources exhausted|cannot be used)' out | wc -l
+}
+
+# Function to check the expected line count in 'out'.
+# Called via retry_delay_().  Sleep some time - see retry_delay_() - if the
+# line count is still smaller than expected.
+wait4lines_ ()
+{
+  local delay=$1
+  local elc=$2   # Expected line count.
+  [ "$(countlines_)" -ge "$elc" ] || { sleep $delay; return 1; }
+}
+
+# Speedup the non inotify case
+fastpoll='---dis -s.1 --max-unchanged-stats=1'
+
+# Terminate any background tail process
+cleanup_() {
+  kill $pid 2>/dev/null && wait $pid;
+  kill $sleep 2>/dev/null && wait $sleep
+}
+
+echo start > file1 || framework_failure_
+echo start > file2 || framework_failure_
+
+# Use this as a way to gracefully terminate tail
+env sleep 20 & sleep=$!
+
+tail $fastpoll --pid=$sleep -f file1 file2 > out & pid=$!
+
+kill -0 $pid || fail=1
+
+# Wait for 5 initial lines
+retry_delay_ wait4lines_ .1 6 5 || fail=1
+
+# Suspend tail so single read() caters for multiple inotify events
+kill -STOP $pid || fail=1
+
+# Interleave writes to files to generate overlapping inotify events
+echo line >> file1 || framework_failure_
+echo line >> file2 || framework_failure_
+echo line >> file1 || framework_failure_
+echo line >> file2 || framework_failure_
+
+# Resume tail processing
+kill -CONT $pid || fail=1
+
+# Wait for 8 more lines
+retry_delay_ wait4lines_ .1 6 13 || fail=1
+
+kill $sleep && wait || framework_failure_
+
+test "$(countlines_)" = 13 || fail=1
+
+Exit $fail
-- 
2.5.5