git/list[1] front-page[2] threads[3] people[4] search[5] about
 

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

From
Johannes Schindelin via GitGitGadget <gitgitgadget@gmail.com>
Date
Aug 9, 2018, 17:35 UTC
Message-ID
<f57234154fb29d0b169442c44e4e683fe1cc3e6c.1533836122.git.gitgitgadget@gmail.com>
In-Reply-To
<pull.17.git.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
Previous: Johannes Schindelin via GitGitGadgetNext: Jeff King
Message 7 of 43 in “t5552: fix flakiness by introducing proper locking for GIT_TRACE”
  1. 0/4 t5552: fix flakiness by introducing proper locking for GIT_TRACEJohannes Schindelin via GitGitGadget, Aug 9, 2018
  2. 1/4 Introduce a function to lock/unlock file descriptors when appendingJohannes Schindelin via GitGitGadget, Aug 9, 2018
  3. Junio C HamanoAug 9, 2018
  4. Johannes SchindelinAug 10, 2018
  5. 2/4 mingw: implement lock_or_unlock_fd_for_appending()Johannes Schindelin via GitGitGadget, Aug 9, 2018
  6. 3/4 trace: lock the trace file to avoid racy trace_write() callsJohannes Schindelin via GitGitGadget, Aug 9, 2018
  7. 4/4 trace: verify that locking worksJohannes Schindelin via GitGitGadget, Aug 9, 2018
  8. Jeff KingAug 9, 2018
  9. Junio C HamanoAug 9, 2018
  10. Junio C HamanoAug 9, 2018
  11. Jeff KingAug 9, 2018
  12. Jeff KingAug 10, 2018
  13. Junio C HamanoAug 10, 2018
  14. Junio C HamanoAug 10, 2018
  15. Johannes SchindelinAug 10, 2018
  16. Jeff KingAug 10, 2018
  17. Junio C HamanoAug 10, 2018
  18. Johannes SchindelinAug 10, 2018
  19. Johannes SixtAug 10, 2018
  20. Jeff HostetlerAug 10, 2018
  21. Jeff HostetlerAug 10, 2018
  22. Johannes SixtAug 10, 2018
  23. Junio C HamanoAug 10, 2018
  24. Jeff KingAug 10, 2018
  25. mingw: enable atomic O_APPENDJohannes Sixt, Aug 13, 2018
  26. Junio C HamanoAug 13, 2018
  27. Johannes SixtAug 13, 2018
  28. Ævar Arnfjörð BjarmasonAug 13, 2018
  29. Junio C HamanoAug 13, 2018
  30. Jeff KingAug 13, 2018
  31. Ævar Arnfjörð BjarmasonAug 14, 2018
  32. Jeff KingAug 14, 2018
  33. Johannes SixtAug 14, 2018
  34. Jeff KingAug 14, 2018
  35. Jeff HostetlerAug 14, 2018
  36. Junio C HamanoAug 14, 2018
  37. 0/4 t5552: fix flakiness by introducing proper locking for GIT_TRACEJohannes Schindelin via GitGitGadget, Aug 10, 2018
  38. 1/4 Introduce a function to lock/unlock file descriptors when appendingJohannes Schindelin via GitGitGadget, Aug 10, 2018
  39. Junio C HamanoAug 10, 2018
  40. Johannes SchindelinAug 10, 2018
  41. 2/4 mingw: implement lock_or_unlock_fd_for_appending()Johannes Schindelin via GitGitGadget, Aug 10, 2018
  42. 3/4 trace: lock the trace file to avoid racy trace_write() callsJohannes Schindelin via GitGitGadget, Aug 10, 2018
  43. 4/4 trace: verify that locking worksJohannes Schindelin via GitGitGadget, Aug 10, 2018

Read the whole thread, see it on lore, or plain text.

$ cat FOOTERMessages come from the public archive at lore.kernel.org/git, fetched every hour. The front page is chosen and written each morning by an AI editor and can be wrong; the threads themselves are the record. About and API. For agents: an MCP server at https://gitlist.dev/mcp, and any thread, story or person page as Markdown by adding .md to its URL (or sending Accept: text/markdown). Details in /llms.txt.