[ptest-runner][PATCH 0/5] Fix ptest timeout errors

[ptest-runner][PATCH 0/5] Fix ptest timeout errors

[Joshua Watt]

e50f217 ("Change test timeout to be total elapsed time") was misguided
in that the timeout is actually the timeout between receiving output
from the process and not the total test timeout. Fix this and also a few
other bugs that were noticed as being different between the old
ptest-runner and the new one.

Joshua Watt (5):
  Revert "Change test timeout to be total elapsed time"
  Only collect system state on timeout
  Report test failure on timeout
  Remove _child_reader singleton
  Flush stdout and stderr after test

 tests/data/hang/ptest/run-ptest |   1 -
 tests/utils.c                   |   2 +-
 utils.c                         | 179 +++++++++++++++-----------------
 3 files changed, 84 insertions(+), 98 deletions(-)

-- 
2.33.0

[ptest-runner][PATCH 1/5] Revert "Change test timeout to be total elapsed time"

[Joshua Watt]

This reverts commit e50f2175d9c6b8aeb8b0bf687e5cca64a0f6e61a.

The timeout is actually the amount of time to wait until there is no
output from the test, not the total test time.

Signed-off-by: Joshua Watt <JPEWhacker@gmail.com>
---
 tests/data/hang/ptest/run-ptest |  1 -
 tests/utils.c                   |  2 +-
 utils.c                         | 23 +++++++++++------------
 3 files changed, 12 insertions(+), 14 deletions(-)

diff --git a/tests/data/hang/ptest/run-ptest b/tests/data/hang/ptest/run-ptest
index 9031be3..738041d 100755
--- a/tests/data/hang/ptest/run-ptest
+++ b/tests/data/hang/ptest/run-ptest
@@ -3,6 +3,5 @@
 echo "hang" 1>&2
 echo "hang"
 while true; do
-	echo "hang"
 	sleep 1
 done
diff --git a/tests/utils.c b/tests/utils.c
index 849a412..d82b90e 100644
--- a/tests/utils.c
+++ b/tests/utils.c
@@ -224,7 +224,7 @@ search_for_timeout_and_duration(const int rp, FILE *fp_stdout)
 START_TEST(test_run_timeout_duration_ptest)
 {
 	struct ptest_list *head = get_available_ptests(opts_directory);
-	unsigned int timeout = 3;
+	unsigned int timeout = 1;
 
 	test_ptest_expected_failure(head, timeout, "hang", search_for_timeout_and_duration);
 
diff --git a/utils.c b/utils.c
index 353d6dc..34ca2f0 100644
--- a/utils.c
+++ b/utils.c
@@ -403,8 +403,7 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 	pid_t child;
 	int pipefd_stdout[2] = {-1, -1};
 	int pipefd_stderr[2] = {-1, -1};
-	time_t sttime, entime, now;
-	time_t timeout_deadline;
+	time_t sttime, entime;
 	time_t duration;
 	int slave;
 	int pgid = -1;
@@ -490,7 +489,6 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 				}
 
 				sttime = time(NULL);
-				timeout_deadline = sttime + opts.timeout;
 				fprintf(fp, "%s\n", get_stime(stime, GET_STIME_BUF_SIZE, sttime));
 				fprintf(fp, "BEGIN: %s\n", ptest_dir);
 
@@ -521,17 +519,18 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 					if (done) {
 						break;
 					}
-					now = time(NULL);
-					if (now >= timeout_deadline) {
-						kill(-child, SIGKILL);
-						_child_reader.timeouted = 1;
-						break;
-					}
 
-					int ret = poll(pfds, 2, (timeout_deadline - now) * 1000);
+					int ret = poll(pfds, 2, _child_reader.timeout*1000);
 
-					if (ret == 0) {
-						continue;
+					if (ret == 0 && !_child_reader.timeouted) {
+						/* kill the child if we haven't
+						 * already. Note that we
+						 * continue to read data from
+						 * the pipes until EOF to make
+						 * sure we get all the output
+						 */
+						kill(-child, SIGKILL);
+						_child_reader.timeouted = 1;
 					}
 
 					for (int i = 0; i < 2; i++) {
-- 
2.33.0

[ptest-runner][PATCH 2/5] Only collect system state on timeout

[Joshua Watt]

To match the behavior of the previous ptest-runner, only collect system
state when a test has timed out

Signed-off-by: Joshua Watt <JPEWhacker@gmail.com>
---
 utils.c | 25 +++++++++++--------------
 1 file changed, 11 insertions(+), 14 deletions(-)

diff --git a/utils.c b/utils.c
index 34ca2f0..d0e6a99 100644
--- a/utils.c
+++ b/utils.c
@@ -556,21 +556,18 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 						}
 					}
 				}
-				collect_system_state(_child_reader.fps[0]);
 
-				for (int i = 0; i < 2; i++) {
-					fflush(_child_reader.fps[i]);
-				}
-
-				/*
-				 * This kill is just in case the child did
-				 * something really silly like close its
-				 * stdout and stderr but then go into an
-				 * infinite loop and never exit. Normally, it
-				 * will just fail because the child is already
-				 * dead
-				 */
-				if (!_child_reader.timeouted) {
+				if (_child_reader.timeouted) {
+					collect_system_state(fp);
+				} else {
+					/*
+					 * This kill is just in case the child did
+					 * something really silly like close its
+					 * stdout and stderr but then go into an
+					 * infinite loop and never exit. Normally, it
+					 * will just fail because the child is already
+					 * dead
+					 */
 					kill(-child, SIGKILL);
 				}
 				waitpid(child, &status, 0);
-- 
2.33.0

[ptest-runner][PATCH 3/5] Report test failure on timeout

[Joshua Watt]

Even when a test times out, an "ERROR:" message should be printed so
that the OE selftest parser knows the test has failed.

Signed-off-by: Joshua Watt <JPEWhacker@gmail.com>
---
 utils.c | 27 ++++++++++++---------------
 1 file changed, 12 insertions(+), 15 deletions(-)

diff --git a/utils.c b/utils.c
index d0e6a99..aacf123 100644
--- a/utils.c
+++ b/utils.c
@@ -575,23 +575,20 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 				entime = time(NULL);
 				duration = entime - sttime;
 
-				int exit_code = 0;
-
-				if (!_child_reader.timeouted) {
-					if (WIFEXITED(status)) {
-						exit_code = WEXITSTATUS(status);
-						if (exit_code) {
-							fprintf(fp, "\nERROR: Exit status is %d\n", exit_code);
-							rc += 1;
-						}
-					} else if (WIFSIGNALED(status)) {
-						int signal = WTERMSIG(status);
-						fprintf(fp, "\nERROR: Exited from signal %s (%d)\n", strsignal(signal), signal);
-						rc += 1;
-					} else {
-						fprintf(fp, "\nERROR: Exited for unknown reason (%d)\n", status);
+				int exit_code = -1;
+				if (WIFEXITED(status)) {
+					exit_code = WEXITSTATUS(status);
+					if (exit_code) {
+						fprintf(fp, "\nERROR: Exit status is %d\n", exit_code);
 						rc += 1;
 					}
+				} else if (WIFSIGNALED(status)) {
+					int signal = WTERMSIG(status);
+					fprintf(fp, "\nERROR: Exited from signal %s (%d)\n", strsignal(signal), signal);
+					rc += 1;
+				} else {
+					fprintf(fp, "\nERROR: Exited for unknown reason (%d)\n", status);
+					rc += 1;
 				}
 				fprintf(fp, "DURATION: %d\n", (int) duration);
 				if (_child_reader.timeouted) {
-- 
2.33.0

[ptest-runner][PATCH 4/5] Remove _child_reader singleton

[Joshua Watt]

Instead of using the _child_reader singleton to track the child process,
use variables on the stack. Also, limit the variable scope as much as
possible and used named constants for the pipe indices.

Signed-off-by: Joshua Watt <JPEWhacker@gmail.com>
---
 utils.c | 108 +++++++++++++++++++++++++-------------------------------
 1 file changed, 48 insertions(+), 60 deletions(-)

diff --git a/utils.c b/utils.c
index aacf123..bd52544 100644
--- a/utils.c
+++ b/utils.c
@@ -55,14 +55,10 @@
 
 #define UNUSED(x) (void)(x)
 
-static struct {
-	int fds[2];
-	FILE *fps[2];
-
-	unsigned int timeout;
-	int timeouted;
-	int padding1;
-} _child_reader;
+enum {
+	PIPE_READ = 0,
+	PIPE_WRITE = 1,
+};
 
 static inline char *
 get_stime(char *stime, size_t size, time_t t)
@@ -398,15 +394,7 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 	FILE *xh = NULL;
 
 	struct ptest_list *p;
-	char stime[GET_STIME_BUF_SIZE];
 
-	pid_t child;
-	int pipefd_stdout[2] = {-1, -1};
-	int pipefd_stderr[2] = {-1, -1};
-	time_t sttime, entime;
-	time_t duration;
-	int slave;
-	int pgid = -1;
 
 	if (opts.xml_filename) {
 		xh = xml_create(ptest_list_length(head), opts.xml_filename);
@@ -423,12 +411,16 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 
 		fprintf(fp, "START: %s\n", progname);
 		PTEST_LIST_ITERATE_START(head, p)
+			int pipefd_stdout[2] = {-1, -1};
+			int pipefd_stderr[2] = {-1, -1};
+			int pgid = -1;
+
 			if ((rc = pipe2(pipefd_stdout, 0)) == -1)
 				break;
 
 			if ((rc = pipe2(pipefd_stderr, 0)) == -1) {
-				close(pipefd_stdout[0]);
-				close(pipefd_stdout[1]);
+				close(pipefd_stdout[PIPE_READ]);
+				close(pipefd_stdout[PIPE_WRITE]);
 				break;
 			}
 
@@ -443,16 +435,18 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 				fprintf(fp, "ERROR: getpgid() failed, %s\n", strerror(errno));
 			}
 
-			child = fork();
+			pid_t child = fork();
 			if (child == -1) {
 				fprintf(fp, "ERROR: Fork %s\n", strerror(errno));
 				rc = -1;
 				break;
 			} else if (child == 0) {
+				int slave;
+
 				close(0);
 				/* Close read ends of the pipe */
-				do_close(&pipefd_stdout[0]);
-				do_close(&pipefd_stderr[0]);
+				do_close(&pipefd_stdout[PIPE_READ]);
+				do_close(&pipefd_stderr[PIPE_READ]);
 
 				if ((slave = setup_slave_pty(fp)) < 0) {
 					fprintf(fp, "ERROR: could not setup pty (%d).", slave);
@@ -469,37 +463,35 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 					fprintf(fp, "ERROR: Unable to attach to controlling tty, %s\n", strerror(errno));
 				}
 
-				run_child(p->run_ptest, pipefd_stdout[1], pipefd_stderr[1]);
+				run_child(p->run_ptest, pipefd_stdout[PIPE_WRITE], pipefd_stderr[PIPE_WRITE]);
 
 			} else {
-				int status;
+				bool timedout = false;
+				char stime[GET_STIME_BUF_SIZE];
 
 				/* Close write ends of the pipe, otherwise this process will never get EOF when the child dies */
-				do_close(&pipefd_stdout[1]);
-				do_close(&pipefd_stderr[1]);
-
-				_child_reader.fds[0] = pipefd_stdout[0];
-				_child_reader.fds[1] = pipefd_stderr[0];
-				_child_reader.fps[0] = fp;
-				_child_reader.fps[1] = fp_stderr;
-				_child_reader.timeout = opts.timeout;
-				_child_reader.timeouted = 0;
+				do_close(&pipefd_stdout[PIPE_WRITE]);
+				do_close(&pipefd_stderr[PIPE_WRITE]);
+
 				if (setpgid(child, pgid) == -1) {
 					fprintf(fp, "ERROR: setpgid() failed, %s\n", strerror(errno));
 				}
 
-				sttime = time(NULL);
-				fprintf(fp, "%s\n", get_stime(stime, GET_STIME_BUF_SIZE, sttime));
+				time_t start_time= time(NULL);
+				fprintf(fp, "%s\n", get_stime(stime, GET_STIME_BUF_SIZE, start_time));
 				fprintf(fp, "BEGIN: %s\n", ptest_dir);
 
-				set_nonblocking(_child_reader.fds[0]);
-				set_nonblocking(_child_reader.fds[1]);
-
 				struct pollfd pfds[2];
-				for (int i = 0; i < 2; i++) {
-					pfds[i].fd = _child_reader.fds[i];
-					pfds[i].events = POLLIN;
-				}
+				FILE* dest_fps[2];
+				set_nonblocking(pipefd_stdout[PIPE_READ]);
+				pfds[0].fd = pipefd_stdout[PIPE_READ];
+				pfds[0].events = POLLIN;
+				dest_fps[0] = fp;
+
+				set_nonblocking(pipefd_stderr[PIPE_READ]);
+				pfds[1].fd = pipefd_stderr[PIPE_READ];
+				pfds[1].events = POLLIN;
+				dest_fps[1] = fp_stderr;
 
 				while (true) {
 					/*
@@ -520,9 +512,9 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 						break;
 					}
 
-					int ret = poll(pfds, 2, _child_reader.timeout*1000);
+					int ret = poll(pfds, 2, opts.timeout*1000);
 
-					if (ret == 0 && !_child_reader.timeouted) {
+					if (ret == 0 && !timedout) {
 						/* kill the child if we haven't
 						 * already. Note that we
 						 * continue to read data from
@@ -530,7 +522,7 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 						 * sure we get all the output
 						 */
 						kill(-child, SIGKILL);
-						_child_reader.timeouted = 1;
+						timedout = true;
 					}
 
 					for (int i = 0; i < 2; i++) {
@@ -551,13 +543,13 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 								}
 								continue;
 							} else {
-								fwrite(buf, (size_t)n, 1, _child_reader.fps[i]);
+								fwrite(buf, (size_t)n, 1, dest_fps[i]);
 							}
 						}
 					}
 				}
 
-				if (_child_reader.timeouted) {
+				if (timedout) {
 					collect_system_state(fp);
 				} else {
 					/*
@@ -570,10 +562,11 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 					 */
 					kill(-child, SIGKILL);
 				}
+				int status;
 				waitpid(child, &status, 0);
 
-				entime = time(NULL);
-				duration = entime - sttime;
+				time_t end_time = time(NULL);
+				time_t duration = end_time - start_time;
 
 				int exit_code = -1;
 				if (WIFEXITED(status)) {
@@ -591,30 +584,25 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 					rc += 1;
 				}
 				fprintf(fp, "DURATION: %d\n", (int) duration);
-				if (_child_reader.timeouted) {
+				if (timedout) {
 					fprintf(fp, "TIMEOUT: %s\n", ptest_dir);
 					rc += 1;
 				}
 
 				if (opts.xml_filename)
-					xml_add_case(xh, exit_code, ptest_dir, _child_reader.timeouted, (int) duration);
+					xml_add_case(xh, exit_code, ptest_dir, timedout, (int) duration);
 
 				fprintf(fp, "END: %s\n", ptest_dir);
-				fprintf(fp, "%s\n", get_stime(stime, GET_STIME_BUF_SIZE, entime));
+				fprintf(fp, "%s\n", get_stime(stime, GET_STIME_BUF_SIZE, end_time));
 			}
 			free(ptest_dir);
-			do_close(&pipefd_stdout[0]);
-			do_close(&pipefd_stdout[1]);
-			do_close(&pipefd_stderr[0]);
-			do_close(&pipefd_stderr[1]);
+			do_close(&pipefd_stdout[PIPE_READ]);
+			do_close(&pipefd_stdout[PIPE_WRITE]);
+			do_close(&pipefd_stderr[PIPE_READ]);
+			do_close(&pipefd_stderr[PIPE_WRITE]);
 
 		PTEST_LIST_ITERATE_END
 		fprintf(fp, "STOP: %s\n", progname);
-
-		do_close(&pipefd_stdout[0]);
-		do_close(&pipefd_stdout[1]);
-		do_close(&pipefd_stderr[0]);
-		do_close(&pipefd_stderr[1]);
 	} while (0);
 
 	if (rc == -1)
-- 
2.33.0

[ptest-runner][PATCH 5/5] Flush stdout and stderr after test

[Joshua Watt]

After reporting test results, flush the output buffers to ensure the
files are written out. Also flush again at the end of running all tests

Signed-off-by: Joshua Watt <JPEWhacker@gmail.com>
---
 utils.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/utils.c b/utils.c
index bd52544..59b8b77 100644
--- a/utils.c
+++ b/utils.c
@@ -601,6 +601,9 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 			do_close(&pipefd_stderr[PIPE_READ]);
 			do_close(&pipefd_stderr[PIPE_WRITE]);
 
+			fflush(fp);
+			fflush(fp_stderr);
+
 		PTEST_LIST_ITERATE_END
 		fprintf(fp, "STOP: %s\n", progname);
 	} while (0);
@@ -611,6 +614,9 @@ run_ptests(struct ptest_list *head, const struct ptest_options opts,
 	if (opts.xml_filename)
 		xml_finish(xh);
 
+	fflush(fp);
+	fflush(fp_stderr);
+
 	return rc;
 }
 
-- 
2.33.0