Re: [PATCH v2 3/5] generic/591: remove redundant output from golden image

["Darrick J. Wong" <djwong@kernel.org>]

On Wed, Jun 01, 2022 at 02:37:28PM +0800, Zorro Lang wrote:
> In generic/591.out expects below output:
>   concurrent reader with O_DIRECT
>   concurrent reader with O_DIRECT     <=== ???
>   concurrent reader without O_DIRECT
>   concurrent reader without O_DIRECT  <=== ???
>   sequential reader with O_DIRECT
>   sequential reader without O_DIRECT
> 
> The lines marked "???" are unbelievable, due to the src/splice-test.c
> only calls printf to output that message once in main function. So
> Why splice-test prints that message twice sometimes? It seems related
> with the "-r" option, due to the test lines without "-r" option only
> print one line each time running.
> 
> A stanger thing is this "double output" issue only can be triggered by
> running g/591, can't reproduce it by running splice-test manually.
> 
> By checking the code of splice-test.c, I found a "fork()" in it, and
> it'll be called if the '-r' option is specified. So I suspect the
> redundant output come from the child process. By the help of strace
> tool, I got:
> 
>   10554 execve("/root/git/xfstests/src/splice-test", ["/root/git/xfstests/src/splice-te"..., "-r", "/mnt/test/a"], 0x7ffcabc2c0a8 /* 202 vars */) = 0
>   ...
>   10554 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f937f5d5a10) = 10555
>   ...
>   10555 read(4, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"..., 512) = 512
>   10555 write(1, "concurrent reader with O_DIRECT\n", 32) = 32
>   10555 exit_group(0)                     = ?
>   10555 +++ exited with 0 +++
>   10554 <... wait4 resumed>NULL, 0, NULL) = 10555
>   10554 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=10555, si_uid=0, si_status=0, si_utime=0, si_stime=1} ---
>   10554 unlink("/mnt/test/a")             = 0
>   10554 write(1, "concurrent reader with O_DIRECT\n", 32) = 32
>   10554 exit_group(0)                     = ?
>   10554 +++ exited with 0 +++
> 
> We can see the "concurrent reader with O_DIRECT\n" be printed by
> parent process 10554 and child process 10555 separately.
> 
> Due to the stdout redirection that fstests does cause the stream
> doesn't refer to a tty anymore, then the stdout become block
> buffered, so the '\n' doesn't help to flush that printf message,
> and the child print it again.
> 
> So use setlinebuf(stdout) to force it line buffered, to avoid the
> confused output to be golden image. Then correct the generic/591.out

Eww, so the printf ends up in the output buffer, which is then
duplicated in the forked child, so both parent and child emit the same
message?

Gross.

Reviewed-by: Darrick J. Wong <djwong@kernel.org>

--D


> Signed-off-by: Zorro Lang <zlang@kernel.org>
> ---
>  src/splice-test.c     | 2 ++
>  tests/generic/591.out | 2 --
>  2 files changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/src/splice-test.c b/src/splice-test.c
> index 2f1ba2ba..dc41b0f5 100644
> --- a/src/splice-test.c
> +++ b/src/splice-test.c
> @@ -140,6 +140,8 @@ int main(int argc, char *argv[])
>  		usage(argv[0]);
>  	filename = argv[optind];
>  
> +	/* force below printf line buffered */
> +	setlinebuf(stdout);
>  	printf("%s reader %s O_DIRECT\n",
>  		   do_splice == do_splice1 ? "sequential" : "concurrent",
>  		   (open_flags & O_DIRECT) ? "with" : "without");
> diff --git a/tests/generic/591.out b/tests/generic/591.out
> index d61811ee..e9fffd1d 100644
> --- a/tests/generic/591.out
> +++ b/tests/generic/591.out
> @@ -1,7 +1,5 @@
>  QA output created by 591
>  concurrent reader with O_DIRECT
> -concurrent reader with O_DIRECT
> -concurrent reader without O_DIRECT
>  concurrent reader without O_DIRECT
>  sequential reader with O_DIRECT
>  sequential reader without O_DIRECT
> -- 
> 2.31.1
>