Imported Upstream version 2.03.22upstream/libdevmapper-1.02.196upstream/2.03.22upstreamsandbox/klewandowski/upstream_2.03.22

1 files changed, 345 insertions, 86 deletions

diff --git a/test/lib/harness.c b/test/lib/harness.c
index 929bfc8..a97f5db 100644
--- a/test/lib/harness.c
+++ b/test/lib/harness.c
@@ -1,5 +1,5 @@
 /*
- * Copyright (C) 2010-2012 Red Hat, Inc. All rights reserved.
+ * Copyright (C) 2010-2013 Red Hat, Inc. All rights reserved.
  *
  * This file is part of LVM2.
  *
@@ -9,24 +9,33 @@
  *
  * You should have received a copy of the GNU General Public License
  * along with this program; if not, write to the Free Software Foundation,
- * Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
  */
 
-#define _GNU_SOURCE
+#include <errno.h>
 #include <fcntl.h>
-#include <string.h>
+#include <limits.h>
 #include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <sys/klog.h>
+#include <sys/resource.h> /* rusage */
+#include <sys/select.h>
 #include <sys/socket.h>
+#include <sys/stat.h>
+#include <sys/time.h>
+#include <sys/types.h>
 #include <sys/wait.h>
-#include <unistd.h>
-#include <stdlib.h>
 #include <time.h>
-#include <sys/time.h>
+#include <unistd.h>
+#include <stdint.h>
 
 static pid_t pid;
 static int fds[2];
 
 #define MAX 1024
+#define MAX_LOG_SIZE (32*1024*1024) /* Default max size of test log */
+#define WRITE_TIMEOUT (180 * 2)	/* 3 minutes */
 
 struct stats {
 	int nfailed;
@@ -34,17 +43,28 @@ struct stats {
 	int npassed;
 	int nknownfail;
 	int nwarned;
+	int ninterrupted;
 	int status[MAX];
 };
 
 static struct stats s;
 
 static char *readbuf = NULL;
-static int readbuf_sz = 0, readbuf_used = 0;
+static size_t readbuf_sz = 0, readbuf_used = 0;
 
 static int die = 0;
 static int verbose = 0; /* >1 with timestamps */
 static int interactive = 0; /* disable all redirections */
+static int quiet = 0;
+static const char *results;
+static unsigned fullbuffer = 0;
+static int unlimited = 0;
+static int write_timeout = WRITE_TIMEOUT;
+
+static time_t harness_start;
+
+static FILE *outfile = NULL;
+char testdirdebug[PATH_MAX];
 
 struct subst {
 	const char *key;
@@ -53,19 +73,24 @@ struct subst {
 
 static struct subst subst[2];
 
-#define PASSED 0
-#define SKIPPED 1
-#define FAILED 2
-#define WARNED 3
-#define KNOWNFAIL 4
+enum {
+	UNKNOWN,
+	FAILED,
+	INTERRUPTED,
+	KNOWNFAIL,
+	PASSED,
+	SKIPPED,
+	TIMEOUT,
+	WARNED,
+};
 
 static void handler( int sig ) {
 	signal( sig, SIG_DFL );
-	kill( pid, sig );
+	kill( -pid, sig );
 	die = sig;
 }
 
-static int outline(char *buf, int start, int force) {
+static int outline(FILE *out, char *buf, int start, int force) {
 	char *from = buf + start;
 	char *next = strchr(buf + start, '\n');
 
@@ -79,9 +104,12 @@ static int outline(char *buf, int start, int force) {
 
 	if (!strncmp(from, "@TESTDIR=", 9)) {
 		subst[0].key = "@TESTDIR@";
+		free(subst[0].value);
 		subst[0].value = strndup(from + 9, next - from - 9 - 1);
+		snprintf(testdirdebug, sizeof(testdirdebug), "%s/debug.log", subst[0].value);
 	} else if (!strncmp(from, "@PREFIX=", 8)) {
 		subst[1].key = "@PREFIX@";
+		free(subst[1].value);
 		subst[1].value = strndup(from + 8, next - from - 8 - 1);
 	} else {
 		char *line = strndup(from, next - from);
@@ -100,11 +128,11 @@ static int outline(char *buf, int start, int force) {
 					}
 				}
 			}
-			fwrite(a, 1, b - a, stdout);
+			fwrite(a, 1, b - a, out);
 			a = b;
 
 			if ( idx >= 0 ) {
-				fprintf(stdout, "%s", subst[idx].key);
+				fprintf(out, "%s", subst[idx].key);
 				a += strlen(subst[idx].value);
 			}
 		} while (b < line + strlen(line));
@@ -117,27 +145,26 @@ static int outline(char *buf, int start, int force) {
 static void dump(void) {
 	int counter_last = -1, counter = 0;
 
-	while ( counter < readbuf_used && counter != counter_last ) {
+	while ((counter < (int) readbuf_used) && (counter != counter_last)) {
 		counter_last = counter;
-		counter = outline( readbuf, counter, 1 );
+		counter = outline( stdout, readbuf, counter, 1 );
 	}
 }
 
-static void trickle(void) {
-	static int counter_last = -1, counter = 0;
-
-	if (counter_last > readbuf_used) {
-		counter_last = -1;
-		counter = 0;
+static void trickle(FILE *out, int *last, int *counter) {
+	if (*last > (int) readbuf_used) {
+		*last = -1;
+		*counter = 0;
 	}
-	while ( counter < readbuf_used && counter != counter_last ) {
-		counter_last = counter;
-		counter = outline( readbuf, counter, 1 );
+	while ((*counter < (int) readbuf_used) && (*counter != *last)) {
+		*last = *counter;
+		*counter = outline( out, readbuf, *counter, 1 );
 	}
 }
 
 static void clear(void) {
 	readbuf_used = 0;
+	fullbuffer = 0;
 }
 
 static int64_t _get_time_us(void)
@@ -151,7 +178,12 @@ static int64_t _get_time_us(void)
 static void _append_buf(const char *buf, size_t len)
 {
 	if ((readbuf_used + len) >= readbuf_sz) {
-		readbuf_sz = readbuf_sz ? 2 * readbuf_sz : 4096;
+		if ((readbuf_sz >= MAX_LOG_SIZE) && !unlimited) {
+			if (fullbuffer++ ==  0)
+				kill(-pid, SIGINT);
+			return;
+		}
+		readbuf_sz = 2 * (readbuf_used + len + readbuf_sz);
 		readbuf = realloc(readbuf, readbuf_sz);
 	}
 
@@ -197,16 +229,19 @@ static const char *_append_with_stamp(const char *buf, int stamp)
 	return bb;
 }
 
-static void drain(void) {
-	char buf[4096];
+static int drain(int fd)
+{
+	char buf[2 * 1024 * 1024 + 1]; /* try to capture large sysrq trace */
 	const char *bp;
 	int stamp = 0;
 	int sz;
 
-	while ((sz = read(fds[1], buf, sizeof(buf) - 1)) > 0) {
+	static int stdout_last = -1, stdout_counter = 0;
+	static int outfile_last = -1, outfile_counter = 0;
+
+	if ((sz = read(fd, buf, sizeof(buf) - 1)) > 0) {
 		buf[sz] = '\0';
 		bp = (verbose < 2) ? buf : _append_with_stamp(buf, stamp);
-
 		if (sz > (bp - buf)) {
 			_append_buf(bp, sz - (bp - buf));
 			stamp = -1; /* unfinished line */
@@ -216,32 +251,91 @@ static void drain(void) {
 		readbuf[readbuf_used] = 0;
 
 		if (verbose)
-			trickle();
+			trickle(stdout, &stdout_last, &stdout_counter);
+		if (outfile)
+			trickle(outfile, &outfile_last, &outfile_counter);
 	}
+
+	return sz;
 }
 
-static const char *duration(time_t start)
+static int drain_fds(int fd1, int fd2, long timeout)
 {
-	static char buf[16];
+	return -1;
+}
+
+#define SYSLOG_ACTION_READ_CLEAR     4
+#define SYSLOG_ACTION_CLEAR          5
+
+static void clear_dmesg(void)
+{
+	klogctl(SYSLOG_ACTION_CLEAR, 0, 0);
+}
+
+static void drain_dmesg(void)
+{
+	char buf[1024 * 1024 + 1];
+	int sz = klogctl(SYSLOG_ACTION_READ_CLEAR, buf, sizeof(buf) - 1);
+	if (sz > 0) {
+		buf[sz] = 0;
+		_append_buf(buf, sz);
+	}
+}
+
+static const char *duration(time_t start, const struct rusage *usage)
+{
+	static char buf[100];
 	int t = (int)(time(NULL) - start);
 
-	sprintf(buf, "%2d:%02d", t / 60, t % 60);
+	int p = sprintf(buf, "%2d:%02d", t / 60, t % 60);
+
+	if (usage)
+		sprintf(buf + p, "   %2ld:%02ld.%03ld/%ld:%02ld.%03ld%5ld%8ld/%ld",
+			usage->ru_utime.tv_sec / 60, usage->ru_utime.tv_sec % 60,
+			usage->ru_utime.tv_usec / 1000,
+			usage->ru_stime.tv_sec / 60, usage->ru_stime.tv_sec % 60,
+			usage->ru_stime.tv_usec / 1000,
+			usage->ru_maxrss / 1024,
+			usage->ru_inblock, usage->ru_oublock);
+
 	return buf;
 }
 
-static void passed(int i, char *f, time_t t) {
+static void passed(int i, char *f, time_t t, const struct rusage *usage) {
 	if (readbuf && strstr(readbuf, "TEST EXPECT FAIL")) {
 		++ s.npassed;
 		s.status[i] = PASSED;
-		printf("passed (UNEXPECTED). %s\n", duration(t));
+		printf("passed (UNEXPECTED). %s\n", duration(t, usage));
 	} else if (readbuf && strstr(readbuf, "TEST WARNING")) {
 		++s.nwarned;
 		s.status[i] = WARNED;
-		printf("warnings  %s\n", duration(t));
+		printf("warnings  %s\n", duration(t, usage));
 	} else {
 		++ s.npassed;
 		s.status[i] = PASSED;
-		printf("passed.   %s\n", duration(t));
+		printf("passed.   %s\n", duration(t, usage));
+	}
+}
+
+static void interrupted(int i, char *f) {
+	++ s.ninterrupted;
+	s.status[i] = INTERRUPTED;
+	printf("\ninterrupted.\n");
+	if (!quiet && !verbose && fullbuffer) {
+		printf("-- Interrupted %s ------------------------------------\n", f);
+		dump();
+		printf("\n-- Interrupted %s (end) ------------------------------\n", f);
+	}
+}
+
+static void timeout(int i, char *f) {
+	++ s.ninterrupted;
+	s.status[i] = TIMEOUT;
+	printf("timeout.\n");
+	if (!quiet && !verbose && readbuf) {
+		printf("-- Timed out %s ------------------------------------\n", f);
+		dump();
+		printf("\n-- Timed out %s (end) ------------------------------\n", f);
 	}
 }
 
@@ -261,12 +355,8 @@ static void failed(int i, char *f, int st) {
 
 	++ s.nfailed;
 	s.status[i] = FAILED;
-	if(die == 2) {
-		printf("interrupted.\n");
-		return;
-	}
-	printf("FAILED.\n");
-	if (!verbose) {
+	printf("FAILED  (status %d).\n", WEXITSTATUS(st));
+	if (!quiet && !verbose && readbuf) {
 		printf("-- FAILED %s ------------------------------------\n", f);
 		dump();
 		printf("-- FAILED %s (end) ------------------------------\n", f);
@@ -274,59 +364,181 @@ static void failed(int i, char *f, int st) {
 }
 
 static void run(int i, char *f) {
+	struct rusage usage;
+	char flavour[512], script[512];
+
 	pid = fork();
 	if (pid < 0) {
 		perror("Fork failed.");
 		exit(201);
 	} else if (pid == 0) {
 		if (!interactive) {
-			close(0);
-			dup2(fds[0], 1);
-			dup2(fds[0], 2);
-			close(fds[0]);
+			close(STDIN_FILENO);
+			dup2(fds[1], STDOUT_FILENO);
+			dup2(fds[1], STDERR_FILENO);
 			close(fds[1]);
 		}
-		execlp("bash", "bash", f, NULL);
+		close(fds[0]);
+		if (strchr(f, ':')) {
+			strcpy(flavour, f);
+			*strchr(flavour, ':') = 0;
+			setenv("LVM_TEST_FLAVOUR", flavour, 1);
+			strcpy(script, strchr(f, ':') + 1);
+		} else {
+			strcpy(script, f);
+		}
+		setpgid(0, 0);
+		execlp("bash", "bash", "-noprofile", "-norc", script, NULL);
 		perror("execlp");
 		fflush(stderr);
 		_exit(202);
 	} else {
-		int st, w;
+		int st = -1, w;
 		time_t start = time(NULL);
 		char buf[128];
-		snprintf(buf, 128, "%s ...", f);
-		buf[127] = 0;
-		printf("Running %-50s ", buf);
+		char outpath[PATH_MAX];
+		char *c = outpath + strlen(results) + 1;
+		struct stat statbuf;
+		int runaway = 0;
+		int no_write = 0;
+		int clobber_dmesg = 0;
+		int collect_debug = 0;
+		int fd_debuglog = -1;
+		int fd_kmsg;
+		fd_set set;
+		int ret;
+
+		//close(fds[1]);
+		testdirdebug[0] = '\0'; /* Capture RUNTESTDIR */
+		snprintf(buf, sizeof(buf), "%s ...", f);
+		printf("Running %-60s%c", buf, verbose ? '\n' : ' ');
 		fflush(stdout);
-		while ((w = waitpid(pid, &st, WNOHANG)) == 0) {
-			drain();
-			usleep(20000);
+		snprintf(outpath, sizeof(outpath), "%s/%s.txt", results, f);
+		while ((c = strchr(c, '/')))
+			*c = '_';
+		if (!(outfile = fopen(outpath, "w")))
+			perror("fopen");
+
+		/* Mix-in kernel log message */
+		if ((fd_kmsg = open("/dev/kmsg", O_RDONLY | O_NONBLOCK)) < 0) {
+			if (errno != ENOENT) /* Older kernels (<3.5) do not support /dev/kmsg */
+				perror("open /dev/kmsg");
+		} else if (lseek(fd_kmsg, 0L, SEEK_END) == (off_t) -1)
+			perror("lseek /dev/kmsg");
+
+		if ((fd_kmsg < 0) &&
+		    (clobber_dmesg = strcmp(getenv("LVM_TEST_CAN_CLOBBER_DMESG") ? : "0", "0")))
+			clear_dmesg();
+
+		while ((w = wait4(pid, &st, WNOHANG, &usage)) == 0) {
+			struct timeval selectwait = { .tv_usec = 500000 }; /* 0.5s */
+
+			if ((fullbuffer && fullbuffer++ == 8000) ||
+			    (write_timeout > 0 && no_write > write_timeout)) 
+			{
+			timeout:
+				kill(pid, SIGINT);
+				sleep(5); /* wait a bit for a reaction */
+				if ((w = waitpid(pid, &st, WNOHANG)) == 0) {
+					if (write_timeout > 0 && no_write > write_timeout)
+						/*
+						 * Kernel traces needed, when stuck for
+						 * too long in userspace without producing
+						 * any output, in other case it should be
+						 * user space problem
+						 */
+						system("echo t > /proc/sysrq-trigger");
+					collect_debug = 1;
+					kill(-pid, SIGKILL);
+					w = pid; // waitpid(pid, &st, NULL);
+				}
+				runaway = 1;
+				break;
+			}
+
+			if (clobber_dmesg)
+				drain_dmesg();
+
+			FD_ZERO(&set);
+			FD_SET(fds[0], &set);
+			if (fd_kmsg >= 0)
+				FD_SET(fd_kmsg, &set);
+
+			if ((ret = select(fd_kmsg > fds[0] ? fd_kmsg + 1 : fds[0] + 1, &set, NULL, NULL, &selectwait)) <= 0) {
+				/* Still checking debug log size if it's not growing too much */
+				if (!unlimited && testdirdebug[0] &&
+				    (stat(testdirdebug, &statbuf) == 0) &&
+				    statbuf.st_size > 32 * 1024 * 1024) { /* 32MB command log size */
+					printf("Killing test since debug.log has gone wild (size %ld)\n",
+					       statbuf.st_size);
+					goto timeout;
+				}
+				no_write++;
+				continue;
+			}
+
+			if (FD_ISSET(fds[0], &set) && drain(fds[0]) > 0)
+				no_write = 0;
+			else if (fd_kmsg >= 0 && FD_ISSET(fd_kmsg, &set) && (drain(fd_kmsg) < 0)) {
+				close(fd_kmsg);
+				fd_kmsg = -1; /* Likely /dev/kmsg is not readable */
+				if ((clobber_dmesg = strcmp(getenv("LVM_TEST_CAN_CLOBBER_DMESG") ? : "0", "0")))
+					clear_dmesg();
+			}
 		}
 		if (w != pid) {
 			perror("waitpid");
 			exit(206);
 		}
-		drain();
-		if (WIFEXITED(st)) {
-			if (WEXITSTATUS(st) == 0) {
-				passed(i, f, start);
-			} else if (WEXITSTATUS(st) == 200) {
+
+		while (!fullbuffer && (drain_fds(fds[0], fd_kmsg, 0) > 0))
+			/* read out what was left */;
+
+		if (die == 2)
+			interrupted(i, f);
+		else if (runaway) {
+			if (collect_debug &&
+			    (fd_debuglog = open(testdirdebug, O_RDONLY)) != -1) {
+				runaway = unlimited ? INT32_MAX : 4 * 1024 * 1024;
+				while (!fullbuffer && runaway > 0 && (ret = drain(fd_debuglog)) > 0)
+					runaway -= ret;
+				close(fd_debuglog);
+			}
+			timeout(i, f);
+		} else if (WIFEXITED(st)) {
+			if (WEXITSTATUS(st) == 0)
+				passed(i, f, start, &usage);
+			else if (WEXITSTATUS(st) == 200)
 				skipped(i, f);
-			} else {
+			else
 				failed(i, f, st);
-			}
-		} else {
+		} else
 			failed(i, f, st);
-		}
+
+		if (fd_kmsg >= 0)
+			close(fd_kmsg);
+		else if (clobber_dmesg)
+			drain_dmesg();
+		if (outfile)
+			fclose(outfile);
+		if (fullbuffer)
+			printf("\nTest was interrupted, output has got too large (>%u) (loop:%u)\n"
+			       "Set LVM_TEST_UNLIMITED=1 for unlimited log.\n",
+			       (unsigned) readbuf_sz, fullbuffer);
 		clear();
 	}
 }
 
 int main(int argc, char **argv) {
+	char results_list[PATH_MAX];
+	const char *result;
 	const char *be_verbose = getenv("VERBOSE"),
-		   *be_interactive = getenv("INTERACTIVE");
+		   *be_interactive = getenv("INTERACTIVE"),
+		   *be_quiet = getenv("QUIET"),
+		   *be_write_timeout = getenv("WRITE_TIMEOUT");
 	time_t start = time(NULL);
 	int i;
+	FILE *list;
 
 	if (argc >= MAX) {
 		fprintf(stderr, "Sorry, my head exploded. Please increase MAX.\n");
@@ -339,55 +551,102 @@ int main(int argc, char **argv) {
 	if (be_interactive)
 		interactive = atoi(be_interactive);
 
+	if (be_quiet)
+		quiet = atoi(be_quiet);
+
+	if (be_write_timeout)
+		write_timeout = atoi(be_write_timeout) * 2;
+
+	results = getenv("LVM_TEST_RESULTS") ? : "results";
+	unlimited = getenv("LVM_TEST_UNLIMITED") ? 1 : 0;
+	(void) snprintf(results_list, sizeof(results_list), "%s/list", results);
+
+	//if (pipe(fds)) {
 	if (socketpair(PF_UNIX, SOCK_STREAM, 0, fds)) {
 		perror("socketpair");
 		return 201;
 	}
 
-        if ( fcntl( fds[1], F_SETFL, O_NONBLOCK ) == -1 ) {
+	if (fcntl(fds[0], F_SETFL, O_NONBLOCK ) == -1) {
 		perror("fcntl on socket");
 		return 202;
 	}
 
 	/* set up signal handlers */
-	for (i = 0; i <= 32; ++i) {
-		if (i == SIGCHLD || i == SIGWINCH || i == SIGURG)
-			continue;
-		signal(i, handler);
-	}
+	for (i = 0; i <= 32; ++i)
+		switch (i) {
+		case SIGCHLD: case SIGWINCH: case SIGURG:
+		case SIGKILL: case SIGSTOP: break;
+		default: signal(i, handler);
+		}
 
+	harness_start = time(NULL);
 	/* run the tests */
-	for (i = 1; i < argc; ++ i) {
+	for (i = 1; !die && i < argc; ++i) {
 		run(i, argv[i]);
-		if (die)
-			break;
+		if ( time(NULL) - harness_start > 48 * 360 ) { /* 04:48 */
+			printf("Nearly 5 hours passed, giving up...\n");
+			die = 1;
+		}
 	}
 
-	printf("\n## %d tests %s : %d OK, %d warnings, %d failures, %d known failures; %d skipped\n",
-	       s.nwarned + s.npassed + s.nfailed + s.nskipped,
-	       duration(start),
-	       s.npassed, s.nwarned, s.nfailed, s.nknownfail, s.nskipped);
+	free(subst[0].value);
+	free(subst[1].value);
+	free(readbuf);
+
+	printf("\n## %d tests %s : %d OK, %d warnings, %d failures (%d interrupted), %d known failures; "
+	       "%d skipped\n",
+	       s.nwarned + s.npassed + s.nfailed + s.nskipped + s.ninterrupted,
+	       duration(start, NULL),
+	       s.npassed, s.nwarned, s.nfailed + s.ninterrupted, s.ninterrupted,
+	       s.nknownfail, s.nskipped);
+
+	/* dump a list to results */
+	if ((list = fopen(results_list, "w"))) {
+		for (i = 1; i < argc; ++ i) {
+			switch (s.status[i]) {
+			case FAILED: result = "failed"; break;
+			case INTERRUPTED: result = "interrupted"; break;
+			case PASSED: result = "passed"; break;
+			case SKIPPED: result = "skipped"; break;
+			case TIMEOUT: result = "timeout"; break;
+			case WARNED: result = "warnings"; break;
+			default: result = "unknown"; break;
+			}
+			fprintf(list, "%s %s\n", argv[i], result);
+		}
+		fclose(list);
+	} else
+		perror("fopen result");
 
 	/* print out a summary */
-	if (s.nfailed || s.nskipped || s.nknownfail) {
+	if (s.nfailed || s.nskipped || s.nknownfail || s.ninterrupted || s.nwarned) {
 		for (i = 1; i < argc; ++ i) {
 			switch (s.status[i]) {
 			case FAILED:
 				printf("FAILED: %s\n", argv[i]);
 				break;
+			case INTERRUPTED:
+				printf("INTERRUPTED: %s\n", argv[i]);
+				break;
 			case KNOWNFAIL:
 				printf("FAILED (expected): %s\n", argv[i]);
 				break;
 			case SKIPPED:
 				printf("skipped: %s\n", argv[i]);
 				break;
+			case TIMEOUT:
+				printf("TIMEOUT: %s\n", argv[i]);
+				break;
+			case WARNED:
+				printf("WARNED: %s\n", argv[i]);
+				break;
+			default: /* do nothing */ ;
 			}
 		}
 		printf("\n");
-		return s.nfailed > 0 || die;
+		return (s.nfailed > 0) || (s.ninterrupted > 0) || die;
 	}
 
-	free(readbuf);
-
 	return die;
 }