[PATCH 4/4] trace: verify that locking works

["Johannes Schindelin via GitGitGadget" <gitgitgadget@gmail.com>]

From: Johannes Schindelin <johannes.schindelin@gmx.de>

Recently, t5552 introduced a pattern where two processes try to write to
the same GIT_TRACE file in parallel. This is not safe, as the two
processes fighting over who gets to append to the file can cause garbled
lines and may even result in data loss on Windows (where buffers are
written to before they are flushed).

To remedy this, we introduced the lock_or_unlock_fd_for_appending()
function. And to make sure that this works, this commit introduces a
regression test.

Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
---
 Makefile               |   1 +
 t/helper/test-tool.c   |   1 +
 t/helper/test-tool.h   |   1 +
 t/helper/test-trace.c  | 130 +++++++++++++++++++++++++++++++++++++++++
 t/t0070-fundamental.sh |   6 ++
 5 files changed, 139 insertions(+)
 create mode 100644 t/helper/test-trace.c

diff --git a/Makefile b/Makefile
index 617475622..2e3fb5b8d 100644
--- a/Makefile
+++ b/Makefile
@@ -729,6 +729,7 @@ TEST_BUILTINS_OBJS += test-strcmp-offset.o
 TEST_BUILTINS_OBJS += test-string-list.o
 TEST_BUILTINS_OBJS += test-submodule-config.o
 TEST_BUILTINS_OBJS += test-subprocess.o
+TEST_BUILTINS_OBJS += test-trace.o
 TEST_BUILTINS_OBJS += test-urlmatch-normalization.o
 TEST_BUILTINS_OBJS += test-wildmatch.o
 TEST_BUILTINS_OBJS += test-write-cache.o
diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c
index 805a45de9..7adce872b 100644
--- a/t/helper/test-tool.c
+++ b/t/helper/test-tool.c
@@ -39,6 +39,7 @@ static struct test_cmd cmds[] = {
 	{ "string-list", cmd__string_list },
 	{ "submodule-config", cmd__submodule_config },
 	{ "subprocess", cmd__subprocess },
+	{ "trace", cmd__trace },
 	{ "urlmatch-normalization", cmd__urlmatch_normalization },
 	{ "wildmatch", cmd__wildmatch },
 	{ "write-cache", cmd__write_cache },
diff --git a/t/helper/test-tool.h b/t/helper/test-tool.h
index 7116ddfb9..c462ac924 100644
--- a/t/helper/test-tool.h
+++ b/t/helper/test-tool.h
@@ -33,6 +33,7 @@ int cmd__strcmp_offset(int argc, const char **argv);
 int cmd__string_list(int argc, const char **argv);
 int cmd__submodule_config(int argc, const char **argv);
 int cmd__subprocess(int argc, const char **argv);
+int cmd__trace(int argc, const char **argv);
 int cmd__urlmatch_normalization(int argc, const char **argv);
 int cmd__wildmatch(int argc, const char **argv);
 int cmd__write_cache(int argc, const char **argv);
diff --git a/t/helper/test-trace.c b/t/helper/test-trace.c
new file mode 100644
index 000000000..1cc88b030
--- /dev/null
+++ b/t/helper/test-trace.c
@@ -0,0 +1,130 @@
+#include "test-tool.h"
+#include "cache.h"
+#include "run-command.h"
+
+static struct child_process children[2] = {
+	CHILD_PROCESS_INIT,
+	CHILD_PROCESS_INIT,
+};
+
+#define SAY(child, what) \
+	if (write_in_full(children[child].in, \
+			  what "\n", strlen(what) + 1) < 0) \
+		die("Failed to tell child process #%d to %s", child, what)
+
+#define LISTEN(child, what) \
+	if (strbuf_getwholeline_fd(&buf, children[child].out, '\n') < 0) \
+		die("Child process #%d failed to acknowledge %s", child, what)
+
+#define ACK(what) \
+	if (write_in_full(1, what ": ACK\n", strlen(what) + 6) < 0) \
+		die_errno("'%s': %s ACK", child_name, what)
+
+static void contention_orchestrator(const char *argv0)
+{
+	struct strbuf buf = STRBUF_INIT;
+	int i;
+
+	/* Spawn two children and simulate write contention */
+	trace_printf("start");
+
+	for (i = 0; i < 2; i++) {
+		strbuf_reset(&buf);
+		strbuf_addf(&buf, "child #%d", i);
+		argv_array_pushl(&children[i].args,
+					argv0, "trace", "lock", buf.buf, NULL);
+		children[i].in = children[i].out = -1;
+		if (start_command(&children[i]) < 0)
+			die("Could not spawn child process #%d", i);
+	}
+
+	SAY(1, "lock");
+	LISTEN(1, "lock");
+
+	SAY(0, "trace delayed");
+	SAY(1, "trace while-locked");
+	LISTEN(1, "trace");
+
+	SAY(1, "unlock");
+	LISTEN(1, "unlock");
+	LISTEN(0, "trace");
+
+	SAY(0, "quit");
+	SAY(1, "quit");
+
+	if (finish_command(&children[0]) < 0 ||
+		finish_command(&children[1]) < 0)
+		die("Child process failed to finish");
+
+	strbuf_release(&buf);
+}
+
+static void child(const char *child_name)
+{
+	struct strbuf buf = STRBUF_INIT;
+	int fd, locked = 0;
+	const char *p;
+
+	/* This is the child process */
+	trace_printf("child start: '%s'", child_name);
+	fd = trace_default_key.fd;
+	if (fd <= 0)
+		die("child process: not tracing...");
+	while (!strbuf_getwholeline_fd(&buf, 0, '\n')) {
+		strbuf_rtrim(&buf);
+		if (!strcmp("lock", buf.buf)) {
+			if (lock_or_unlock_fd_for_appending(fd, 1) < 0 &&
+			    errno != EBADF)
+				die_errno("'%s': lock", child_name);
+			ACK("lock");
+			locked = 1;
+		} else if (!strcmp("unlock", buf.buf)) {
+			if (lock_or_unlock_fd_for_appending(fd, 0) < 0 &&
+			    errno != EBADF)
+				die_errno("'%s': unlock", child_name);
+			ACK("unlock");
+			locked = 0;
+		} else if (skip_prefix(buf.buf, "trace ", &p)) {
+			if (!locked)
+				trace_printf("%s: %s", child_name, p);
+			else {
+				char *p2 = xstrdup(p);
+
+				/* Give the racy process a run for its money. */
+				sleep_millisec(50);
+
+				strbuf_reset(&buf);
+				strbuf_addf(&buf, "%s: %s\n",
+					    child_name, p2);
+				free(p2);
+
+				if (write_in_full(fd, buf.buf, buf.len) < 0)
+					die_errno("'%s': trace", child_name);
+			}
+			ACK("trace");
+		} else if (!strcmp("quit", buf.buf)) {
+			close(0);
+			close(1);
+			break;
+		} else
+			die("Unhandled command: '%s'", buf.buf);
+
+	}
+
+	strbuf_release(&buf);
+}
+
+int cmd__trace(int argc, const char **argv)
+{
+	const char *argv0 = argv[-1];
+
+	if (argc > 1 && !strcmp("lock", argv[1])) {
+		if (argc > 2)
+			child(argv[2]);
+		else
+			contention_orchestrator(argv0);
+	} else
+		die("Usage: %s %s lock [<child-name>]", argv0, argv[0]);
+
+	return 0;
+}
diff --git a/t/t0070-fundamental.sh b/t/t0070-fundamental.sh
index 23fbe6434..57f7a1246 100755
--- a/t/t0070-fundamental.sh
+++ b/t/t0070-fundamental.sh
@@ -34,4 +34,10 @@ test_expect_success 'check for a bug in the regex routines' '
 	test-tool regex --bug
 '
 
+test_expect_success 'multiple processes can GIT_TRACE to the same file' '
+	GIT_TRACE="$(pwd)/trace" test-tool trace lock &&
+	sed -n "/while-locked/,\$s/.*delayed$/YES/p" <trace >actual &&
+	test YES = "$(cat actual)"
+'
+
 test_done
-- 
gitgitgadget