GNU bug report logs - #23539
tail -f file name headings displayed too many times after suspend

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 23539 in the body.
You can then email your comments to 23539 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Janne Snabb <snabb <at> epipe.com>
To: bug-coreutils <at> gnu.org
Subject: tail -f file name headings displayed too many times after suspend
Date: Sat, 14 May 2016 23:36:03 +0300

Hi,

I have a habit of running "tail -F /some/log/file /other/log/file" in my
shell window. Whenever I need that shell window for something else, I
hit ctrl-Z to suspend the tail. Then I do whatever I need to do.

After I am done I do "fg" to get back to displaying the tail of the log
files. I get the log output that I missed while tail was suspended.

However that is followed by several extra file name headings with no log
output following the headings. Like this:

==> /var/log/nginx/access.log <==

==> /var/log/nginx/error.log <==

==> /var/log/nginx/access.log <==

==> /var/log/nginx/error.log <==

==> /var/log/nginx/access.log <==


This happens at least on Ubuntu 16.04 (4.4.0 kernel) and CentOS 7 (3.1.0
kernel) on x86_64 architecture. It happens with distro provided tail
(coreutils 8.25 on Ubuntu and coreutils 8.22 on CentOS) as well as with
coreutils 8.25 compiled from sources.

I also tried this on FreeBSD 8.4 (which does not have inotify) with
coreutils 8.25 but I was unable to reproduce it there. So it seems to be
Linux and inotify dependent.

I have been seeing this for long time, but I am unsure how long. I
finally took the effort to report this.

I wrote a shell script (#1) which demonstrates the problem:

#!/bin/sh

echo start > file1
echo start > file2

tail -f file1 file2 &
pid=$!

sleep 1
kill -STOP $pid
sleep 1
echo line >> file1
sleep 1
echo line >> file2
sleep 1
echo line >> file1
sleep 1
echo line >> file2
sleep 1
kill -CONT $pid
sleep 1
kill -TERM $pid
# end

The output of the above script ends with extra file name headings.

However the following script (#2) does not exhibit this behaviour:

#!/bin/sh

echo start > file1
echo start > file2

tail -f file1 file2 &
pid=$!

sleep 1
kill -STOP $pid
sleep 1
echo line >> file1
sleep 1
echo line >> file1
sleep 1
echo line >> file2
sleep 1
echo line >> file2
sleep 1
kill -CONT $pid
sleep 1
kill -TERM $pid
# end

The only difference between these two scripts is the ordering of the
writes to the files which are being tail'ed. If the writes are
interleaved, tail displays extra file name headings.

If I add the ---disable-inotify option to the tail commend line there is
no extra file name headings. Thus this is clearly inotify related.

I believe the extra file name headings are not displayed in case #2
because the following check in check_fspec() function suppresses them:


  if (fspec != *prev_fspec)


This only suppresses the headings if the inotify events are not
interleaved (case #2).

I am unsure how to fix this.


Best Regards,
-- 
Janne Snabb
snabb <at> epipe.com

Message #8 received at 23539 <at> debbugs.gnu.org (full text, mbox):

From: Janne Snabb <snabb <at> epipe.com>
To: 23539 <at> debbugs.gnu.org
Subject: bug#23539: tail -f file name headings displayed too many times after
 suspend
Date: Sun, 15 May 2016 02:06:02 +0300

[Message part 1 (text/plain, inline)]

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.

-- 
Janne Snabb
snabb <at> epipe.com

[tail-f-inotify-excess-header-output.patch (text/x-patch, attachment)]

Message #11 received at 23539 <at> debbugs.gnu.org (full text, mbox):

From: Pádraig Brady <P <at> draigBrady.com>
To: Janne Snabb <snabb <at> epipe.com>, 23539 <at> debbugs.gnu.org
Subject: Re: bug#23539: tail -f file name headings displayed too many times
 after suspend
Date: Fri, 20 May 2016 13:08:12 +0100

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

I suppose you could track the header_outputted state in each File_spec?

thanks!
Pádraig

Message #14 received at 23539 <at> debbugs.gnu.org (full text, mbox):

From: Pádraig Brady <P <at> draigBrady.com>
To: Janne Snabb <snabb <at> epipe.com>, 23539 <at> debbugs.gnu.org
Subject: Re: bug#23539: tail -f file name headings displayed too many times
 after suspend
Date: Mon, 6 Feb 2017 23:42:27 -0800

[Message part 1 (text/plain, inline)]

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

[tail-suspend.patch (text/x-patch, attachment)]

Message #17 received at 23539 <at> debbugs.gnu.org (full text, mbox):

From: Bernhard Voelker <mail <at> bernhard-voelker.de>
To: Pádraig Brady <P <at> draigBrady.com>,
 Janne Snabb <snabb <at> epipe.com>, 23539 <at> debbugs.gnu.org
Subject: Re: bug#23539: tail -f file name headings displayed too many times
 after suspend
Date: Wed, 8 Feb 2017 08:53:47 +0100

On 02/07/2017 08:42 AM, Pádraig Brady wrote:
> I'll push in your name tomorrow.

+1

Thanks & have a nice day,
Berny

Previous Next

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