bin/54514: script(1) sometimes swallows last line(s) of output

[logix%foobar.franken.de@localhost]

>Number:         54514
>Category:       bin
>Synopsis:       script(1) sometimes swallows last line(s) of output
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    bin-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Fri Aug 30 19:40:00 +0000 2019
>Originator:     Harold Gutch
>Release:        8.0
>Organization:
>Environment:
NetBSD localhost 8.0 NetBSD 8.0 (GENERIC) #0: Tue Jul 17 14:59:51 UTC 2018  mkrepro%mkrepro.NetBSD.org@localhost:/usr/src/sys/arch/amd64/compile/GENERIC amd64
>Description:
script(1) can terminate before the last few lines of output are printed and dumped to the logfile.  The reason is that the script process handling output and writing to file might receive a SIGCHLD and terminate before finishing its job.
>How-To-Repeat:
This is non-deterministic, but in my tests (see "Fix") I got wrong output depending on the exact test script ~30%-70% of the time.


% cat > test.sh << EOF
? #!/bin/sh
? echo 1
? echo 2
? echo 3
? EOF
% chmod u+x test.sh
% ./test.sh
1
2
3
% script -c ./test.sh typescript
Script started, output file is typescript
1
Script done, output file is typescript
% cat typescript
Script started on Fri Aug 30 21:16:26 2019
1

Script done on Fri Aug 30 21:16:26 2019
%
>Fix:
Inspired by OpenBSD ( http://cvsweb.openbsd.org/cgi-bin/cvsweb/src/usr.bin/script/script.c.diff?r1=1.26&r2=1.27 ):

-Index: script.c
===================================================================
RCS file: /usr/cvs/netbsd/src/usr.bin/script/script.c,v
retrieving revision 1.21
diff -u -p -r1.21 script.c
--- src/usr.bin/script/script.c	6 Sep 2011 18:29:56 -0000	1.21
+++ src/usr.bin/script/script.c	30 Aug 2019 21:22:48 -0000
@@ -166,7 +166,6 @@ main(int argc, char *argv[])
 	rtt.c_lflag &= ~ECHO;
 	(void)tcsetattr(STDIN_FILENO, TCSAFLUSH, &rtt);
 
-	(void)signal(SIGCHLD, finish);
 	child = fork();
 	if (child < 0) {
 		warn("fork");
@@ -183,6 +182,7 @@ main(int argc, char *argv[])
 		else
 			doshell(command);
 	}
+	(void)signal(SIGCHLD, finish);
 
 	if (!rawout)
 		(void)fclose(fscript);
@@ -226,6 +226,7 @@ dooutput(void)
 		(void)fprintf(fscript, "Script started on %s", ctime(&tvec));
 
 	(void)signal(SIGALRM, scriptflush);
+	(void)signal(SIGCHLD, SIG_IGN);
 	value.it_interval.tv_sec = SECSPERMIN / 2;
 	value.it_interval.tv_usec = 0;
 	value.it_value = value.it_interval;


Result:
1) without patch:
$ for i in `jot 100`; do script -c ./test.sh typescript.${i}; done
[...]
$ wc -l typescript.* | awk '/typescript/{print $1}' | sort | uniq -c
  71 4
  29 6

===> only in 29 out of 100 runs the output contained 6 lines (1 line header, 3 lines regular output, 1 new line, 1 line footer)

2) with patch:
$ for i in `jot 100`; do ./script -c ./test.sh typescript.${i}; done
[...]
$ wc -l typescript.* | awk '/typescript/{print $1}' | sort | uniq -c
 100 6

===> every run contained the expected 6 lines