#include <ccan/hash/hash.h>
#include <ccan/htable/htable_type.h>
#include <ccan/str/str.h>
+#include <ccan/compiler/compiler.h>
enum failtest_result (*failtest_hook)(struct tlist_calls *);
-static int tracefd = -1;
-static int warnfd;
+static FILE *tracef = NULL, *warnf;
+static int traceindent = 0;
unsigned int failtest_timeout_ms = 20000;
static int control_fd = -1;
/* If we're a child, this is the first call we did ourselves. */
static struct failtest_call *our_history_start = NULL;
-/* For printing runtime with --tracepath. */
+/* For printing runtime with --trace. */
static struct timeval start;
/* Set when failtest_hook returns FAIL_PROBE */
static bool probing = false;
return ret;
}
-static void warn_via_fd(int e, const char *fmt, va_list ap)
+static void do_warn(int e, const char *fmt, va_list ap)
{
char *p = failpath_string();
- vdprintf(warnfd, fmt, ap);
+ vfprintf(warnf, fmt, ap);
if (e != -1)
- dprintf(warnfd, ": %s", strerror(e));
- dprintf(warnfd, " [%s]\n", p);
+ fprintf(warnf, ": %s", strerror(e));
+ fprintf(warnf, " [%s]\n", p);
free(p);
}
int e = errno;
va_start(ap, fmt);
- warn_via_fd(e, fmt, ap);
+ do_warn(e, fmt, ap);
va_end(ap);
}
va_list ap;
va_start(ap, fmt);
- warn_via_fd(-1, fmt, ap);
+ do_warn(-1, fmt, ap);
va_end(ap);
}
exit(1);
}
-static void trace(const char *fmt, ...)
+static void PRINTF_FMT(1, 2) trace(const char *fmt, ...)
{
va_list ap;
+ unsigned int i;
+ char *p;
+ static int idx;
- if (tracefd == -1)
+ if (!tracef)
return;
+ for (i = 0; i < traceindent; i++)
+ fprintf(tracef, " ");
+
+ p = failpath_string();
+ fprintf(tracef, "%i: %u: %s ", idx++, getpid(), p);
va_start(ap, fmt);
- vdprintf(tracefd, fmt, ap);
+ vfprintf(tracef, fmt, ap);
va_end(ap);
+ free(p);
}
static pid_t child;
fl.l_start = 0;
fl.l_len = 0;
+ trace("Releasing %u locks\n", lock_num);
for (i = 0; i < lock_num; i++)
fcntl(locks[i].fd, F_SETLK, &fl);
} else {
if (lock_owner != 0) {
enum info_type type = RELEASE_LOCKS;
assert(control_fd != -1);
+ trace("Asking parent to release locks\n");
write_all(control_fd, &type, sizeof(type));
}
if (fcntl(locks[i].fd, F_SETLKW, &fl) != 0)
abort();
}
+ trace("Acquired %u locks\n", lock_num);
lock_owner = getpid();
}
-static struct contents_saved *save_contents(int fd, size_t count, off_t off)
+static struct contents_saved *save_contents(const char *filename,
+ int fd, size_t count, off_t off,
+ const char *why)
{
struct contents_saved *s = malloc(sizeof(*s) + count);
ssize_t ret;
off = lseek(fd, 0, SEEK_CUR);
s->old_len = lseek(fd, 0, SEEK_END);
lseek(fd, off, SEEK_SET);
+
+ trace("Saving %p %s %zu@%llu after %s (filelength %llu) via fd %i\n",
+ s, filename, s->count, (long long)s->off, why,
+ (long long)s->old_len, fd);
return s;
}
return;
}
/* Make it clearly distinguisable from a "normal" fd. */
- opener->u.open.ret = move_fd_to_high(fd);
+ fd = move_fd_to_high(fd);
+ trace("Reopening %s to restore it (was fd %i, now %i)\n",
+ opener->u.open.pathname, opener->u.open.ret, fd);
+ opener->u.open.ret = fd;
opener->u.open.closed = false;
}
fd = opener->u.open.ret;
+ trace("Restoring %p %s %zu@%llu after %s (filelength %llu) via fd %i\n",
+ s, opener->u.open.pathname, s->count, (long long)s->off, caller,
+ (long long)s->old_len, fd);
if (pwrite(fd, s->contents, s->count, s->off) != s->count) {
fwarn("failtest: write failed cleaning up %s for %s!",
opener->u.open.pathname, caller);
opener->u.open.pathname, caller);
}
- if (restore_offset)
+ if (restore_offset) {
+ trace("Restoring offset of fd %i to %llu\n",
+ fd, (long long)s->off);
lseek(fd, s->off, SEEK_SET);
+ }
}
/* We save/restore most things on demand, but always do mmaped files. */
static void save_mmapped_files(void)
{
struct failtest_call *i;
+ trace("Saving mmapped files in child\n");
tlist_for_each_rev(&history, i, list) {
struct mmap_call *m = &i->u.mmap;
continue;
s = malloc(sizeof *s);
- s->s = save_contents(m->fd, m->length, m->offset);
+ s->s = save_contents(m->opener->u.open.pathname,
+ m->fd, m->length, m->offset,
+ "mmapped file before fork");
s->opener = m->opener;
s->next = saved_mmapped_files;
saved_mmapped_files = s;
static void free_mmapped_files(bool restore)
{
+ trace("%s mmapped files in child\n",
+ restore ? "Restoring" : "Discarding");
while (saved_mmapped_files) {
struct saved_mmapped_file *next = saved_mmapped_files->next;
if (restore)
{
struct failtest_call *i;
- while ((i = tlist_top(&history, struct failtest_call, list)) != NULL)
+ while ((i = tlist_top(&history, list)) != NULL)
free_call(i);
failtable_clear(&failtable);
}
/* Are we probing? If so, we never fail twice. */
- if (probing)
+ if (probing) {
+ trace("Not failing %c due to FAIL_PROBE return\n",
+ info_to_arg[call->type]);
return call->fail = false;
+ }
- /* Don't more than once in the same place. */
+ /* Don't fail more than once in the same place. */
dup = failtable_get(&failtable, call);
- if (dup)
+ if (dup) {
+ trace("Not failing %c due to duplicate\n",
+ info_to_arg[call->type]);
return call->fail = false;
+ }
if (failtest_hook) {
switch (failtest_hook(&history)) {
probing = true;
break;
case FAIL_DONT_FAIL:
+ trace("Not failing %c due to failhook return\n",
+ info_to_arg[call->type]);
call->fail = false;
return false;
default:
/* Prevent double-printing (in child and parent) */
fflush(stdout);
+ fflush(warnf);
+ if (tracef)
+ fflush(tracef);
child = fork();
if (child == -1)
err(1, "forking failed");
if (child == 0) {
- if (tracefd != -1) {
+ traceindent++;
+ if (tracef) {
struct timeval diff;
const char *p;
char *failpath;
struct failtest_call *c;
- c = tlist_tail(&history, struct failtest_call, list);
+ c = tlist_tail(&history, list);
diff = time_sub(time_now(), start);
failpath = failpath_string();
- trace("%u->%u (%u.%02u): %s (", getppid(), getpid(),
- (int)diff.tv_sec, (int)diff.tv_usec / 10000,
- failpath);
- free(failpath);
p = strrchr(c->file, '/');
if (p)
- trace("%s", p+1);
+ p++;
else
- trace("%s", c->file);
- trace(":%u)\n", c->line);
+ p = c->file;
+ trace("%u->%u (%u.%02u): %s (%s:%u)\n",
+ getppid(), getpid(),
+ (int)diff.tv_sec, (int)diff.tv_usec / 10000,
+ failpath, p, c->line);
+ free(failpath);
}
/* From here on, we have to clean up! */
- our_history_start = tlist_tail(&history, struct failtest_call,
- list);
+ our_history_start = tlist_tail(&history, list);
close(control[0]);
close(output[0]);
- dup2(output[1], STDOUT_FILENO);
- dup2(output[1], STDERR_FILENO);
- if (output[1] != STDOUT_FILENO && output[1] != STDERR_FILENO)
- close(output[1]);
+ /* Don't swallow stderr if we're tracing. */
+ if (!tracef) {
+ dup2(output[1], STDOUT_FILENO);
+ dup2(output[1], STDERR_FILENO);
+ if (output[1] != STDOUT_FILENO
+ && output[1] != STDERR_FILENO)
+ close(output[1]);
+ }
control_fd = move_fd_to_high(control[1]);
/* Forget any of our parent's saved files. */
static void cleanup_calloc(struct calloc_call *call, bool restore)
{
+ trace("undoing calloc %p\n", call->ret);
free(call->ret);
}
p->u.calloc.ret = calloc(nmemb, size);
set_cleanup(p, cleanup_calloc, struct calloc_call);
}
+ trace("calloc %zu x %zu %s:%u -> %p\n",
+ nmemb, size, file, line, p->u.calloc.ret);
errno = p->error;
return p->u.calloc.ret;
}
static void cleanup_malloc(struct malloc_call *call, bool restore)
{
+ trace("undoing malloc %p\n", call->ret);
free(call->ret);
}
p->u.malloc.ret = malloc(size);
set_cleanup(p, cleanup_malloc, struct malloc_call);
}
+ trace("malloc %zu %s:%u -> %p\n",
+ size, file, line, p->u.malloc.ret);
errno = p->error;
return p->u.malloc.ret;
}
static void cleanup_realloc(struct realloc_call *call, bool restore)
{
+ trace("undoing realloc %p\n", call->ret);
free(call->ret);
}
/* Walk back and find out if we got this ptr from a previous routine. */
-static void fixup_ptr_history(void *ptr)
+static void fixup_ptr_history(void *ptr, const char *why)
{
struct failtest_call *i;
switch (i->type) {
case FAILTEST_REALLOC:
if (i->u.realloc.ret == ptr) {
+ trace("found realloc %p %s:%u matching %s\n",
+ ptr, i->file, i->line, why);
i->cleanup = NULL;
i->can_leak = false;
return;
break;
case FAILTEST_MALLOC:
if (i->u.malloc.ret == ptr) {
+ trace("found malloc %p %s:%u matching %s\n",
+ ptr, i->file, i->line, why);
i->cleanup = NULL;
i->can_leak = false;
return;
break;
case FAILTEST_CALLOC:
if (i->u.calloc.ret == ptr) {
+ trace("found calloc %p %s:%u matching %s\n",
+ ptr, i->file, i->line, why);
i->cleanup = NULL;
i->can_leak = false;
return;
break;
}
}
+ trace("Did not find %p matching %s\n", ptr, why);
}
void *failtest_realloc(void *ptr, size_t size, const char *file, unsigned line)
} else {
/* Don't catch this one in the history fixup... */
p->u.realloc.ret = NULL;
- fixup_ptr_history(ptr);
+ fixup_ptr_history(ptr, "realloc");
p->u.realloc.ret = realloc(ptr, size);
set_cleanup(p, cleanup_realloc, struct realloc_call);
}
+ trace("realloc %p %s:%u -> %p\n",
+ ptr, file, line, p->u.realloc.ret);
errno = p->error;
return p->u.realloc.ret;
}
* a previous allocation we did see. */
void failtest_free(void *ptr)
{
- fixup_ptr_history(ptr);
+ fixup_ptr_history(ptr, "free");
+ trace("free %p\n", ptr);
free(ptr);
}
if (fd < 0)
return NULL;
- s = save_contents(fd, lseek(fd, 0, SEEK_END), 0);
+ s = save_contents(pathname, fd, lseek(fd, 0, SEEK_END), 0,
+ "open with O_TRUNC");
close(fd);
return s;
}
if (should_fail(p)) {
/* Don't bother inserting failures that would happen anyway. */
- if (open_would_fail(pathname, call.flags))
+ if (open_would_fail(pathname, call.flags)) {
+ trace("Open would have failed anyway: stopping\n");
failtest_cleanup(true, 0);
+ }
p->u.open.ret = -1;
/* FIXME: Play with error codes? */
p->error = EACCES;
set_cleanup(p, cleanup_open, struct open_call);
}
}
+ trace("open %s %s:%u -> %i (opener %p)\n",
+ pathname, file, line, p->u.open.ret, &p->u.open);
errno = p->error;
return p->u.open.ret;
}
static void cleanup_mmap(struct mmap_call *mmap, bool restore)
{
+ trace("cleaning up mmap @%p (opener %p)\n",
+ mmap->ret, mmap->opener);
if (restore)
restore_contents(mmap->opener, mmap->saved, false, "mmap");
free(mmap->saved);
fwarnx("failtest_mmap: couldn't figure out source for"
" fd %i at %s:%u", fd, file, line);
}
- return mmap(addr, length, prot, flags, fd, offset);
+ addr = mmap(addr, length, prot, flags, fd, offset);
+ trace("mmap of fd %i -> %p (opener = NULL)\n", fd, addr);
+ return addr;
}
p = add_history(FAILTEST_MMAP, false, file, line, &call);
if (p->u.mmap.ret != MAP_FAILED
&& (prot & PROT_WRITE)
&& call.opener->type == FAILTEST_OPEN) {
- p->u.mmap.saved = save_contents(fd, length, offset);
+ const char *fname = call.opener->u.open.pathname;
+ p->u.mmap.saved = save_contents(fname, fd, length,
+ offset, "being mmapped");
set_cleanup(p, cleanup_mmap, struct mmap_call);
}
}
+ trace("mmap of fd %i %s:%u -> %p (opener = %p)\n",
+ fd, file, line, addr, call.opener);
errno = p->error;
return p->u.mmap.ret;
}
static void cleanup_pipe(struct pipe_call *call, bool restore)
{
+ trace("cleaning up pipe fd=%i%s,%i%s\n",
+ call->fds[0], call->closed[0] ? "(already closed)" : "",
+ call->fds[1], call->closed[1] ? "(already closed)" : "");
if (!call->closed[0])
close(call->fds[0]);
if (!call->closed[1])
p->u.pipe.closed[0] = p->u.pipe.closed[1] = false;
set_cleanup(p, cleanup_pipe, struct pipe_call);
}
+
+ trace("pipe %s:%u -> %i,%i\n", file, line,
+ p->u.pipe.ret ? -1 : p->u.pipe.fds[0],
+ p->u.pipe.ret ? -1 : p->u.pipe.fds[1]);
+
/* This causes valgrind to notice if they use pipefd[] after failure */
memcpy(pipefd, p->u.pipe.fds, sizeof(p->u.pipe.fds));
errno = p->error;
static void cleanup_read(struct read_call *call, bool restore)
{
if (restore) {
+ trace("cleaning up read on fd %i: seeking to %llu\n",
+ call->fd, (long long)call->off);
+
/* Read (not readv!) moves file offset! */
if (lseek(call->fd, call->off, SEEK_SET) != call->off) {
fwarn("Restoring lseek pointer failed (read)");
set_cleanup(p, cleanup_read, struct read_call);
}
}
+ trace("%sread %s:%u fd %i %zu@%llu -> %i\n",
+ is_pread ? "p" : "", file, line, fd, count, (long long)off,
+ p->u.read.ret);
errno = p->error;
return p->u.read.ret;
}
static void cleanup_write(struct write_call *write, bool restore)
{
+ trace("cleaning up write on %s\n", write->opener->u.open.pathname);
if (restore)
restore_contents(write->opener, write->saved, !write->is_pwrite,
"write");
sizeof(child_writes[0]) * child_writes_num);
/* Child wrote it already. */
+ trace("write %s:%i on fd %i already done by child\n",
+ file, line, fd);
p->u.write.ret = count;
errno = p->error;
return p->u.write.ret;
}
if (is_file) {
- p->u.write.saved = save_contents(fd, count, off);
+ p->u.write.saved = save_contents(call.opener->u.open.pathname,
+ fd, count, off,
+ "being overwritten");
set_cleanup(p, cleanup_write, struct write_call);
}
else
p->u.write.ret = write(fd, buf, count);
}
+ trace("%swrite %s:%i %zu@%llu on fd %i -> %i\n",
+ p->u.write.is_pwrite ? "p" : "",
+ file, line, count, (long long)off, fd, p->u.write.ret);
errno = p->error;
return p->u.write.ret;
}
off_t new_start, new_end;
new_start = end + 1;
new_end = l->end;
+ trace("splitting lock on fd %i from %llu-%llu"
+ " to %llu-%llu\n",
+ fd, (long long)l->start, (long long)l->end,
+ (long long)l->start, (long long)start - 1);
l->end = start - 1;
locks = add_lock(locks,
fd, new_start, new_end, l->type);
l = &locks[i];
} else if (start <= l->start && end >= l->end) {
/* Total overlap: eliminate entry. */
+ trace("erasing lock on fd %i %llu-%llu\n",
+ fd, (long long)l->start, (long long)l->end);
l->end = 0;
l->start = 1;
} else if (end >= l->start && end < l->end) {
+ trace("trimming lock on fd %i from %llu-%llu"
+ " to %llu-%llu\n",
+ fd, (long long)l->start, (long long)l->end,
+ (long long)end + 1, (long long)l->end);
/* Start overlap: trim entry. */
l->start = end + 1;
} else if (start > l->start && start <= l->end) {
+ trace("trimming lock on fd %i from %llu-%llu"
+ " to %llu-%llu\n",
+ fd, (long long)l->start, (long long)l->end,
+ (long long)l->start, (long long)start - 1);
/* End overlap: trim entry. */
l->end = start-1;
}
/* Nothing left? Remove it. */
if (l->end < l->start) {
+ trace("forgetting lock on fd %i\n", fd);
memmove(l, l + 1, (--lock_num - i) * sizeof(l[0]));
i--;
}
l->start = start;
l->end = end;
l->type = type;
+ trace("new lock on fd %i %llu-%llu\n",
+ fd, (long long)l->start, (long long)l->end);
}
return locks;
}
abort();
}
+ trace("close on fd %i\n", fd);
if (fd < 0)
return close(fd);
/* Mark opener as not leaking, remove its cleanup function. */
if (opener) {
+ trace("close on fd %i found opener %p\n", fd, opener);
if (opener->type == FAILTEST_PIPE) {
/* From a pipe? */
if (opener->u.pipe.fds[0] == fd) {
if (i == opener)
break;
if (i->type == FAILTEST_LSEEK && i->u.lseek.fd == fd) {
+ trace("close on fd %i undoes lseek\n", fd);
/* This seeks back. */
i->cleanup(&i->u, true);
i->cleanup = NULL;
} else if (i->type == FAILTEST_WRITE
&& i->u.write.fd == fd
&& !i->u.write.is_pwrite) {
+ trace("close on fd %i undoes write"
+ " offset change\n", fd);
/* Write (not pwrite!) moves file offset! */
if (lseek(fd, i->u.write.off, SEEK_SET)
!= i->u.write.off) {
&& i->u.read.fd == fd) {
/* preads don't *have* cleanups */
if (i->cleanup) {
+ trace("close on fd %i undoes read"
+ " offset change\n", fd);
/* This seeks back. */
i->cleanup(&i->u, true);
i->cleanup = NULL;
va_start(ap, cmd);
call.arg.l = va_arg(ap, long);
va_end(ap);
+ trace("fcntl on fd %i F_SETFL/F_SETFD\n", fd);
return fcntl(fd, cmd, call.arg.l);
case F_GETFD:
case F_GETFL:
+ trace("fcntl on fd %i F_GETFL/F_GETFD\n", fd);
return fcntl(fd, cmd);
case F_GETLK:
+ trace("fcntl on fd %i F_GETLK\n", fd);
get_locks();
va_start(ap, cmd);
call.arg.fl = *va_arg(ap, struct flock *);
return fcntl(fd, cmd, &call.arg.fl);
case F_SETLK:
case F_SETLKW:
+ trace("fcntl on fd %i F_SETLK%s\n",
+ fd, cmd == F_SETLKW ? "W" : "");
va_start(ap, cmd);
call.arg.fl = *va_arg(ap, struct flock *);
va_end(ap);
p->u.fcntl.arg.fl.l_type);
}
}
+ trace("fcntl on fd %i -> %i\n", fd, p->u.fcntl.ret);
errno = p->error;
return p->u.fcntl.ret;
}
static void cleanup_lseek(struct lseek_call *call, bool restore)
{
if (restore) {
+ trace("cleaning up lseek on fd %i -> %llu\n",
+ call->fd, (long long)call->old_off);
if (lseek(call->fd, call->old_off, SEEK_SET) != call->old_off)
fwarn("Restoring lseek pointer failed");
}
if (p->u.lseek.ret != (off_t)-1)
set_cleanup(p, cleanup_lseek, struct lseek_call);
+
+ trace("lseek %s:%u on fd %i from %llu to %llu%s\n",
+ file, line, fd, (long long)call.old_off, (long long)offset,
+ whence == SEEK_CUR ? " (from current off)" :
+ whence == SEEK_END ? " (from end)" :
+ whence == SEEK_SET ? "" : " (invalid whence)");
return p->u.lseek.ret;
}
orig_pid = getpid();
- warnfd = move_fd_to_high(dup(STDERR_FILENO));
+ warnf = fdopen(move_fd_to_high(dup(STDERR_FILENO)), "w");
for (i = 1; i < argc; i++) {
if (!strncmp(argv[i], "--failpath=", strlen("--failpath="))) {
failpath = argv[i] + strlen("--failpath=");
- } else if (strcmp(argv[i], "--tracepath") == 0) {
- tracefd = warnfd;
+ } else if (strcmp(argv[i], "--trace") == 0) {
+ tracef = warnf;
failtest_timeout_ms = -1;
} else if (!strncmp(argv[i], "--debugpath=",
strlen("--debugpath="))) {
void failtest_exit(int status)
{
+ trace("failtest_exit with status %i\n", status);
if (failtest_exit_check) {
if (!failtest_exit_check(&history))
child_fail(NULL, 0, "failtest_exit_check failed\n");
projects / ccan / blobdiff