/* * Copyright (C) 2010-2013 Red Hat, Inc. All rights reserved. * * This file is part of LVM2. * * This copyrighted material is made available to anyone wishing to use, * modify, copy, or redistribute it subject to the terms and conditions * of the GNU General Public License v.2. * * 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., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA */ #include #include #include #include #include #include #include #include /* rusage */ #include #include #include #include #include #include #include #include #include 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; int nskipped; int npassed; int nknownfail; int nwarned; int ninterrupted; int status[MAX]; }; static struct stats s; static char *readbuf = NULL; 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; char *value; }; static struct subst subst[2]; enum { UNKNOWN, FAILED, INTERRUPTED, KNOWNFAIL, PASSED, SKIPPED, TIMEOUT, WARNED, }; static void handler( int sig ) { signal( sig, SIG_DFL ); kill( -pid, sig ); die = sig; } static int outline(FILE *out, char *buf, int start, int force) { char *from = buf + start; char *next = strchr(buf + start, '\n'); if (!next && !force) /* not a complete line yet... */ return start; if (!next) next = from + strlen(from); else ++next; 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); char *a = line, *b; do { int idx = -1; int i; b = line + strlen(line); for ( i = 0; i < 2; ++i ) { if (subst[i].key) { // printf("trying: %s -> %s\n", subst[i].value, subst[i].key); char *stop = strstr(a, subst[i].value); if (stop && stop < b) { idx = i; b = stop; } } } fwrite(a, 1, b - a, out); a = b; if ( idx >= 0 ) { fprintf(out, "%s", subst[idx].key); a += strlen(subst[idx].value); } } while (b < line + strlen(line)); free(line); } return next - buf + (force ? 0 : 1); } static void dump(void) { int counter_last = -1, counter = 0; while ((counter < (int) readbuf_used) && (counter != counter_last)) { counter_last = counter; counter = outline( stdout, readbuf, counter, 1 ); } } static void trickle(FILE *out, int *last, int *counter) { if (*last > (int) readbuf_used) { *last = -1; *counter = 0; } 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) { struct timeval tv; (void) gettimeofday(&tv, 0); return (int64_t) tv.tv_sec * 1000000 + (int64_t) tv.tv_usec; } static void _append_buf(const char *buf, size_t len) { if ((readbuf_used + len) >= readbuf_sz) { 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); } if (!readbuf) exit(205); memcpy(readbuf + readbuf_used, buf, len); readbuf_used += len; } static const char *_append_with_stamp(const char *buf, int stamp) { static const char spaces[] = " "; static int64_t t_last; static int64_t t_start = 0; int64_t t_now; char stamp_buf[32]; /* Bigger to always fit both numbers */ const char *be; const char *bb = buf; size_t len; while ((be = strchr(bb, '\n'))) { if (stamp++ == 0) { t_now = _get_time_us(); if (!t_start) t_start = t_last = t_now; len = snprintf(stamp_buf, sizeof(stamp_buf), "%8.3f%8.4f ", (t_now - t_start) / 1000000.f, (t_now - t_last) / 1000000.f); _append_buf(stamp_buf, (len < (sizeof(spaces) - 1)) ? len : (sizeof(spaces) - 1)); t_last = t_now; } _append_buf(bb, be + 1 - bb); bb = be + 1; if (stamp > 0 && bb[0]) _append_buf(spaces, sizeof(spaces) - 1); } return bb; } 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; 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 */ } else stamp = 0; readbuf[readbuf_used] = 0; if (verbose) trickle(stdout, &stdout_last, &stdout_counter); if (outfile) trickle(outfile, &outfile_last, &outfile_counter); } return sz; } static int drain_fds(int fd1, int fd2, long timeout) { 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); 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, const struct rusage *usage) { if (readbuf && strstr(readbuf, "TEST EXPECT FAIL")) { ++ s.npassed; s.status[i] = PASSED; 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, usage)); } else { ++ s.npassed; s.status[i] = PASSED; 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); } } static void skipped(int i, char *f) { ++ s.nskipped; s.status[i] = SKIPPED; printf("skipped.\n"); } static void failed(int i, char *f, int st) { if (readbuf && strstr(readbuf, "TEST EXPECT FAIL")) { printf("FAILED (expected).\n"); s.status[i] = KNOWNFAIL; ++ s.nknownfail; return; } ++ s.nfailed; s.status[i] = FAILED; printf("FAILED (status %d).\n", WEXITSTATUS(st)); if (!quiet && !verbose && readbuf) { printf("-- FAILED %s ------------------------------------\n", f); dump(); printf("-- FAILED %s (end) ------------------------------\n", f); } } 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(STDIN_FILENO); dup2(fds[1], STDOUT_FILENO); dup2(fds[1], STDERR_FILENO); close(fds[1]); } 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 = -1, w; time_t start = time(NULL); char buf[128]; 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); 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 > " DEFAULT_PROC_DIR "/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); } 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 failed(i, f, st); } 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_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"); exit(1); } if (be_verbose) verbose = atoi(be_verbose); 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[0], F_SETFL, O_NONBLOCK ) == -1) { perror("fcntl on socket"); return 202; } /* set up signal handlers */ 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; !die && i < argc; ++i) { run(i, argv[i]); if ( time(NULL) - harness_start > 48 * 360 ) { /* 04:48 */ printf("Nearly 5 hours passed, giving up...\n"); die = 1; } } 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 || 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) || (s.ninterrupted > 0) || die; } return die; }