From 7de265d88a78a27d58c2c728424e5bb8379ef351 Mon Sep 17 00:00:00 2001 From: Denys Vlasenko Date: Tue, 13 Mar 2012 11:44:31 +0100 Subject: [PATCH] Fix logging for "strace -o FILE -ff test/threaded_execve" test case Our logic which was deciding whether to print "" thingy wasn't working properly for -ff case. * defs.h: Group log generation-related declarations together. Add a large comment which explains how it works. Add declaration of line_ended() function. * strace.c (line_ended): New function which sets up internal data to indicate that previous line was finished. (printleader): Change logic to fix log generation in -ff mode. (newoutf): Make check for -ff mode consistent with other places. (droptcb): Print "" if last line for this tcp wasn't finished. (cleanup): Remove code to print "", printleader() or detach() will do it instead. (trace): Remove code to print "". Add code which finishes threaded execve's incomplete line with " " message. Replace printing_tcp = NULL followed by fflush() by line_ended() call. * process.c (sys_exit): Call line_ended() to indicate that we finished priting. * syscall.c (trace_syscall_exiting): Set printing_tcp to current tcp. Call line_ended() to indicate that we finished priting. Remove call to fflush(), it is done by line_ended() now. Signed-off-by: Denys Vlasenko --- defs.h | 38 +++++++++++++------ process.c | 2 +- strace.c | 109 +++++++++++++++++++++++++++++++++--------------------- syscall.c | 26 +++++++++---- 4 files changed, 113 insertions(+), 62 deletions(-) diff --git a/defs.h b/defs.h index c96b0310..a5656323 100644 --- a/defs.h +++ b/defs.h @@ -443,13 +443,6 @@ extern unsigned int ptrace_setoptions; extern int dtime, xflag, qflag; extern cflag_t cflag; extern int max_strlen; -/* - * Which tcb has incomplete line being printed right now? - * NULL if last line has been completed ('\n'-terminated). - * printleader(tcp) sets it. Clearing is open-coded. - */ -extern struct tcb *printing_tcp; - enum bitness_t { BITNESS_CURRENT = 0, BITNESS_32 }; void error_msg(const char *fmt, ...) __attribute__ ((format(printf, 1, 2))); @@ -518,8 +511,8 @@ extern void printcall(struct tcb *); extern const char *signame(int); extern void print_sigset(struct tcb *, long, int); extern void printsignal(int); -extern void printleader(struct tcb *); -extern void tabto(void); + + extern void call_summary(FILE *); extern void tprint_iov(struct tcb *, unsigned long, unsigned long, int decode_iov); extern void tprint_open_modes(mode_t); @@ -564,6 +557,30 @@ extern char *stpcpy(char *dst, const char *src); extern long getrval2(struct tcb *); #endif +/* Strace log generation machinery. + * + * printing_tcp: tcb which has incomplete line being printed right now. + * NULL if last line has been completed ('\n'-terminated). + * printleader(tcp) examines it, finishes incomplete line if needed, + * the sets it to tcp. + * line_ended() clears printing_tcp and resets ->curcol = 0. + * tcp->curcol == 0 check is also used to detect completeness + * of last line, since in -ff mode just checking printing_tcp for NULL + * is not enough. + * + * If you change this code, test log generation in both -f and -ff modes + * using: + * strace -oLOG -f[f] test/threaded_execve + * strace -oLOG -f[f] test/sigkill_rain + * strace -oLOG -f[f] -p "`pidof web_browser`" + */ +extern struct tcb *printing_tcp; +extern void printleader(struct tcb *); +extern void line_ended(void); +extern void tabto(void); +extern void tprintf(const char *fmt, ...) __attribute__ ((format (printf, 1, 2))); +extern void tprints(const char *str); + #define umove(pid, addr, objp) \ umoven((pid), (addr), sizeof *(objp), (char *) (objp)) @@ -572,9 +589,6 @@ extern long getrval2(struct tcb *); #define printtv_special(tcp, addr) \ printtv_bitness((tcp), (addr), BITNESS_CURRENT, 1) -extern void tprintf(const char *fmt, ...) __attribute__ ((format (printf, 1, 2))); -extern void tprints(const char *str); - #ifndef HAVE_STRERROR const char *strerror(int); #endif diff --git a/process.c b/process.c index 12d0948b..5a0aae2b 100644 --- a/process.c +++ b/process.c @@ -392,7 +392,7 @@ sys_exit(struct tcb *tcp) tprintf("%ld) ", tcp->u_arg[0]); tabto(); tprints("= ?\n"); - printing_tcp = NULL; + line_ended(); return 0; } diff --git a/strace.c b/strace.c index 27b64b09..4129a8a0 100644 --- a/strace.c +++ b/strace.c @@ -370,10 +370,29 @@ tprints(const char *str) } } +void +line_ended(void) +{ + curcol = 0; + fflush(outf); + if (!printing_tcp) + return; + printing_tcp->curcol = 0; + printing_tcp = NULL; +} + void printleader(struct tcb *tcp) { + /* If -ff, "previous tcb we printed" is always the same as current, + * because we have per-tcb output files. + */ + if (followfork >= 2) + printing_tcp = tcp; + if (printing_tcp) { + outf = printing_tcp->outf; + curcol = printing_tcp->curcol; if (printing_tcp->ptrace_errno) { if (printing_tcp->flags & TCB_INSYSCALL) { tprints(" ) "); @@ -381,13 +400,23 @@ printleader(struct tcb *tcp) } tprints("= ? \n"); printing_tcp->ptrace_errno = 0; - } else if (!outfname || followfork < 2 || printing_tcp == tcp) { - printing_tcp->flags |= TCB_REPRINT; + printing_tcp->curcol = 0; + } + if (printing_tcp->curcol != 0 && (followfork < 2 || printing_tcp == tcp)) { + /* + * case 1: we have a shared log (i.e. not -ff), and last line + * wasn't finished (same or different tcb, doesn't matter). + * case 2: split log, we are the same tcb, but our last line + * didn't finish ("SIGKILL nuked us after syscall entry" etc). + */ tprints(" \n"); + printing_tcp->flags |= TCB_REPRINT; + printing_tcp->curcol = 0; } } printing_tcp = tcp; + outf = tcp->outf; curcol = 0; if (print_pid_pfx) @@ -518,7 +547,7 @@ strace_popen(const char *command) static void newoutf(struct tcb *tcp) { - if (outfname && followfork > 1) { + if (outfname && followfork >= 2) { char name[520 + sizeof(int) * 3]; sprintf(name, "%.512s.%u", outfname, tcp->pid); tcp->outf = strace_fopen(name); @@ -1516,8 +1545,16 @@ droptcb(struct tcb *tcp) if (debug) fprintf(stderr, "dropped tcb for pid %d, %d remain\n", tcp->pid, nprocs); - if (outfname && followfork > 1 && tcp->outf) + if (printing_tcp == tcp) + printing_tcp = NULL; + + if (outfname && followfork >= 2 && tcp->outf) { + if (tcp->curcol != 0) + fprintf(tcp->outf, " \n"); fclose(tcp->outf); + } else if (tcp->outf) { + fflush(tcp->outf); + } memset(tcp, 0, sizeof(*tcp)); } @@ -1646,17 +1683,11 @@ cleanup(void) if (debug) fprintf(stderr, "cleanup: looking at pid %u\n", tcp->pid); - if (printing_tcp && - (!outfname || followfork < 2 || printing_tcp == tcp)) { - tprints(" \n"); - printing_tcp = NULL; - } - if (!(tcp->flags & TCB_STRACE_CHILD)) - detach(tcp); - else { + if (tcp->flags & TCB_STRACE_CHILD) { kill(tcp->pid, SIGCONT); kill(tcp->pid, fatal_sig); } + detach(tcp); } if (cflag) call_summary(outf); @@ -1851,18 +1882,20 @@ trace(void) if (tcp) { outf = tcp->outf; curcol = tcp->curcol; - if (!cflag) { - if (printing_tcp) - tprints(" \n"); - printleader(tcp); - tprintf("+++ superseded by execve in pid %lu +++\n", old_pid); - printing_tcp = NULL; - fflush(outf); - } if (execve_thread) { + if (execve_thread->curcol != 0) { + /* + * One case we are here is -ff: + * try "strace -oLOG -ff test/threaded_execve" + */ + fprintf(execve_thread->outf, " \n", pid); + execve_thread->curcol = 0; + } /* swap output FILEs (needed for -ff) */ tcp->outf = execve_thread->outf; + tcp->curcol = execve_thread->curcol; execve_thread->outf = outf; + execve_thread->curcol = curcol; } droptcb(tcp); } @@ -1870,6 +1903,11 @@ trace(void) if (tcp) { tcp->pid = pid; tcp->flags |= TCB_REPRINT; + if (!cflag) { + printleader(tcp); + tprintf("+++ superseded by execve in pid %lu +++\n", old_pid); + line_ended(); + } } } } @@ -1900,9 +1938,11 @@ trace(void) error_msg_and_die("Unknown pid: %u", pid); } } - /* set current output file */ + + /* Set current output file */ outf = tcp->outf; curcol = tcp->curcol; + if (cflag) { tv_sub(&tcp->dtime, &ru.ru_stime, &tcp->stime); tcp->stime = ru.ru_stime; @@ -1922,25 +1962,19 @@ trace(void) tprintf("+++ killed by %s +++\n", signame(WTERMSIG(status))); #endif - printing_tcp = NULL; + line_ended(); } - fflush(tcp->outf); droptcb(tcp); continue; } if (WIFEXITED(status)) { if (pid == strace_child) exit_code = WEXITSTATUS(status); - if (tcp == printing_tcp) { - tprints(" \n"); - printing_tcp = NULL; - } if (!cflag /* && (qual_flags[WTERMSIG(status)] & QUAL_SIGNAL) */ ) { printleader(tcp); tprintf("+++ exited with %d +++\n", WEXITSTATUS(status)); - printing_tcp = NULL; + line_ended(); } - fflush(tcp->outf); droptcb(tcp); continue; } @@ -2054,8 +2088,7 @@ trace(void) strsignal(sig), signame(sig) PC_FORMAT_ARG); - printing_tcp = NULL; - fflush(tcp->outf); + line_ended(); } if (!stopped) @@ -2074,6 +2107,7 @@ trace(void) cleanup(); return -1; } + tcp->curcol = curcol; continue; } /* We don't have PTRACE_LISTEN support... */ @@ -2094,22 +2128,13 @@ trace(void) * Likely a result of process disappearing mid-flight. * Observed case: exit_group() terminating * all processes in thread group. - */ - if (printing_tcp) { - /* Do we have dangling line "syscall(param, param"? - * Finish the line then. - */ - printing_tcp->flags |= TCB_REPRINT; - tprints(" \n"); - printing_tcp = NULL; - fflush(tcp->outf); - } - /* We assume that ptrace error was caused by process death. + * We assume that ptrace error was caused by process death. * We used to detach(tcp) here, but since we no longer * implement "detach before death" policy/hack, * we can let this process to report its death to us * normally, via WIFEXITED or WIFSIGNALED wait status. */ + tcp->curcol = curcol; continue; } restart_tracee_with_sig_0: diff --git a/syscall.c b/syscall.c index f54df0fc..191127b0 100644 --- a/syscall.c +++ b/syscall.c @@ -1915,6 +1915,17 @@ trace_syscall_exiting(struct tcb *tcp) goto ret; } + /* TODO: TCB_REPRINT is probably not necessary: + * we can determine whether reprinting is needed + * by examining printing_tcp. Something like: + * if not in -ff mode, and printing_tcp != tcp, + * then the log is not currenlty ends with *our* + * syscall entry output, but with something else, + * and we need to reprint. + * If we'd implement this, printing_tcp = tcp + * assignments in code below can be made more logical. + */ + if (tcp->flags & TCB_REPRINT) { printleader(tcp); if (!SCNO_IN_RANGE(tcp->scno)) @@ -1932,18 +1943,20 @@ trace_syscall_exiting(struct tcb *tcp) } if (res != 1) { + printing_tcp = tcp; tprints(") "); tabto(); tprints("= ? \n"); - printing_tcp = NULL; + line_ended(); tcp->flags &= ~TCB_INSYSCALL; return res; } if (!SCNO_IN_RANGE(tcp->scno) - || (qual_flags[tcp->scno] & QUAL_RAW)) + || (qual_flags[tcp->scno] & QUAL_RAW)) { + printing_tcp = tcp; sys_res = printargs(tcp); - else { + } else { /* FIXME: not_failing_only (IOW, option -z) is broken: * failure of syscall is known only after syscall return. * Thus we end up with something like this on, say, ENOENT: @@ -1954,6 +1967,7 @@ trace_syscall_exiting(struct tcb *tcp) */ if (not_failing_only && tcp->u_error) goto ret; /* ignore failed syscalls */ + printing_tcp = tcp; sys_res = (*sysent[tcp->scno].sys_func)(tcp); } @@ -2081,11 +2095,9 @@ trace_syscall_exiting(struct tcb *tcp) (long) tv.tv_sec, (long) tv.tv_usec); } tprints("\n"); - printing_tcp = NULL; - dumpio(tcp); - if (fflush(tcp->outf) == EOF) - return -1; + line_ended(); + ret: tcp->flags &= ~TCB_INSYSCALL; return 0; -- 2.40.0