Fix logging for "strace -o FILE -ff test/threaded_execve" test case
Our logic which was deciding whether to print "<unfinished ...>"
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 "<detached ...>" if last line for this tcp wasn't finished.
(cleanup): Remove code to print "<unfinished ...>", printleader()
or detach() will do it instead.
(trace): Remove code to print "<unfinished ...>".
Add code which finishes threaded execve's incomplete line
with " <pid changed to PID ...>" 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 <vda.linux@googlemail.com>
diff --git a/defs.h b/defs.h
index c96b031..a565632 100644
--- a/defs.h
+++ b/defs.h
@@ -443,13 +443,6 @@
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 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 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 @@
#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 12d0948..5a0aae2 100644
--- a/process.c
+++ b/process.c
@@ -392,7 +392,7 @@
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 27b64b0..4129a8a 100644
--- a/strace.c
+++ b/strace.c
@@ -371,9 +371,28 @@
}
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(" <unavailable>) ");
@@ -381,13 +400,23 @@
}
tprints("= ? <unavailable>\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(" <unfinished ...>\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 @@
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 @@
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, " <detached>\n");
fclose(tcp->outf);
+ } else if (tcp->outf) {
+ fflush(tcp->outf);
+ }
memset(tcp, 0, sizeof(*tcp));
}
@@ -1646,17 +1683,11 @@
if (debug)
fprintf(stderr,
"cleanup: looking at pid %u\n", tcp->pid);
- if (printing_tcp &&
- (!outfname || followfork < 2 || printing_tcp == tcp)) {
- tprints(" <unfinished ...>\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 @@
if (tcp) {
outf = tcp->outf;
curcol = tcp->curcol;
- if (!cflag) {
- if (printing_tcp)
- tprints(" <unfinished ...>\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, " <pid changed to %d ...>\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 @@
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 @@
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 @@
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(" <unfinished ...>\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 @@
strsignal(sig),
signame(sig)
PC_FORMAT_ARG);
- printing_tcp = NULL;
- fflush(tcp->outf);
+ line_ended();
}
if (!stopped)
@@ -2074,6 +2107,7 @@
cleanup();
return -1;
}
+ tcp->curcol = curcol;
continue;
}
/* We don't have PTRACE_LISTEN support... */
@@ -2094,22 +2128,13 @@
* 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(" <unfinished ...>\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 f54df0f..191127b 100644
--- a/syscall.c
+++ b/syscall.c
@@ -1915,6 +1915,17 @@
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 @@
}
if (res != 1) {
+ printing_tcp = tcp;
tprints(") ");
tabto();
tprints("= ? <unavailable>\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 @@
*/
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 @@
(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;