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>

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

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;
 }
 

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->curcol = 0;
-			printing_tcp->flags |= TCB_REPRINT;
+		}
+		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 &&
+		if (tcp->flags & TCB_STRACE_CHILD) {
-		    (!outfname || followfork < 2 || printing_tcp == tcp)) {
-			tprints(" <unfinished ...>\n");
-			printing_tcp = NULL;
-		}
-		if (!(tcp->flags & TCB_STRACE_CHILD))
-			detach(tcp);
-		else {
 			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;
+				line_ended();
-				fflush(tcp->outf);
 			}
 
 			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.
-			 */
+			 * We assume that ptrace error was caused by process death.
-			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 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:

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)
+	line_ended();
-		return -1;
+
  ret:
 	tcp->flags &= ~TCB_INSYSCALL;
 	return 0;