linux-next fsnotify mod breaks tail -f

linux-next fsnotify mod breaks tail -f

[Hugh Dickins]

Hi Jan, Amir,

There's something wrong with linux-next commit ca7fbf0d29ab
("fsnotify: fix events reported to watching parent and child").

If I revert that commit, no problem;
but here's a one-line script "tailed":

for i in 1 2 3 4 5; do date; sleep 1; done &

Then if I run that (same result doing ./tailed after chmod a+x):

sh tailed >log; tail -f log

the "tail -f log" behaves in one of three ways:

1) On a console, before graphical screen, no problem,
   it shows the five lines coming from "date" as you would expect.
2) From xterm or another tty, shows just the first line from date,
   but after I wait and Ctrl-C out, "cat log" shows all five lines.
3) From xterm or another tty, doesn't even show that first line.

The before/after graphical screen thing seems particularly weird:
I expect you'll end up with a simpler explanation for what's
causing that difference.

tailed and log are on ext4, if that's relevant;
ah, I just tried on tmpfs, and saw no problem there.

CONFIG_FSNOTIFY=y
CONFIG_DNOTIFY=y
CONFIG_INOTIFY_USER=y
CONFIG_FANOTIFY=y

Hugh

Re: linux-next fsnotify mod breaks tail -f

[Amir Goldstein]

[-- Attachment #1: Type: text/plain, Size: 2154 bytes --]

On Fri, Dec 11, 2020 at 1:45 AM Hugh Dickins <hughd@google.com> wrote:
>
> Hi Jan, Amir,
>
> There's something wrong with linux-next commit ca7fbf0d29ab
> ("fsnotify: fix events reported to watching parent and child").
>
> If I revert that commit, no problem;
> but here's a one-line script "tailed":
>
> for i in 1 2 3 4 5; do date; sleep 1; done &
>
> Then if I run that (same result doing ./tailed after chmod a+x):
>
> sh tailed >log; tail -f log
>
> the "tail -f log" behaves in one of three ways:
>
> 1) On a console, before graphical screen, no problem,
>    it shows the five lines coming from "date" as you would expect.
> 2) From xterm or another tty, shows just the first line from date,
>    but after I wait and Ctrl-C out, "cat log" shows all five lines.
> 3) From xterm or another tty, doesn't even show that first line.
>
> The before/after graphical screen thing seems particularly weird:
> I expect you'll end up with a simpler explanation for what's
> causing that difference.
>
> tailed and log are on ext4, if that's relevant;
> ah, I just tried on tmpfs, and saw no problem there.

Nice riddle Hugh :)
Thanks for this early testing!

I was able to reproduce this.
The outcome does not depend on the type of terminal or filesystem
it depends on the existence of a watch on the parent dir of the log file.
Running ' inotifywait -m . &' will stop tail from getting notifications:

echo > log
tail -f log &
sleep 1
echo "can you see this?" >> log
inotifywait -m . &
sleep 1
echo "how about this?" >> log
kill $(jobs -p)

I suppose with a graphical screen you have systemd or other services
in the system watching the logs/home dir in your test env.

Attached fix patch. I suppose Jan will want to sqhash it.

We missed a subtle logic change in the switch from inode/child marks
to parent/inode marks terminology.

Before the change (!inode_mark && child_mark) meant that name
was not NULL and should be discarded (which the old code did).
After the change (!parent_mark && inode_mark) is not enough to
determine if name should be discarded (it should be discarded only
for "events on child"), so another check is needed.

Thanks,
Amir.

[-- Attachment #2: fsnotify-fix-for-fix-events-reported-to-watching-parent-and-child.patch.txt --]
[-- Type: text/plain, Size: 1276 bytes --]

From c7ea57c66c8c9f9607928bf7c55fc409eecc3e57 Mon Sep 17 00:00:00 2001
From: Amir Goldstein <amir73il@gmail.com>
Date: Fri, 11 Dec 2020 10:19:36 +0200
Subject: [PATCH] fsnotify: fix for fix events reported to watching parent and
 child

The child watch is expecting an event without file name and without
the ON_CHILD flag.

Reported-by: Hugh Dickins <hughd@google.com>
Signed-off-by: Amir Goldstein <amir73il@gmail.com>
---
 fs/notify/fsnotify.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/fs/notify/fsnotify.c b/fs/notify/fsnotify.c
index a0da9e766992..30d422b8c0fc 100644
--- a/fs/notify/fsnotify.c
+++ b/fs/notify/fsnotify.c
@@ -291,13 +291,18 @@ static int fsnotify_handle_event(struct fsnotify_group *group, __u32 mask,
 		}
 		if (!inode_mark)
 			return 0;
+	}
 
+	if (mask & FS_EVENT_ON_CHILD) {
 		/*
 		 * Some events can be sent on both parent dir and child marks
 		 * (e.g. FS_ATTRIB).  If both parent dir and child are
 		 * watching, report the event once to parent dir with name (if
 		 * interested) and once to child without name (if interested).
+		 * The child watcher is expecting an event without a file name
+		 * and without the FS_EVENT_ON_CHILD flag.
 		 */
+		mask &= ~FS_EVENT_ON_CHILD;
 		dir = NULL;
 		name = NULL;
 	}
-- 
2.25.1

Re: linux-next fsnotify mod breaks tail -f

[Jan Kara]

On Fri 11-12-20 10:42:16, Amir Goldstein wrote:
> On Fri, Dec 11, 2020 at 1:45 AM Hugh Dickins <hughd@google.com> wrote:
> >
> > Hi Jan, Amir,
> >
> > There's something wrong with linux-next commit ca7fbf0d29ab
> > ("fsnotify: fix events reported to watching parent and child").
> >
> > If I revert that commit, no problem;
> > but here's a one-line script "tailed":
> >
> > for i in 1 2 3 4 5; do date; sleep 1; done &
> >
> > Then if I run that (same result doing ./tailed after chmod a+x):
> >
> > sh tailed >log; tail -f log
> >
> > the "tail -f log" behaves in one of three ways:
> >
> > 1) On a console, before graphical screen, no problem,
> >    it shows the five lines coming from "date" as you would expect.
> > 2) From xterm or another tty, shows just the first line from date,
> >    but after I wait and Ctrl-C out, "cat log" shows all five lines.
> > 3) From xterm or another tty, doesn't even show that first line.
> >
> > The before/after graphical screen thing seems particularly weird:
> > I expect you'll end up with a simpler explanation for what's
> > causing that difference.
> >
> > tailed and log are on ext4, if that's relevant;
> > ah, I just tried on tmpfs, and saw no problem there.
> 
> Nice riddle Hugh :)
> Thanks for this early testing!
> 
> I was able to reproduce this.
> The outcome does not depend on the type of terminal or filesystem
> it depends on the existence of a watch on the parent dir of the log file.
> Running ' inotifywait -m . &' will stop tail from getting notifications:
> 
> echo > log
> tail -f log &
> sleep 1
> echo "can you see this?" >> log
> inotifywait -m . &
> sleep 1
> echo "how about this?" >> log
> kill $(jobs -p)
> 
> I suppose with a graphical screen you have systemd or other services
> in the system watching the logs/home dir in your test env.
> 
> Attached fix patch. I suppose Jan will want to sqhash it.
> 
> We missed a subtle logic change in the switch from inode/child marks
> to parent/inode marks terminology.
> 
> Before the change (!inode_mark && child_mark) meant that name
> was not NULL and should be discarded (which the old code did).
> After the change (!parent_mark && inode_mark) is not enough to
> determine if name should be discarded (it should be discarded only
> for "events on child"), so another check is needed.

Thanks for testing Hugh and for a quick fix Amir! I've folded it into the
original buggy commit.

								Honza

> 
> Thanks,
> Amir.

> From c7ea57c66c8c9f9607928bf7c55fc409eecc3e57 Mon Sep 17 00:00:00 2001
> From: Amir Goldstein <amir73il@gmail.com>
> Date: Fri, 11 Dec 2020 10:19:36 +0200
> Subject: [PATCH] fsnotify: fix for fix events reported to watching parent and
>  child
> 
> The child watch is expecting an event without file name and without
> the ON_CHILD flag.
> 
> Reported-by: Hugh Dickins <hughd@google.com>
> Signed-off-by: Amir Goldstein <amir73il@gmail.com>
> ---
>  fs/notify/fsnotify.c | 5 +++++
>  1 file changed, 5 insertions(+)
> 
> diff --git a/fs/notify/fsnotify.c b/fs/notify/fsnotify.c
> index a0da9e766992..30d422b8c0fc 100644
> --- a/fs/notify/fsnotify.c
> +++ b/fs/notify/fsnotify.c
> @@ -291,13 +291,18 @@ static int fsnotify_handle_event(struct fsnotify_group *group, __u32 mask,
>  		}
>  		if (!inode_mark)
>  			return 0;
> +	}
>  
> +	if (mask & FS_EVENT_ON_CHILD) {
>  		/*
>  		 * Some events can be sent on both parent dir and child marks
>  		 * (e.g. FS_ATTRIB).  If both parent dir and child are
>  		 * watching, report the event once to parent dir with name (if
>  		 * interested) and once to child without name (if interested).
> +		 * The child watcher is expecting an event without a file name
> +		 * and without the FS_EVENT_ON_CHILD flag.
>  		 */
> +		mask &= ~FS_EVENT_ON_CHILD;
>  		dir = NULL;
>  		name = NULL;
>  	}
> -- 
> 2.25.1
> 

-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: linux-next fsnotify mod breaks tail -f

[Amir Goldstein]

On Fri, Dec 11, 2020 at 12:47 PM Jan Kara <jack@suse.cz> wrote:
>
> On Fri 11-12-20 10:42:16, Amir Goldstein wrote:
> > On Fri, Dec 11, 2020 at 1:45 AM Hugh Dickins <hughd@google.com> wrote:
> > >
> > > Hi Jan, Amir,
> > >
> > > There's something wrong with linux-next commit ca7fbf0d29ab
> > > ("fsnotify: fix events reported to watching parent and child").
> > >
> > > If I revert that commit, no problem;
> > > but here's a one-line script "tailed":
> > >
> > > for i in 1 2 3 4 5; do date; sleep 1; done &
> > >
> > > Then if I run that (same result doing ./tailed after chmod a+x):
> > >
> > > sh tailed >log; tail -f log
> > >
> > > the "tail -f log" behaves in one of three ways:
> > >
> > > 1) On a console, before graphical screen, no problem,
> > >    it shows the five lines coming from "date" as you would expect.
> > > 2) From xterm or another tty, shows just the first line from date,
> > >    but after I wait and Ctrl-C out, "cat log" shows all five lines.
> > > 3) From xterm or another tty, doesn't even show that first line.
> > >
> > > The before/after graphical screen thing seems particularly weird:
> > > I expect you'll end up with a simpler explanation for what's
> > > causing that difference.
> > >
> > > tailed and log are on ext4, if that's relevant;
> > > ah, I just tried on tmpfs, and saw no problem there.
> >
> > Nice riddle Hugh :)
> > Thanks for this early testing!
> >
> > I was able to reproduce this.
> > The outcome does not depend on the type of terminal or filesystem
> > it depends on the existence of a watch on the parent dir of the log file.
> > Running ' inotifywait -m . &' will stop tail from getting notifications:
> >
> > echo > log
> > tail -f log &
> > sleep 1
> > echo "can you see this?" >> log
> > inotifywait -m . &
> > sleep 1
> > echo "how about this?" >> log
> > kill $(jobs -p)
> >
> > I suppose with a graphical screen you have systemd or other services
> > in the system watching the logs/home dir in your test env.
> >
> > Attached fix patch. I suppose Jan will want to sqhash it.
> >
> > We missed a subtle logic change in the switch from inode/child marks
> > to parent/inode marks terminology.
> >
> > Before the change (!inode_mark && child_mark) meant that name
> > was not NULL and should be discarded (which the old code did).
> > After the change (!parent_mark && inode_mark) is not enough to
> > determine if name should be discarded (it should be discarded only
> > for "events on child"), so another check is needed.
>
> Thanks for testing Hugh and for a quick fix Amir! I've folded it into the
> original buggy commit.
>

Test for original commit [1] extended to cover this bug as well:
Test #1: Group with child watches and other group with parent watch

Cheers,
Amir.

[1] https://github.com/amir73il/ltp/commits/fsnotify-fixes

Re: linux-next fsnotify mod breaks tail -f

[Hugh Dickins]

On Fri, 11 Dec 2020, Amir Goldstein wrote:
> On Fri, Dec 11, 2020 at 1:45 AM Hugh Dickins <hughd@google.com> wrote:
> >
> > Hi Jan, Amir,
> >
> > There's something wrong with linux-next commit ca7fbf0d29ab
> > ("fsnotify: fix events reported to watching parent and child").
> >
> > If I revert that commit, no problem;
> > but here's a one-line script "tailed":
> >
> > for i in 1 2 3 4 5; do date; sleep 1; done &
> >
> > Then if I run that (same result doing ./tailed after chmod a+x):
> >
> > sh tailed >log; tail -f log
> >
> > the "tail -f log" behaves in one of three ways:
> >
> > 1) On a console, before graphical screen, no problem,
> >    it shows the five lines coming from "date" as you would expect.
> > 2) From xterm or another tty, shows just the first line from date,
> >    but after I wait and Ctrl-C out, "cat log" shows all five lines.
> > 3) From xterm or another tty, doesn't even show that first line.
> >
> > The before/after graphical screen thing seems particularly weird:
> > I expect you'll end up with a simpler explanation for what's
> > causing that difference.
> >
> > tailed and log are on ext4, if that's relevant;
> > ah, I just tried on tmpfs, and saw no problem there.
> 
> Nice riddle Hugh :)
> Thanks for this early testing!
> 
> I was able to reproduce this.

Oh good!

> The outcome does not depend on the type of terminal or filesystem
> it depends on the existence of a watch on the parent dir of the log file.
> Running ' inotifywait -m . &' will stop tail from getting notifications:
> 
> echo > log
> tail -f log &
> sleep 1
> echo "can you see this?" >> log
> inotifywait -m . &
> sleep 1
> echo "how about this?" >> log
> kill $(jobs -p)
> 
> I suppose with a graphical screen you have systemd or other services
> in the system watching the logs/home dir in your test env.

And great answer to the riddle, Amir: yes, I was testing in
my home directory all the time, except when I tried tmpfs.

> 
> Attached fix patch. I suppose Jan will want to sqhash it.

Yes, I confirm that "tail -f" is back to normal for me
with this fix. Thank you both.

Hugh

> 
> We missed a subtle logic change in the switch from inode/child marks
> to parent/inode marks terminology.
> 
> Before the change (!inode_mark && child_mark) meant that name
> was not NULL and should be discarded (which the old code did).
> After the change (!parent_mark && inode_mark) is not enough to
> determine if name should be discarded (it should be discarded only
> for "events on child"), so another check is needed.
> 
> Thanks,
> Amir.