Date: Wed, 3 Dec 2008 12:56:22 -0600 From: Dan Nelson <dnelson@allantgroup.com> To: Vlad GALU <dudu@dudu.ro> Cc: freebsd-stable@freebsd.org Subject: Re: Weird truss output Message-ID: <20081203185622.GF22076@dan.emsphone.com> In-Reply-To: <20081203170857.GE22076@dan.emsphone.com> References: <ad79ad6b0812030147x7b9fa194nf86180f89583cdf5@mail.gmail.com> <20081203152330.GD22076@dan.emsphone.com> <ad79ad6b0812030745i5dd344d4qbae54d32579c142c@mail.gmail.com> <20081203170857.GE22076@dan.emsphone.com>
next in thread | previous in thread | raw e-mail | index | archive | help
In the last episode (Dec 03), Dan Nelson said: > It looks like there's some other problem where truss either drops a > syscall event, or puts some status fields into the wrong thread's > structure. It seems to happen when two threads call blocking > syscalls, and when they return, truss gets confused as to which > thread called which syscall. The read syscall is probably still > pending, and you're getting the arguments of the syscall that > returned, printed as if it was the read syscall. When the read call > completes, you'll probably get an --UNKNOWN SYSCALL-- line, or > another mismatched syscall output line. It turns out that was the problem. There was a global structure that held syscall information. Converting it to a per-thread structure makes it work much better :) If you're adventurous, try applying the patch at http://www.evoy.net/FreeBSD/truss.diff , which fixes that problem plus a bunch of other stuff. If you're not adventurous, try the following instead, which just fixes the per-thread problem. Index: i386-fbsd.c =================================================================== RCS file: /home/ncvs/src/usr.bin/truss/i386-fbsd.c,v retrieving revision 1.29 diff -u -r1.29 i386-fbsd.c --- i386-fbsd.c 28 Jul 2007 23:15:04 -0000 1.29 +++ i386-fbsd.c 3 Dec 2008 18:48:23 -0000 @@ -49,6 +49,7 @@ #include <machine/reg.h> #include <machine/psl.h> +#include <err.h> #include <errno.h> #include <fcntl.h> #include <signal.h> @@ -77,29 +78,29 @@ * 'struct syscall' describes the system call; it may be NULL, however, * if we don't know about this particular system call yet. */ -static struct freebsd_syscall { +struct freebsd_syscall { struct syscall *sc; const char *name; int number; unsigned long *args; int nargs; /* number of arguments -- *not* number of words! */ char **s_args; /* the printable arguments */ -} fsc; +}; /* Clear up and free parts of the fsc structure. */ static __inline void -clear_fsc(void) { - if (fsc.args) { - free(fsc.args); +clear_fsc(struct freebsd_syscall *fsc) { + if (fsc->args) { + free(fsc->args); } - if (fsc.s_args) { + if (fsc->s_args) { int i; - for (i = 0; i < fsc.nargs; i++) - if (fsc.s_args[i]) - free(fsc.s_args[i]); - free(fsc.s_args); + for (i = 0; i < fsc->nargs; i++) + if (fsc->s_args[i]) + free(fsc->s_args[i]); + free(fsc->s_args); } - memset(&fsc, 0, sizeof(fsc)); + memset(fsc, 0, sizeof(*fsc)); } /* @@ -117,9 +118,20 @@ unsigned int parm_offset; struct syscall *sc = NULL; struct ptrace_io_desc iorequest; + struct freebsd_syscall *fsc; + cpid = trussinfo->curthread->tid; - clear_fsc(); + fsc = trussinfo->curthread->fsc; + if (fsc == NULL) + { + fsc = malloc(sizeof(*fsc)); + if (fsc == NULL) + errx(1, "cannot allocate syscall struct"); + memset(fsc, 0, sizeof(*fsc)); + trussinfo->curthread->fsc = fsc; + } else + clear_fsc(fsc); if (ptrace(PT_GETREGS, cpid, (caddr_t)®s, 0) < 0) { @@ -145,17 +157,24 @@ break; } - fsc.number = syscall_num; - fsc.name = + fsc->number = syscall_num; + fsc->name = (syscall_num < 0 || syscall_num > nsyscalls) ? NULL : syscallnames[syscall_num]; - if (!fsc.name) { - fprintf(trussinfo->outfile, "-- UNKNOWN SYSCALL %d --\n", syscall_num); + if (!fsc->name) { + fprintf(trussinfo->outfile, "-- UNKNOWN SYSCALL %u (0x%08x) --\n", syscall_num, syscall_num); + if ((unsigned int)syscall_num > 0x1000) { + /* When attaching to a running process, we have a 50-50 chance + of attaching to a process waiting in a syscall, which means + our first trap is an exit instead of an entry and we're out + of synch. Reset our flag */ + trussinfo->curthread->in_syscall = 0; + } } - if (fsc.name && (trussinfo->flags & FOLLOWFORKS) - && ((!strcmp(fsc.name, "fork") - || !strcmp(fsc.name, "rfork") - || !strcmp(fsc.name, "vfork")))) + if (fsc->name && (trussinfo->flags & FOLLOWFORKS) + && ((!strcmp(fsc->name, "fork") + || !strcmp(fsc->name, "rfork") + || !strcmp(fsc->name, "vfork")))) { trussinfo->curthread->in_fork = 1; } @@ -163,30 +182,30 @@ if (nargs == 0) return; - fsc.args = malloc((1+nargs) * sizeof(unsigned long)); + fsc->args = malloc((1+nargs) * sizeof(unsigned long)); iorequest.piod_op = PIOD_READ_D; iorequest.piod_offs = (void *)parm_offset; - iorequest.piod_addr = fsc.args; + iorequest.piod_addr = fsc->args; iorequest.piod_len = (1+nargs) * sizeof(unsigned long); ptrace(PT_IO, cpid, (caddr_t)&iorequest, 0); if (iorequest.piod_len == 0) return; - if (fsc.name) - sc = get_syscall(fsc.name); + if (fsc->name) + sc = get_syscall(fsc->name); if (sc) { - fsc.nargs = sc->nargs; + fsc->nargs = sc->nargs; } else { #if DEBUG fprintf(trussinfo->outfile, "unknown syscall %s -- setting args to %d\n", - fsc.name, nargs); + fsc->name, nargs); #endif - fsc.nargs = nargs; + fsc->nargs = nargs; } - fsc.s_args = malloc((1+fsc.nargs) * sizeof(char*)); - memset(fsc.s_args, 0, fsc.nargs * sizeof(char*)); - fsc.sc = sc; + fsc->s_args = malloc((1+fsc->nargs) * sizeof(char*)); + memset(fsc->s_args, 0, fsc->nargs * sizeof(char*)); + fsc->sc = sc; /* * At this point, we set up the system call arguments. @@ -196,21 +215,21 @@ * passed in *and* out, however. */ - if (fsc.name) { + if (fsc->name) { #if DEBUG - fprintf(stderr, "syscall %s(", fsc.name); + fprintf(stderr, "syscall %s(", fsc->name); #endif - for (i = 0; i < fsc.nargs; i++) { + for (i = 0; i < fsc->nargs; i++) { #if DEBUG fprintf(stderr, "0x%x%s", sc - ? fsc.args[sc->args[i].offset] - : fsc.args[i], - i < (fsc.nargs - 1) ? "," : ""); + ? fsc->args[sc->args[i].offset] + : fsc->args[i], + i < (fsc->nargs - 1) ? "," : ""); #endif if (sc && !(sc->args[i].type & OUT)) { - fsc.s_args[i] = print_arg(&sc->args[i], fsc.args, 0, trussinfo); + fsc->s_args[i] = print_arg(&sc->args[i], fsc->args, 0, trussinfo); } } #if DEBUG @@ -222,23 +241,23 @@ fprintf(trussinfo->outfile, "\n"); #endif - if (fsc.name != NULL && - (!strcmp(fsc.name, "execve") || !strcmp(fsc.name, "exit"))) { + if (fsc->name != NULL && + (!strcmp(fsc->name, "execve") || !strcmp(fsc->name, "exit"))) { /* XXX * This could be done in a more general * manner but it still wouldn't be very pretty. */ - if (!strcmp(fsc.name, "execve")) { + if (!strcmp(fsc->name, "execve")) { if ((trussinfo->flags & EXECVEARGS) == 0) - if (fsc.s_args[1]) { - free(fsc.s_args[1]); - fsc.s_args[1] = NULL; + if (fsc->s_args[1]) { + free(fsc->s_args[1]); + fsc->s_args[1] = NULL; } if ((trussinfo->flags & EXECVEENVS) == 0) - if (fsc.s_args[2]) { - free(fsc.s_args[2]); - fsc.s_args[2] = NULL; + if (fsc->s_args[2]) { + free(fsc->s_args[2]); + fsc->s_args[2] = NULL; } } @@ -262,9 +281,14 @@ int i; int errorp; struct syscall *sc; + struct freebsd_syscall *fsc; - if (fsc.name == NULL) + fsc = trussinfo->curthread->fsc; + if (fsc == NULL || fsc->name == NULL) { + fprintf(trussinfo->outfile, "No syscall?\n"); + fflush(trussinfo->outfile); return (-1); + } cpid = trussinfo->curthread->tid; if (ptrace(PT_GETREGS, cpid, (caddr_t)®s, 0) < 0) @@ -281,10 +305,10 @@ * stand some significant cleaning. */ - sc = fsc.sc; + sc = fsc->sc; if (!sc) { - for (i = 0; i < fsc.nargs; i++) - asprintf(&fsc.s_args[i], "0x%lx", fsc.args[i]); + for (i = 0; i < fsc->nargs; i++) + asprintf(&fsc->s_args[i], "0x%lx", fsc->args[i]); } else { /* * Here, we only look for arguments that have OUT masked in -- @@ -298,10 +322,10 @@ * it may not be valid. */ if (errorp) - asprintf(&temp, "0x%lx", fsc.args[sc->args[i].offset]); + asprintf(&temp, "0x%lx", fsc->args[sc->args[i].offset]); else - temp = print_arg(&sc->args[i], fsc.args, retval, trussinfo); - fsc.s_args[i] = temp; + temp = print_arg(&sc->args[i], fsc->args, retval, trussinfo); + fsc->s_args[i] = temp; } } } @@ -312,15 +336,15 @@ * The nargs check is so we don't have to do yet another strcmp on every * syscall. */ - if (!errorp && fsc.nargs == 0 && fsc.name && strcmp(fsc.name, "pipe") == 0) { - fsc.nargs = 1; - fsc.s_args = malloc((1+fsc.nargs) * sizeof(char*)); - asprintf(&fsc.s_args[0], "[%d,%d]", (int)retval, regs.r_edx); + if (!errorp && fsc->nargs == 0 && fsc->name && strcmp(fsc->name, "pipe") == 0) { + fsc->nargs = 1; + fsc->s_args = malloc((1+fsc->nargs) * sizeof(char*)); + asprintf(&fsc->s_args[0], "[%d,%d]", (int)retval, regs.r_edx); retval = 0; } - if (fsc.name != NULL && - (!strcmp(fsc.name, "execve") || !strcmp(fsc.name, "exit"))) { + if (fsc->name != NULL && + (!strcmp(fsc->name, "execve") || !strcmp(fsc->name, "exit"))) { trussinfo->curthread->in_syscall = 1; } @@ -329,8 +353,8 @@ * but that complicates things considerably. */ - print_syscall_ret(trussinfo, fsc.name, fsc.nargs, fsc.s_args, errorp, retval); - clear_fsc(); + print_syscall_ret(trussinfo, fsc->name, fsc->nargs, fsc->s_args, errorp, retval); + clear_fsc(fsc); return (retval); } Index: setup.c =================================================================== RCS file: /home/ncvs/src/usr.bin/truss/setup.c,v retrieving revision 1.24 diff -u -r1.24 setup.c --- setup.c 26 Jun 2007 22:42:37 -0000 1.24 +++ setup.c 3 Dec 2008 18:49:06 -0000 @@ -166,6 +166,7 @@ np->tid = lwpid; np->in_fork = 0; np->in_syscall = 0; + np->fsc = NULL; SLIST_INSERT_HEAD(&info->threadlist, np, entries); info->curthread = np; } Index: truss.h =================================================================== RCS file: /home/ncvs/src/usr.bin/truss/truss.h,v retrieving revision 1.8 diff -u -r1.8 truss.h --- truss.h 10 Apr 2007 04:03:34 -0000 1.8 +++ truss.h 3 Dec 2008 18:42:54 -0000 @@ -38,6 +38,7 @@ { SLIST_ENTRY(threadinfo) entries; lwpid_t tid; + void *fsc; int in_syscall; int in_fork; }; -- Dan Nelson dnelson@allantgroup.com
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20081203185622.GF22076>