]> granicus.if.org Git - strace/commitdiff
Fix logging for "strace -o FILE -ff test/threaded_execve" test case
authorDenys Vlasenko <vda.linux@googlemail.com>
Tue, 13 Mar 2012 10:44:31 +0000 (11:44 +0100)
committerDenys Vlasenko <vda.linux@googlemail.com>
Tue, 13 Mar 2012 10:44:31 +0000 (11:44 +0100)
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>
defs.h
process.c
strace.c
syscall.c

diff --git a/defs.h b/defs.h
index c96b03104969cdc7bf4e7ddc15df01f365fdd4c3..a56563235c01729da51be5715e4d745f086ef1bc 100644 (file)
--- 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
index 12d0948b983b8658aa371d24e2dc33f3be225839..5a0aae2b641bd6d783c9fef83c3057081e5802ea 100644 (file)
--- 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;
 }
 
index 27b64b093fd27111a25d912ee9556aefab664296..4129a8a00f23deae421e9ebf01e1b482768659a1 100644 (file)
--- 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(" <unavailable>) ");
@@ -381,13 +400,23 @@ printleader(struct tcb *tcp)
                        }
                        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 @@ 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, " <detached>\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(" <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 @@ trace(void)
                                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 @@ 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(" <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 @@ 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(" <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:
index f54df0fcb3fc104ec49c967e122544fed75614db..191127b04be19c417500b0be85129c26a427adad 100644 (file)
--- 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("= ? <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 @@ 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;