threads / patch / 49085

patch, 4 partst5552: fix flakiness by introducing proper locking for GIT_TRACE

Subject: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

## tl;dr

43 messages between Aug 9, 2018 and Aug 14, 2018. Diffs are folded; open one to read it.

replies: 42people: 6as markdown or json

Johannes Schindelin via GitGitGadget· Aug 9, 2018, 17:35 UTC · lore

I reported a couple of times that t5552 is not passing reliably. It has now reached next, and will no doubt infect master soon.

Turns out that it is not a Windows-specific issue, even if it occurs a lot more often on Windows than elsewhere.

The culprit is that two processes try simultaneously to write to the same file specified via GIT_TRACE_PACKET, and it is not well defined how that should work, even on Linux.

This patch series addresses that by locking the trace fd. I chose to use flock() instead of fcntl() because the Win32 API LockFileEx() [https://docs.microsoft.com/en-us/windows/desktop/api/fileapi/nf-fileapi-lockfileex] (which does exactly what I want in this context) has much more similar semantics to the former than the latter.

Of course, I have to admit that I am not super solid on flock() semantics, and I also do not know which conditional blocks in config.mak.uname should grow a HAVE_FLOCK = YesWeDo line, still. Reviewers knowledgeable in flock() semantics: I would be much indebted if you helped me there. Also: is it safe to call flock() on file descriptors referring not to files, but, say, pipes or an interactive terminal?

Johannes Schindelin (4):
  Introduce a function to lock/unlock file descriptors when appending
  mingw: implement lock_or_unlock_fd_for_appending()
  trace: lock the trace file to avoid racy trace_write() calls
  trace: verify that locking works
 Makefile               |   1 +
 compat/mingw.c         |  19 ++++++
 compat/mingw.h         |   3 +
 config.mak.uname       |   3 +
 git-compat-util.h      |   2 +
 t/helper/test-tool.c   |   1 +
 t/helper/test-tool.h   |   1 +
 t/helper/test-trace.c  | 130 +++++++++++++++++++++++++++++++++++++++++
 t/t0070-fundamental.sh |   6 ++
 trace.c                |  11 +++-
 wrapper.c              |  14 +++++
 11 files changed, 190 insertions(+), 1 deletion(-)
 create mode 100644 t/helper/test-trace.c
base-commit: 42cc7485a2ec49ecc440c921d2eb0cae4da80549
Published-As: https://github.com/gitgitgadget/git/releases/tags/pr-17%2Fdscho%2Ffetch-negotiator-skipping-v1
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-17/dscho/fetch-negotiator-skipping-v1
Pull-Request: https://github.com/gitgitgadget/git/pull/17
-- 
gitgitgadget
Johannes Schindelin via GitGitGadget· Aug 9, 2018, 17:35 UTC · re: Johannes Schindelin via GitGitGadget · lore

[PATCH 1/4] Introduce a function to lock/unlock file descriptors when appending

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

This function will be used to make write accesses in trace_write() a bit safer.

Note: this patch takes a very different approach for cross-platform
support than Git is historically taking: the original approach is to
first implement everything on Linux, using the functions available on
Linux, and then trying to emulate these functions on platforms that do
not have those functions such as Windows.

This leads to all kinds of undesirable quirks in Git's source code (and performance characteristics) because of the lack of a proper abstraction layer: instead of declaring functions for the functionality we *actually* need, we abuse POSIX functions to say what we need, even if those functions serve much broader purposes (and do not make at all clear what the caller wants of them).

For example, when Git wants to determine whether a path refers to a symbolic link, it calls lstat(). That POSIX function has to be emulated on Windows, painstakingly filling all the information lstat() would, only for the caller to throw away everything except that one bit of information, and all of the time figuring out the mtime/atime/ctime and file size and whatnot was spent in vain.

If we were to follow that approach, we would extend the fcntl() emulation in compat/mingw.c after this commit, to support the function added in this commit.

But fcntl() allows a lot more versatile file region locking that we actually need, to by necessity the fcntl() emulation would be quite complex: To support the `l_whence = SEEK_CUR` (which we would use, if it did not require so much book-keeping due to our writing between locking and unlocking the file), we would have to call `SetFilePointerEx()` (after obtaining the `HANDLE` on which all Win32 API functions work instead of the integer file descriptors used by all POSIX functions). Multiplying the number of Win32 API round-trips. Of course, we could implement an incomplete emulation of fcntl()'s F_WRLCK, but that would be unsatisfying.

An alternative approach would be to use the `flock()` function, whose semantics are much closer to existing Win32 API. But `flock()` is not even a POSIX standard, so we would have to implement emulation of `flock()` for *other* platforms. And it would again be the wrong thing to do, as we would once again fail to have an abstraction that clearly says what *exact*functionality we want to use.

To set a precedent for a better approach, let's introduce a proper abstraction: a function that says in its name precisely what Git wants it to do (as opposed to *how* it does it on Linux): lock_or_unlock_fd_for_appending().

The next commit will provide a Windows-specific implementation of this function/functionality.

Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
squash! Introduce a function to lock/unlock file descriptors when appending
---
 git-compat-util.h |  2 ++
 wrapper.c         | 14 ++++++++++++++
 2 files changed, 16 insertions(+)
Show changes to 2 files +16 −0

git-compat-util.h, wrapper.c

diff --git a/git-compat-util.h b/git-compat-util.h
index 9a64998b2..13b83bade 100644
--- a/git-compat-util.h
+++ b/git-compat-util.h
@@ -1202,6 +1202,8 @@ struct tm *git_gmtime_r(const time_t *, struct tm *);
 #define getc_unlocked(fh) getc(fh)
 #endif
 
+extern int lock_or_unlock_fd_for_appending(int fd, int lock_it);
+
 /*
  * Our code often opens a path to an optional file, to work on its
  * contents when we can successfully open it.  We can ignore a failure
diff --git a/wrapper.c b/wrapper.c
index e4fa9d84c..6c2116272 100644
--- a/wrapper.c
+++ b/wrapper.c
@@ -690,3 +690,17 @@ int xgethostname(char *buf, size_t len)
 		buf[len - 1] = 0;
 	return ret;
 }
+
+#ifndef GIT_WINDOWS_NATIVE
+int lock_or_unlock_fd_for_appending(int fd, int lock_it)
+{
+	struct flock flock;
+
+	flock.l_type = lock_it ? F_WRLCK : F_UNLCK;
+	flock.l_whence = SEEK_SET;
+	flock.l_start = 0;
+	flock.l_len = 0xffffffff; /* arbitrary number of bytes */
+
+	return fcntl(fd, F_SETLKW, &flock);
+}
+#endif
-- 
gitgitgadget
Junio C Hamano· Aug 9, 2018, 19:01 UTC · re: Johannes Schindelin via GitGitGadget · lore

Re: [PATCH 1/4] Introduce a function to lock/unlock file descriptors when appending

"Johannes Schindelin via GitGitGadget" <gitgitgadget@gmail.com> writes:

Show 16 quoted lines
> From: Johannes Schindelin <johannes.schindelin@gmx.de>
>
> This function will be used to make write accesses in trace_write() a bit
> safer.
> ...
> To set a precedent for a better approach, let's introduce a proper
> abstraction: a function that says in its name precisely what Git
> wants it to do (as opposed to *how* it does it on Linux):
> lock_or_unlock_fd_for_appending().
>
> The next commit will provide a Windows-specific implementation of this
> function/functionality.
>
> Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
>
> squash! Introduce a function to lock/unlock file descriptors when appending

If we can keep the custom, narrow and easy-to-port API (like this patch introduces) focused and resist feature creep over time, then it would be worth spending effort to come up with such a custom helper that is easy to port. So I agree with the approach in general but I tend to think "set a precedent for a better approach" is a way-too-early and wishful verdict. We do not know if we can really keep that custom API easy-to-port-and-maintain yet.

In short, even though I agree with the approach, most of the verbiage above is unnecessary and mere distraction.

Show 36 quoted lines
> ---
>  git-compat-util.h |  2 ++
>  wrapper.c         | 14 ++++++++++++++
>  2 files changed, 16 insertions(+)
>
> diff --git a/git-compat-util.h b/git-compat-util.h
> index 9a64998b2..13b83bade 100644
> --- a/git-compat-util.h
> +++ b/git-compat-util.h
> @@ -1202,6 +1202,8 @@ struct tm *git_gmtime_r(const time_t *, struct tm *);
>  #define getc_unlocked(fh) getc(fh)
>  #endif
>  
> +extern int lock_or_unlock_fd_for_appending(int fd, int lock_it);
> +
>  /*
>   * Our code often opens a path to an optional file, to work on its
>   * contents when we can successfully open it.  We can ignore a failure
> diff --git a/wrapper.c b/wrapper.c
> index e4fa9d84c..6c2116272 100644
> --- a/wrapper.c
> +++ b/wrapper.c
> @@ -690,3 +690,17 @@ int xgethostname(char *buf, size_t len)
>  		buf[len - 1] = 0;
>  	return ret;
>  }
> +
> +#ifndef GIT_WINDOWS_NATIVE
> +int lock_or_unlock_fd_for_appending(int fd, int lock_it)
> +{
> +	struct flock flock;
> +
> +	flock.l_type = lock_it ? F_WRLCK : F_UNLCK;
> +	flock.l_whence = SEEK_SET;
> +	flock.l_start = 0;
> +	flock.l_len = 0xffffffff; /* arbitrary number of bytes */

If this can be an arbitrary range, do we need to cover this many (or only this few, depending on your point of view) bytes?

Would it be sufficient to cover just the first one byte instead? Or perhaps give l_len==0 to cover all no matter how large the file grows, which sounds like a better range specification.

> +	return fcntl(fd, F_SETLKW, &flock);
> +}
> +#endif
Johannes Schindelin· Aug 10, 2018, 18:32 UTC · re: Junio C Hamano · lore

Re: [PATCH 1/4] Introduce a function to lock/unlock file descriptors when appending

Hi Junio,
On Thu, 9 Aug 2018, Junio C Hamano wrote:
Show 30 quoted lines
> "Johannes Schindelin via GitGitGadget" <gitgitgadget@gmail.com>
> writes:
> 
> > From: Johannes Schindelin <johannes.schindelin@gmx.de>
> >
> > This function will be used to make write accesses in trace_write() a bit
> > safer.
> > ...
> > To set a precedent for a better approach, let's introduce a proper
> > abstraction: a function that says in its name precisely what Git
> > wants it to do (as opposed to *how* it does it on Linux):
> > lock_or_unlock_fd_for_appending().
> >
> > The next commit will provide a Windows-specific implementation of this
> > function/functionality.
> >
> > Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
> >
> > squash! Introduce a function to lock/unlock file descriptors when appending
> 
> If we can keep the custom, narrow and easy-to-port API (like this
> patch introduces) focused and resist feature creep over time, then
> it would be worth spending effort to come up with such a custom
> helper that is easy to port.  So I agree with the approach in
> general but I tend to think "set a precedent for a better approach"
> is a way-too-early and wishful verdict.  We do not know if we can
> really keep that custom API easy-to-port-and-maintain yet.
> 
> In short, even though I agree with the approach, most of the
> verbiage above is unnecessary and mere distraction.

I disagree that it is a distraction, because the commit messages are the very location where I am supposed to detail my rationale, motivation, and considerations that are not obvious from the diff alone.

Of course, I cannot force you to take this commit message, you can overrule me and edit it. But you would do this against my express wish.

Show 39 quoted lines
> > ---
> >  git-compat-util.h |  2 ++
> >  wrapper.c         | 14 ++++++++++++++
> >  2 files changed, 16 insertions(+)
> >
> > diff --git a/git-compat-util.h b/git-compat-util.h
> > index 9a64998b2..13b83bade 100644
> > --- a/git-compat-util.h
> > +++ b/git-compat-util.h
> > @@ -1202,6 +1202,8 @@ struct tm *git_gmtime_r(const time_t *, struct tm *);
> >  #define getc_unlocked(fh) getc(fh)
> >  #endif
> >  
> > +extern int lock_or_unlock_fd_for_appending(int fd, int lock_it);
> > +
> >  /*
> >   * Our code often opens a path to an optional file, to work on its
> >   * contents when we can successfully open it.  We can ignore a failure
> > diff --git a/wrapper.c b/wrapper.c
> > index e4fa9d84c..6c2116272 100644
> > --- a/wrapper.c
> > +++ b/wrapper.c
> > @@ -690,3 +690,17 @@ int xgethostname(char *buf, size_t len)
> >  		buf[len - 1] = 0;
> >  	return ret;
> >  }
> > +
> > +#ifndef GIT_WINDOWS_NATIVE
> > +int lock_or_unlock_fd_for_appending(int fd, int lock_it)
> > +{
> > +	struct flock flock;
> > +
> > +	flock.l_type = lock_it ? F_WRLCK : F_UNLCK;
> > +	flock.l_whence = SEEK_SET;
> > +	flock.l_start = 0;
> > +	flock.l_len = 0xffffffff; /* arbitrary number of bytes */
> 
> If this can be an arbitrary range, do we need to cover this many (or
> only this few, depending on your point of view) bytes?

It can be an arbitrary range, but it does not matter at this point because we expect only appending callers. Therefore any range will do, as long as it covers the range of bytes to be written by the trace functions. And with 0-0xffffffff, I am fairly certain we got it.

Technically, we could even lock the range 0-1, as all of our callers would agree on that, and block each other. Other Git implementations might not, though. So 0-0xffffffff is my best bet and cheap.

> Would it be sufficient to cover just the first one byte instead?

As I said, this would depend on no other software trying to append to the trace file, including alternative Git implementations.

In other words: it would be "too clever". Clever, but asking for problems.
> Or perhaps give l_len==0 to cover all no matter how large the file
> grows, which sounds like a better range specification.
I must have overlooked that option in the documentation.
*clicketyclick*

Indeed, http://pubs.opengroup.org/onlinepubs/9699919799/functions/fcntl.html spells it out pretty clearly:

> A lock shall be set to extend to the largest possible value of the file
> offset for that file by setting l_len to 0. If such a lock also has
> l_start set to 0 and l_whence is set to SEEK_SET, the whole file shall
> be locked.
Sorry about missing this. I will change the implementation to this.
> > +	return fcntl(fd, F_SETLKW, &flock);
> > +}
> > +#endif

Thanks for helping me improve the patch, Dscho

Johannes Schindelin via GitGitGadget· Aug 9, 2018, 17:35 UTC · re: Johannes Schindelin via GitGitGadget · lore

[PATCH 2/4] mingw: implement lock_or_unlock_fd_for_appending()

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

For some reason, t/t5552-skipping-fetch-negotiator.sh fails particularly often on Windows due to racy tracing where the `git upload-pack` and the `git fetch` processes compete for the same file.

We just introduced a remedy that uses fcntl(), but Windows does not have fcntl(). So let's implement an alternative.

Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
---
 compat/mingw.c   | 19 +++++++++++++++++++
 compat/mingw.h   |  3 +++
 config.mak.uname |  3 +++
 3 files changed, 25 insertions(+)
Show changes to 3 files +25 −0

compat/mingw.c, compat/mingw.h, config.mak.uname

diff --git a/compat/mingw.c b/compat/mingw.c
index 6ded1c859..6da9ce861 100644
--- a/compat/mingw.c
+++ b/compat/mingw.c
@@ -514,6 +514,25 @@ int mingw_chmod(const char *filename, int mode)
 	return _wchmod(wfilename, mode);
 }
 
+int mingw_lock_or_unlock_fd_for_appending(int fd, int lock_it)
+{
+	HANDLE handle = (HANDLE)_get_osfhandle(fd);
+	OVERLAPPED overlapped = { 0 };
+	DWORD err;
+
+	if (!lock_it && UnlockFileEx(handle, 0, -1, 0, &overlapped))
+		return 0;
+	if (lock_it &&
+	    LockFileEx(handle, LOCKFILE_EXCLUSIVE_LOCK, 0, -1, 0, &overlapped))
+		return 0;
+
+	err = GetLastError();
+	/* LockFileEx() cannot lock pipes */
+	errno = err == ERROR_INVALID_FUNCTION ?
+		EBADF : err_win_to_posix(GetLastError());
+	return -1;
+}
+
 /*
  * The unit of FILETIME is 100-nanoseconds since January 1, 1601, UTC.
  * Returns the 100-nanoseconds ("hekto nanoseconds") since the epoch.
diff --git a/compat/mingw.h b/compat/mingw.h
index 571019d0b..0f76d89a9 100644
--- a/compat/mingw.h
+++ b/compat/mingw.h
@@ -397,6 +397,9 @@ HANDLE winansi_get_osfhandle(int fd);
  * git specific compatibility
  */
 
+int mingw_lock_or_unlock_fd_for_appending(int fd, int lock_it);
+#define lock_or_unlock_fd_for_appending mingw_lock_or_unlock_fd_for_appending
+
 #define has_dos_drive_prefix(path) \
 	(isalpha(*(path)) && (path)[1] == ':' ? 2 : 0)
 int mingw_skip_dos_drive_prefix(char **path);
diff --git a/config.mak.uname b/config.mak.uname
index 684fc5bf0..159b7da81 100644
--- a/config.mak.uname
+++ b/config.mak.uname
@@ -376,6 +376,7 @@ ifeq ($(uname_S),Windows)
 	NO_POSIX_GOODIES = UnfortunatelyYes
 	NATIVE_CRLF = YesPlease
 	DEFAULT_HELP_FORMAT = html
+	HAVE_FLOCK = YesWeEmulate
 
 	CC = compat/vcbuild/scripts/clink.pl
 	AR = compat/vcbuild/scripts/lib.pl
@@ -523,6 +524,8 @@ ifneq (,$(findstring MINGW,$(uname_S)))
 	NO_INET_NTOP = YesPlease
 	NO_POSIX_GOODIES = UnfortunatelyYes
 	DEFAULT_HELP_FORMAT = html
+	HAVE_FLOCK = YesWeEmulate
+
 	COMPAT_CFLAGS += -DNOGDI -Icompat -Icompat/win32
 	COMPAT_CFLAGS += -DSTRIP_EXTENSION=\".exe\"
 	COMPAT_OBJS += compat/mingw.o compat/winansi.o \
-- 
gitgitgadget
Johannes Schindelin via GitGitGadget· Aug 9, 2018, 17:35 UTC · re: Johannes Schindelin via GitGitGadget · lore

[PATCH 3/4] trace: lock the trace file to avoid racy trace_write() calls

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

When multiple processes try to write to the same file, it is not guaranteed that everything works as expected: those writes can overlap, and in the worst case even lose messages.

This happens in t/t5552-skipping-fetch-negotiator.sh, where we abuse the `GIT_TRACE` facility to write traces of two concurrent processes (`git fetch` and `git upload-pack`) to the same file, and then verify that the trace contains certain expected breadcrumbs.

To remedy this, let's lock the file descriptors for exclusive writing, using the function we just introduced in the previous commit.

Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
---
 trace.c | 11 ++++++++++-
 1 file changed, 10 insertions(+), 1 deletion(-)
Show changes to trace.c +10 −1
diff --git a/trace.c b/trace.c
index fc623e91f..6f97dde27 100644
--- a/trace.c
+++ b/trace.c
@@ -114,11 +114,20 @@ static int prepare_trace_line(const char *file, int line,
 
 static void trace_write(struct trace_key *key, const void *buf, unsigned len)
 {
-	if (write_in_full(get_trace_fd(key), buf, len) < 0) {
+	int fd = get_trace_fd(key), locked;
+
+	locked = !lock_or_unlock_fd_for_appending(fd, 1);
+	if (!locked && errno != EBADF)
+		warning("unable to lock file descriptor for %s: %s",
+			key->key, strerror(errno));
+	if (write_in_full(fd, buf, len) < 0) {
 		warning("unable to write trace for %s: %s",
 			key->key, strerror(errno));
 		trace_disable(key);
 	}
+	if (locked && lock_or_unlock_fd_for_appending(fd, 0) < 0)
+		warning("failed to remove lock on fd for %s: %s",
+			key->key, strerror(errno));
 }
 
 void trace_verbatim(struct trace_key *key, const void *buf, unsigned len)
-- 
gitgitgadget
Johannes Schindelin via GitGitGadget· Aug 9, 2018, 17:35 UTC · re: Johannes Schindelin via GitGitGadget · lore

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

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
Show changes to 5 files +139 −0

Makefile, t/helper/test-tool.c, t/helper/test-tool.h, t/helper/test-trace.c, t/t0070-fundamental.sh

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
Jeff King· Aug 9, 2018, 19:47 UTC · re: Johannes Schindelin via GitGitGadget · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

On Thu, Aug 09, 2018 at 10:35:24AM -0700, Johannes Schindelin via GitGitGadget wrote:
> The culprit is that two processes try simultaneously to write to the same
> file specified via GIT_TRACE_PACKET, and it is not well defined how that
> should work, even on Linux.

Are you sure that it's not well-defined? We open the path with O_APPEND, which means every write() will be atomically positioned at the end of file. So we would never lose or overwrite data.

We do our own buffering in a strbuf, writing the result out in a single write() call (modulo the OS returning a short write, but that should not generally happen when writing short strings to a file). So we should get individual trace lines as atomic units.

The order of lines from the two processes is undefined, of course.
Show 5 quoted lines
> This patch series addresses that by locking the trace fd. I chose to use 
> flock() instead of fcntl() because the Win32 API LockFileEx()
> [https://docs.microsoft.com/en-us/windows/desktop/api/fileapi/nf-fileapi-lockfileex] 
> (which does exactly what I want in this context) has much more similar
> semantics to the former than the latter.

I must admit I'm not excited to see us adding extra locking and complexity when it is not necessarily needed. Is this a feature we actually care about delivering for normal users of GIT_TRACE, or do we just care about solving the test flakiness here?

Because we should be able to do the latter with the patch below.

I also wonder if we should be clearing GIT_TRACE as part of clearing repo-env. It would do what we want automatically in this case, though there are definitely cases where I prefer the current behavior (because I really do want to see the upload-pack side of it). Of course I could always use "--upload-pack 'GIT_TRACE_PACKET=... upload-pack'", so this is really just a default.

Show changes to t/t5552-skipping-fetch-negotiator.sh +18 −5
diff --git a/t/t5552-skipping-fetch-negotiator.sh b/t/t5552-skipping-fetch-negotiator.sh
index 3b60bd44e0..5ad5bece55 100755
--- a/t/t5552-skipping-fetch-negotiator.sh
+++ b/t/t5552-skipping-fetch-negotiator.sh
@@ -28,6 +28,19 @@ have_not_sent () {
 	done
 }
 
+# trace_fetch <client_dir> <server_dir> [args]
+#
+# Trace the packet output of fetch, but make sure we disable the variable
+# in the child upload-pack, so we don't combine the results in the same file.
+trace_fetch () {
+	client=$1; shift
+	server=$1; shift
+	GIT_TRACE_PACKET="$(pwd)/trace" \
+	git -C "$client" fetch \
+	  --upload-pack 'unset GIT_TRACE_PACKET; git-upload-pack' \
+	  "$server" "$@"
+}
+
 test_expect_success 'commits with no parents are sent regardless of skip distance' '
 	git init server &&
 	test_commit -C server to_fetch &&
@@ -42,7 +55,7 @@ test_expect_success 'commits with no parents are sent regardless of skip distanc
 	# "c1" has no parent, it is still sent as "have" even though it would
 	# normally be skipped.
 	test_config -C client fetch.negotiationalgorithm skipping &&
-	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
+	trace_fetch client "$(pwd)/server" &&
 	have_sent c7 c5 c2 c1 &&
 	have_not_sent c6 c4 c3
 '
@@ -88,7 +101,7 @@ test_expect_success 'when two skips collide, favor the larger one' '
 	# the next "have" sent will be "c1" (from "c6" skip 4) and not "c4"
 	# (from "c5side" skip 1).
 	test_config -C client fetch.negotiationalgorithm skipping &&
-	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
+	trace_fetch client "$(pwd)/server" &&
 	have_sent c5side c11 c9 c6 c1 &&
 	have_not_sent c10 c8 c7 c5 c4 c3 c2
 '
@@ -114,7 +127,7 @@ test_expect_success 'use ref advertisement to filter out commits' '
 	# not need to send any ancestors of "c3", but we still need to send "c3"
 	# itself.
 	test_config -C client fetch.negotiationalgorithm skipping &&
-	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch origin to_fetch &&
+	trace_fetch client origin to_fetch &&
 	have_sent c5 c4^ c2side &&
 	have_not_sent c4 c4^^ c4^^^
 '
@@ -144,7 +157,7 @@ test_expect_success 'handle clock skew' '
 	# and sent, because (due to clock skew) its only parent has already been
 	# popped off the priority queue.
 	test_config -C client fetch.negotiationalgorithm skipping &&
-	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
+	trace_fetch client "$(pwd)/server" &&
 	have_sent c2 c1 old4 old2 old1 &&
 	have_not_sent old3
 '
@@ -176,7 +189,7 @@ test_expect_success 'do not send "have" with ancestors of commits that server AC
 	test_commit -C server commit-on-b1 &&
 
 	test_config -C client fetch.negotiationalgorithm skipping &&
-	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" to_fetch &&
+	trace_fetch client "$(pwd)/server" to_fetch &&
 	grep "  fetch" trace &&
 
 	# fetch-pack sends 2 requests each containing 16 "have" lines before
Junio C Hamano· Aug 9, 2018, 20:49 UTC · re: Jeff King · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

Jeff King <peff@peff.net> writes:
Show 10 quoted lines
> Are you sure that it's not well-defined? We open the path with O_APPEND,
> which means every write() will be atomically positioned at the end of
> file. So we would never lose or overwrite data.
>
> We do our own buffering in a strbuf, writing the result out in a single
> write() call (modulo the OS returning a short write, but that should not
> generally happen when writing short strings to a file). So we should get
> individual trace lines as atomic units.
>
> The order of lines from the two processes is undefined, of course.

Correct. But I am more worried about the "mixed/overwriting" breakage, if there is one; it means we may need to be prepared for systems that lack O_APPEND that works correctly. I initially just assumed that it was what Dscho was seeing, but after re-reading his message, I am not sure anymore.

I think the "do not trace the other side" approach you suggest for these tests that only care about one side is more appropriate solution for this particular case. We then do not have to worry about overwriting or output from both sides mixed randomly.

Show 69 quoted lines
> diff --git a/t/t5552-skipping-fetch-negotiator.sh b/t/t5552-skipping-fetch-negotiator.sh
> index 3b60bd44e0..5ad5bece55 100755
> --- a/t/t5552-skipping-fetch-negotiator.sh
> +++ b/t/t5552-skipping-fetch-negotiator.sh
> @@ -28,6 +28,19 @@ have_not_sent () {
>  	done
>  }
>  
> +# trace_fetch <client_dir> <server_dir> [args]
> +#
> +# Trace the packet output of fetch, but make sure we disable the variable
> +# in the child upload-pack, so we don't combine the results in the same file.
> +trace_fetch () {
> +	client=$1; shift
> +	server=$1; shift
> +	GIT_TRACE_PACKET="$(pwd)/trace" \
> +	git -C "$client" fetch \
> +	  --upload-pack 'unset GIT_TRACE_PACKET; git-upload-pack' \
> +	  "$server" "$@"
> +}
> +
>  test_expect_success 'commits with no parents are sent regardless of skip distance' '
>  	git init server &&
>  	test_commit -C server to_fetch &&
> @@ -42,7 +55,7 @@ test_expect_success 'commits with no parents are sent regardless of skip distanc
>  	# "c1" has no parent, it is still sent as "have" even though it would
>  	# normally be skipped.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c7 c5 c2 c1 &&
>  	have_not_sent c6 c4 c3
>  '
> @@ -88,7 +101,7 @@ test_expect_success 'when two skips collide, favor the larger one' '
>  	# the next "have" sent will be "c1" (from "c6" skip 4) and not "c4"
>  	# (from "c5side" skip 1).
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c5side c11 c9 c6 c1 &&
>  	have_not_sent c10 c8 c7 c5 c4 c3 c2
>  '
> @@ -114,7 +127,7 @@ test_expect_success 'use ref advertisement to filter out commits' '
>  	# not need to send any ancestors of "c3", but we still need to send "c3"
>  	# itself.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch origin to_fetch &&
> +	trace_fetch client origin to_fetch &&
>  	have_sent c5 c4^ c2side &&
>  	have_not_sent c4 c4^^ c4^^^
>  '
> @@ -144,7 +157,7 @@ test_expect_success 'handle clock skew' '
>  	# and sent, because (due to clock skew) its only parent has already been
>  	# popped off the priority queue.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c2 c1 old4 old2 old1 &&
>  	have_not_sent old3
>  '
> @@ -176,7 +189,7 @@ test_expect_success 'do not send "have" with ancestors of commits that server AC
>  	test_commit -C server commit-on-b1 &&
>  
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" to_fetch &&
> +	trace_fetch client "$(pwd)/server" to_fetch &&
>  	grep "  fetch" trace &&
>  
>  	# fetch-pack sends 2 requests each containing 16 "have" lines before
Junio C Hamano· Aug 9, 2018, 21:08 UTC · re: Junio C Hamano · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

Junio C Hamano <gitster@pobox.com> writes:
Show 23 quoted lines
> Jeff King <peff@peff.net> writes:
>
>> Are you sure that it's not well-defined? We open the path with O_APPEND,
>> which means every write() will be atomically positioned at the end of
>> file. So we would never lose or overwrite data.
>>
>> We do our own buffering in a strbuf, writing the result out in a single
>> write() call (modulo the OS returning a short write, but that should not
>> generally happen when writing short strings to a file). So we should get
>> individual trace lines as atomic units.
>>
>> The order of lines from the two processes is undefined, of course.
>
> Correct.  But I am more worried about the "mixed/overwriting"
> breakage, if there is one; it means we may need to be prepared for
> systems that lack O_APPEND that works correctly.  I initially just
> assumed that it was what Dscho was seeing, but after re-reading his
> message, I am not sure anymore.
>
> I think the "do not trace the other side" approach you suggest for
> these tests that only care about one side is more appropriate
> solution for this particular case.  We then do not have to worry
> about overwriting or output from both sides mixed randomly.

A concluding sentence I forgot to add, after saying "this is simpler and better to fix test breakage", was

	But if we really are seeing O_APPEND breakage, a mandatory
	locking mechanism like this one might be necessary to work
	around it (I seriously hope we do not have to, though).
Sorry for an additional noise.
Jeff King· Aug 9, 2018, 21:32 UTC · re: Junio C Hamano · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

On Thu, Aug 09, 2018 at 02:08:56PM -0700, Junio C Hamano wrote:
Show 19 quoted lines
> > Correct.  But I am more worried about the "mixed/overwriting"
> > breakage, if there is one; it means we may need to be prepared for
> > systems that lack O_APPEND that works correctly.  I initially just
> > assumed that it was what Dscho was seeing, but after re-reading his
> > message, I am not sure anymore.
> >
> > I think the "do not trace the other side" approach you suggest for
> > these tests that only care about one side is more appropriate
> > solution for this particular case.  We then do not have to worry
> > about overwriting or output from both sides mixed randomly.
> 
> A concluding sentence I forgot to add, after saying "this is simpler
> and better to fix test breakage", was
> 
> 	But if we really are seeing O_APPEND breakage, a mandatory
> 	locking mechanism like this one might be necessary to work
> 	around it (I seriously hope we do not have to, though).
> 
> Sorry for an additional noise.
Yeah, my earlier email said "if we just care about this test, then...".

But if we do care about making this multiple-tracing case work all the time, then we'd need some solution. If there's something that can work like O_APPEND, even if we have to make some system-specific call, I'd prefer that to locking.

I did some searching for atomic append on Windows and got mixed reports on whether their FILE_DATA_APPEND does what we want or not. Knowing nothing about msys, I'd _assume_ that O_APPEND would get translated to that flag, but I got lost trying to find it in git-for-windows/msys2-runtime.

Wouldn't it be wonderful if the solution were as simple as making sure that flag was plumbed through? I seriously doubt it will be that easy, though. :)

-Peff
Jeff King· Aug 10, 2018, 14:09 UTC · re: Junio C Hamano · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

On Thu, Aug 09, 2018 at 01:49:52PM -0700, Junio C Hamano wrote:
Show 23 quoted lines
> Jeff King <peff@peff.net> writes:
> 
> > Are you sure that it's not well-defined? We open the path with O_APPEND,
> > which means every write() will be atomically positioned at the end of
> > file. So we would never lose or overwrite data.
> >
> > We do our own buffering in a strbuf, writing the result out in a single
> > write() call (modulo the OS returning a short write, but that should not
> > generally happen when writing short strings to a file). So we should get
> > individual trace lines as atomic units.
> >
> > The order of lines from the two processes is undefined, of course.
> 
> Correct.  But I am more worried about the "mixed/overwriting"
> breakage, if there is one; it means we may need to be prepared for
> systems that lack O_APPEND that works correctly.  I initially just
> assumed that it was what Dscho was seeing, but after re-reading his
> message, I am not sure anymore.
> 
> I think the "do not trace the other side" approach you suggest for
> these tests that only care about one side is more appropriate
> solution for this particular case.  We then do not have to worry
> about overwriting or output from both sides mixed randomly.

Here it is as a patch on top of jt/fetch-negotiator-skipping, which lets us pursue any fix for interleaved trace output on Windows without the pressure of an impending flaky test.

My gut says that looking into making O_APPEND work there is going to be the nicest solution, but my gut is not very well versed in Windows subtleties. ;)

-- >8 --
Subject: [PATCH] t5552: suppress upload-pack trace output

The t5552 test script uses GIT_TRACE_PACKET to monitor what git-fetch sends and receives. However, because we're accessing a local repository, the child upload-pack also sends trace output to the same file.

On Linux, this works out OK. We open the trace file with O_APPEND, so all writes are atomically positioned at the end of the file. No data can be overwritten or omitted. And since we prepare our small writes in a strbuf and write them with a single write(), we should see each line as an atomic unit. The order of lines between the two processes is undefined, but the test script greps only for "fetch>" or "fetch<" lines. So under Linux, the test results are deterministic.

The test fails intermittently on Windows, however, reportedly even overwriting bits of the output file (i.e., O_APPEND does not seem to give us an atomic position+write).

Since the test only cares about the trace output from fetch, we can just disable the output from upload-pack. That doesn't solve the greater question of O_APPEND/trace issues under Windows, but it easily fixes the flakiness from this test.

Reported-by: Johannes Schindelin <johannes.schindelin@gmx.de>
Signed-off-by: Jeff King <peff@peff.net>
---
I'm assuming that this really isn't triggerable on Linux. I tried and
couldn't manage to get it to fail, and the reasoning above explains why.
But I wasn't 100% clear that Dscho hadn't seen it fail on non-Windows.
 t/t5552-skipping-fetch-negotiator.sh | 23 ++++++++++++++++++-----
 1 file changed, 18 insertions(+), 5 deletions(-)
Show changes to t/t5552-skipping-fetch-negotiator.sh +18 −5
diff --git a/t/t5552-skipping-fetch-negotiator.sh b/t/t5552-skipping-fetch-negotiator.sh
index 0a8e0e42ed..0ad50dd839 100755
--- a/t/t5552-skipping-fetch-negotiator.sh
+++ b/t/t5552-skipping-fetch-negotiator.sh
@@ -28,6 +28,19 @@ have_not_sent () {
 	done
 }
 
+# trace_fetch <client_dir> <server_dir> [args]
+#
+# Trace the packet output of fetch, but make sure we disable the variable
+# in the child upload-pack, so we don't combine the results in the same file.
+trace_fetch () {
+	client=$1; shift
+	server=$1; shift
+	GIT_TRACE_PACKET="$(pwd)/trace" \
+	git -C "$client" fetch \
+	  --upload-pack 'unset GIT_TRACE_PACKET; git-upload-pack' \
+	  "$server" "$@"
+}
+
 test_expect_success 'commits with no parents are sent regardless of skip distance' '
 	git init server &&
 	test_commit -C server to_fetch &&
@@ -42,7 +55,7 @@ test_expect_success 'commits with no parents are sent regardless of skip distanc
 	# "c1" has no parent, it is still sent as "have" even though it would
 	# normally be skipped.
 	test_config -C client fetch.negotiationalgorithm skipping &&
-	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
+	trace_fetch client "$(pwd)/server" &&
 	have_sent c7 c5 c2 c1 &&
 	have_not_sent c6 c4 c3
 '
@@ -65,7 +78,7 @@ test_expect_success 'when two skips collide, favor the larger one' '
 	# the next "have" sent will be "c1" (from "c6" skip 4) and not "c4"
 	# (from "c5side" skip 1).
 	test_config -C client fetch.negotiationalgorithm skipping &&
-	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
+	trace_fetch client "$(pwd)/server" &&
 	have_sent c5side c11 c9 c6 c1 &&
 	have_not_sent c10 c8 c7 c5 c4 c3 c2
 '
@@ -91,7 +104,7 @@ test_expect_success 'use ref advertisement to filter out commits' '
 	# not need to send any ancestors of "c3", but we still need to send "c3"
 	# itself.
 	test_config -C client fetch.negotiationalgorithm skipping &&
-	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch origin to_fetch &&
+	trace_fetch client origin to_fetch &&
 	have_sent c5 c4^ c2side &&
 	have_not_sent c4 c4^^ c4^^^
 '
@@ -121,7 +134,7 @@ test_expect_success 'handle clock skew' '
 	# and sent, because (due to clock skew) its only parent has already been
 	# popped off the priority queue.
 	test_config -C client fetch.negotiationalgorithm skipping &&
-	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
+	trace_fetch client "$(pwd)/server" &&
 	have_sent c2 c1 old4 old2 old1 &&
 	have_not_sent old3
 '
@@ -153,7 +166,7 @@ test_expect_success 'do not send "have" with ancestors of commits that server AC
 	test_commit -C server commit-on-b1 &&
 
 	test_config -C client fetch.negotiationalgorithm skipping &&
-	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" to_fetch &&
+	trace_fetch client "$(pwd)/server" to_fetch &&
 	grep "  fetch" trace &&
 
 	# fetch-pack sends 2 requests each containing 16 "have" lines before
-- 
2.18.0.1058.g0926f0b71f
Junio C Hamano· Aug 10, 2018, 15:58 UTC · re: Jeff King · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

Jeff King <peff@peff.net> writes:
Show 7 quoted lines
> Here it is as a patch on top of jt/fetch-negotiator-skipping, which lets
> us pursue any fix for interleaved trace output on Windows without the
> pressure of an impending flaky test.
>
> My gut says that looking into making O_APPEND work there is going to be
> the nicest solution, but my gut is not very well versed in Windows
> subtleties. ;)

As we know these tests are only interested in "fetch" lines and not record of communication in the other direction, I think this is a nice clean-up that is worth doing.

For only two grep's it may not look worth doing, but it would be also a good clean-up to give an got_acked helper that sits next to have_sent and have_not_sent helpers for readability. That is of course outside the scope of this change.

Will queue.  Thansk.
Show 107 quoted lines
> -- >8 --
> Subject: [PATCH] t5552: suppress upload-pack trace output
>
> The t5552 test script uses GIT_TRACE_PACKET to monitor what
> git-fetch sends and receives. However, because we're
> accessing a local repository, the child upload-pack also
> sends trace output to the same file.
>
> On Linux, this works out OK. We open the trace file with
> O_APPEND, so all writes are atomically positioned at the end
> of the file. No data can be overwritten or omitted. And
> since we prepare our small writes in a strbuf and write them
> with a single write(), we should see each line as an atomic
> unit. The order of lines between the two processes is
> undefined, but the test script greps only for "fetch>" or
> "fetch<" lines. So under Linux, the test results are
> deterministic.
>
> The test fails intermittently on Windows, however,
> reportedly even overwriting bits of the output file (i.e.,
> O_APPEND does not seem to give us an atomic position+write).
>
> Since the test only cares about the trace output from fetch,
> we can just disable the output from upload-pack. That
> doesn't solve the greater question of O_APPEND/trace issues
> under Windows, but it easily fixes the flakiness from this
> test.
>
> Reported-by: Johannes Schindelin <johannes.schindelin@gmx.de>
> Signed-off-by: Jeff King <peff@peff.net>
> ---
> I'm assuming that this really isn't triggerable on Linux. I tried and
> couldn't manage to get it to fail, and the reasoning above explains why.
> But I wasn't 100% clear that Dscho hadn't seen it fail on non-Windows.
>
>  t/t5552-skipping-fetch-negotiator.sh | 23 ++++++++++++++++++-----
>  1 file changed, 18 insertions(+), 5 deletions(-)
>
> diff --git a/t/t5552-skipping-fetch-negotiator.sh b/t/t5552-skipping-fetch-negotiator.sh
> index 0a8e0e42ed..0ad50dd839 100755
> --- a/t/t5552-skipping-fetch-negotiator.sh
> +++ b/t/t5552-skipping-fetch-negotiator.sh
> @@ -28,6 +28,19 @@ have_not_sent () {
>  	done
>  }
>  
> +# trace_fetch <client_dir> <server_dir> [args]
> +#
> +# Trace the packet output of fetch, but make sure we disable the variable
> +# in the child upload-pack, so we don't combine the results in the same file.
> +trace_fetch () {
> +	client=$1; shift
> +	server=$1; shift
> +	GIT_TRACE_PACKET="$(pwd)/trace" \
> +	git -C "$client" fetch \
> +	  --upload-pack 'unset GIT_TRACE_PACKET; git-upload-pack' \
> +	  "$server" "$@"
> +}
> +
>  test_expect_success 'commits with no parents are sent regardless of skip distance' '
>  	git init server &&
>  	test_commit -C server to_fetch &&
> @@ -42,7 +55,7 @@ test_expect_success 'commits with no parents are sent regardless of skip distanc
>  	# "c1" has no parent, it is still sent as "have" even though it would
>  	# normally be skipped.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c7 c5 c2 c1 &&
>  	have_not_sent c6 c4 c3
>  '
> @@ -65,7 +78,7 @@ test_expect_success 'when two skips collide, favor the larger one' '
>  	# the next "have" sent will be "c1" (from "c6" skip 4) and not "c4"
>  	# (from "c5side" skip 1).
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c5side c11 c9 c6 c1 &&
>  	have_not_sent c10 c8 c7 c5 c4 c3 c2
>  '
> @@ -91,7 +104,7 @@ test_expect_success 'use ref advertisement to filter out commits' '
>  	# not need to send any ancestors of "c3", but we still need to send "c3"
>  	# itself.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch origin to_fetch &&
> +	trace_fetch client origin to_fetch &&
>  	have_sent c5 c4^ c2side &&
>  	have_not_sent c4 c4^^ c4^^^
>  '
> @@ -121,7 +134,7 @@ test_expect_success 'handle clock skew' '
>  	# and sent, because (due to clock skew) its only parent has already been
>  	# popped off the priority queue.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c2 c1 old4 old2 old1 &&
>  	have_not_sent old3
>  '
> @@ -153,7 +166,7 @@ test_expect_success 'do not send "have" with ancestors of commits that server AC
>  	test_commit -C server commit-on-b1 &&
>  
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" to_fetch &&
> +	trace_fetch client "$(pwd)/server" to_fetch &&
>  	grep "  fetch" trace &&
>  
>  	# fetch-pack sends 2 requests each containing 16 "have" lines before
Junio C Hamano· Aug 10, 2018, 15:58 UTC · re: Jeff King · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

Jeff King <peff@peff.net> writes:
Show 7 quoted lines
> Here it is as a patch on top of jt/fetch-negotiator-skipping, which lets
> us pursue any fix for interleaved trace output on Windows without the
> pressure of an impending flaky test.
>
> My gut says that looking into making O_APPEND work there is going to be
> the nicest solution, but my gut is not very well versed in Windows
> subtleties. ;)

As we know these tests are only interested in "fetch" lines and not record of communication in the other direction, I think this is a nice clean-up that is worth doing.

For only two grep's it may not look worth doing, but it would be also a good clean-up to give an got_acked helper that sits next to have_sent and have_not_sent helpers for readability. That is of course outside the scope of this change.

Will queue.  Thanks.
Show 107 quoted lines
> -- >8 --
> Subject: [PATCH] t5552: suppress upload-pack trace output
>
> The t5552 test script uses GIT_TRACE_PACKET to monitor what
> git-fetch sends and receives. However, because we're
> accessing a local repository, the child upload-pack also
> sends trace output to the same file.
>
> On Linux, this works out OK. We open the trace file with
> O_APPEND, so all writes are atomically positioned at the end
> of the file. No data can be overwritten or omitted. And
> since we prepare our small writes in a strbuf and write them
> with a single write(), we should see each line as an atomic
> unit. The order of lines between the two processes is
> undefined, but the test script greps only for "fetch>" or
> "fetch<" lines. So under Linux, the test results are
> deterministic.
>
> The test fails intermittently on Windows, however,
> reportedly even overwriting bits of the output file (i.e.,
> O_APPEND does not seem to give us an atomic position+write).
>
> Since the test only cares about the trace output from fetch,
> we can just disable the output from upload-pack. That
> doesn't solve the greater question of O_APPEND/trace issues
> under Windows, but it easily fixes the flakiness from this
> test.
>
> Reported-by: Johannes Schindelin <johannes.schindelin@gmx.de>
> Signed-off-by: Jeff King <peff@peff.net>
> ---
> I'm assuming that this really isn't triggerable on Linux. I tried and
> couldn't manage to get it to fail, and the reasoning above explains why.
> But I wasn't 100% clear that Dscho hadn't seen it fail on non-Windows.
>
>  t/t5552-skipping-fetch-negotiator.sh | 23 ++++++++++++++++++-----
>  1 file changed, 18 insertions(+), 5 deletions(-)
>
> diff --git a/t/t5552-skipping-fetch-negotiator.sh b/t/t5552-skipping-fetch-negotiator.sh
> index 0a8e0e42ed..0ad50dd839 100755
> --- a/t/t5552-skipping-fetch-negotiator.sh
> +++ b/t/t5552-skipping-fetch-negotiator.sh
> @@ -28,6 +28,19 @@ have_not_sent () {
>  	done
>  }
>  
> +# trace_fetch <client_dir> <server_dir> [args]
> +#
> +# Trace the packet output of fetch, but make sure we disable the variable
> +# in the child upload-pack, so we don't combine the results in the same file.
> +trace_fetch () {
> +	client=$1; shift
> +	server=$1; shift
> +	GIT_TRACE_PACKET="$(pwd)/trace" \
> +	git -C "$client" fetch \
> +	  --upload-pack 'unset GIT_TRACE_PACKET; git-upload-pack' \
> +	  "$server" "$@"
> +}
> +
>  test_expect_success 'commits with no parents are sent regardless of skip distance' '
>  	git init server &&
>  	test_commit -C server to_fetch &&
> @@ -42,7 +55,7 @@ test_expect_success 'commits with no parents are sent regardless of skip distanc
>  	# "c1" has no parent, it is still sent as "have" even though it would
>  	# normally be skipped.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c7 c5 c2 c1 &&
>  	have_not_sent c6 c4 c3
>  '
> @@ -65,7 +78,7 @@ test_expect_success 'when two skips collide, favor the larger one' '
>  	# the next "have" sent will be "c1" (from "c6" skip 4) and not "c4"
>  	# (from "c5side" skip 1).
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c5side c11 c9 c6 c1 &&
>  	have_not_sent c10 c8 c7 c5 c4 c3 c2
>  '
> @@ -91,7 +104,7 @@ test_expect_success 'use ref advertisement to filter out commits' '
>  	# not need to send any ancestors of "c3", but we still need to send "c3"
>  	# itself.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch origin to_fetch &&
> +	trace_fetch client origin to_fetch &&
>  	have_sent c5 c4^ c2side &&
>  	have_not_sent c4 c4^^ c4^^^
>  '
> @@ -121,7 +134,7 @@ test_expect_success 'handle clock skew' '
>  	# and sent, because (due to clock skew) its only parent has already been
>  	# popped off the priority queue.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c2 c1 old4 old2 old1 &&
>  	have_not_sent old3
>  '
> @@ -153,7 +166,7 @@ test_expect_success 'do not send "have" with ancestors of commits that server AC
>  	test_commit -C server commit-on-b1 &&
>  
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" to_fetch &&
> +	trace_fetch client "$(pwd)/server" to_fetch &&
>  	grep "  fetch" trace &&
>  
>  	# fetch-pack sends 2 requests each containing 16 "have" lines before
Johannes Schindelin· Aug 10, 2018, 16:43 UTC · re: Jeff King · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

Hi,
On Fri, 10 Aug 2018, Jeff King wrote:
Show 25 quoted lines
> On Thu, Aug 09, 2018 at 01:49:52PM -0700, Junio C Hamano wrote:
> 
> > Jeff King <peff@peff.net> writes:
> > 
> > > Are you sure that it's not well-defined? We open the path with O_APPEND,
> > > which means every write() will be atomically positioned at the end of
> > > file. So we would never lose or overwrite data.
> > >
> > > We do our own buffering in a strbuf, writing the result out in a single
> > > write() call (modulo the OS returning a short write, but that should not
> > > generally happen when writing short strings to a file). So we should get
> > > individual trace lines as atomic units.
> > >
> > > The order of lines from the two processes is undefined, of course.
> > 
> > Correct.  But I am more worried about the "mixed/overwriting"
> > breakage, if there is one; it means we may need to be prepared for
> > systems that lack O_APPEND that works correctly.  I initially just
> > assumed that it was what Dscho was seeing, but after re-reading his
> > message, I am not sure anymore.
> > 
> > I think the "do not trace the other side" approach you suggest for
> > these tests that only care about one side is more appropriate
> > solution for this particular case.  We then do not have to worry
> > about overwriting or output from both sides mixed randomly.

Just so everybody knows: I never received the above two mails. Something is seriously rotten in GMX. This seems to have started a week or two ago.

Show 7 quoted lines
> Here it is as a patch on top of jt/fetch-negotiator-skipping, which lets
> us pursue any fix for interleaved trace output on Windows without the
> pressure of an impending flaky test.
> 
> My gut says that looking into making O_APPEND work there is going to be
> the nicest solution, but my gut is not very well versed in Windows
> subtleties. ;)

Your patch seems to be a patch in the original sense of the word: it is not a solution.

And let me spell it out very clearly (as I have mentioned to Jonathan a couple times, without any response): t5552 fails regularly, way more than rarely, see for yourself:

https://git-for-windows.visualstudio.com/git/_build/index?definitionId=1&_a=history

And the reason it fails was analyzed by me and described in the commit message (I am sorry that the cover letter was still stale and talked about flock(), which I had decided was not the right approach after fighting with Linux over it).

What you cannot see easily, unless you go the route that I offered Jonathan (open a PR on gitgitgadget/git which will automatically run the test suite on Windows, macOS and Linux, and of course you can do anything in a PR, including narrowing down what tests are run) is that sometimes those lines in the `trace` file were clearly *incomplete*. That is, even if both processes tried to write atomically, one managed to overwrite the other's buffer in flight.

This is a pretty serious thing, even worse than the failing test suite, and I don't think that your patch acknowledges how serious this is.

And please don't give me that "but it works on Linux" response. Seriously. Sheesh.

Even if you have not managed to trigger it, the POSIX standard seems not to define clearly what the behavior is of two competing write() calls, unless you lock the files appropriately, as my patch series does.

So unless you are willing to ignore, to willfully keep this breakage, I would suggest not to introduce the ugliness of an overridden upload-pack for the sole purpose of disabling the tracing on one side, but instead to get this here bug fixed, by helping me with this here patch series.

We don't have to rush this, you know? We have to fix it, though.

Thank you, Dscho

Show 111 quoted lines
> -- >8 --
> Subject: [PATCH] t5552: suppress upload-pack trace output
> 
> The t5552 test script uses GIT_TRACE_PACKET to monitor what
> git-fetch sends and receives. However, because we're
> accessing a local repository, the child upload-pack also
> sends trace output to the same file.
> 
> On Linux, this works out OK. We open the trace file with
> O_APPEND, so all writes are atomically positioned at the end
> of the file. No data can be overwritten or omitted. And
> since we prepare our small writes in a strbuf and write them
> with a single write(), we should see each line as an atomic
> unit. The order of lines between the two processes is
> undefined, but the test script greps only for "fetch>" or
> "fetch<" lines. So under Linux, the test results are
> deterministic.
> 
> The test fails intermittently on Windows, however,
> reportedly even overwriting bits of the output file (i.e.,
> O_APPEND does not seem to give us an atomic position+write).
> 
> Since the test only cares about the trace output from fetch,
> we can just disable the output from upload-pack. That
> doesn't solve the greater question of O_APPEND/trace issues
> under Windows, but it easily fixes the flakiness from this
> test.
> 
> Reported-by: Johannes Schindelin <johannes.schindelin@gmx.de>
> Signed-off-by: Jeff King <peff@peff.net>
> ---
> I'm assuming that this really isn't triggerable on Linux. I tried and
> couldn't manage to get it to fail, and the reasoning above explains why.
> But I wasn't 100% clear that Dscho hadn't seen it fail on non-Windows.
> 
>  t/t5552-skipping-fetch-negotiator.sh | 23 ++++++++++++++++++-----
>  1 file changed, 18 insertions(+), 5 deletions(-)
> 
> diff --git a/t/t5552-skipping-fetch-negotiator.sh b/t/t5552-skipping-fetch-negotiator.sh
> index 0a8e0e42ed..0ad50dd839 100755
> --- a/t/t5552-skipping-fetch-negotiator.sh
> +++ b/t/t5552-skipping-fetch-negotiator.sh
> @@ -28,6 +28,19 @@ have_not_sent () {
>  	done
>  }
>  
> +# trace_fetch <client_dir> <server_dir> [args]
> +#
> +# Trace the packet output of fetch, but make sure we disable the variable
> +# in the child upload-pack, so we don't combine the results in the same file.
> +trace_fetch () {
> +	client=$1; shift
> +	server=$1; shift
> +	GIT_TRACE_PACKET="$(pwd)/trace" \
> +	git -C "$client" fetch \
> +	  --upload-pack 'unset GIT_TRACE_PACKET; git-upload-pack' \
> +	  "$server" "$@"
> +}
> +
>  test_expect_success 'commits with no parents are sent regardless of skip distance' '
>  	git init server &&
>  	test_commit -C server to_fetch &&
> @@ -42,7 +55,7 @@ test_expect_success 'commits with no parents are sent regardless of skip distanc
>  	# "c1" has no parent, it is still sent as "have" even though it would
>  	# normally be skipped.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c7 c5 c2 c1 &&
>  	have_not_sent c6 c4 c3
>  '
> @@ -65,7 +78,7 @@ test_expect_success 'when two skips collide, favor the larger one' '
>  	# the next "have" sent will be "c1" (from "c6" skip 4) and not "c4"
>  	# (from "c5side" skip 1).
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c5side c11 c9 c6 c1 &&
>  	have_not_sent c10 c8 c7 c5 c4 c3 c2
>  '
> @@ -91,7 +104,7 @@ test_expect_success 'use ref advertisement to filter out commits' '
>  	# not need to send any ancestors of "c3", but we still need to send "c3"
>  	# itself.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch origin to_fetch &&
> +	trace_fetch client origin to_fetch &&
>  	have_sent c5 c4^ c2side &&
>  	have_not_sent c4 c4^^ c4^^^
>  '
> @@ -121,7 +134,7 @@ test_expect_success 'handle clock skew' '
>  	# and sent, because (due to clock skew) its only parent has already been
>  	# popped off the priority queue.
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" &&
> +	trace_fetch client "$(pwd)/server" &&
>  	have_sent c2 c1 old4 old2 old1 &&
>  	have_not_sent old3
>  '
> @@ -153,7 +166,7 @@ test_expect_success 'do not send "have" with ancestors of commits that server AC
>  	test_commit -C server commit-on-b1 &&
>  
>  	test_config -C client fetch.negotiationalgorithm skipping &&
> -	GIT_TRACE_PACKET="$(pwd)/trace" git -C client fetch "$(pwd)/server" to_fetch &&
> +	trace_fetch client "$(pwd)/server" to_fetch &&
>  	grep "  fetch" trace &&
>  
>  	# fetch-pack sends 2 requests each containing 16 "have" lines before
> -- 
> 2.18.0.1058.g0926f0b71f
> 
> 
Jeff King· Aug 10, 2018, 17:15 UTC · re: Johannes Schindelin · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

On Fri, Aug 10, 2018 at 06:43:07PM +0200, Johannes Schindelin wrote:
Show 13 quoted lines
> > > Correct.  But I am more worried about the "mixed/overwriting"
> > > breakage, if there is one; it means we may need to be prepared for
> > > systems that lack O_APPEND that works correctly.  I initially just
> > > assumed that it was what Dscho was seeing, but after re-reading his
> > > message, I am not sure anymore.
> > > 
> > > I think the "do not trace the other side" approach you suggest for
> > > these tests that only care about one side is more appropriate
> > > solution for this particular case.  We then do not have to worry
> > > about overwriting or output from both sides mixed randomly.
> 
> Just so everybody knows: I never received the above two mails. Something
> is seriously rotten in GMX. This seems to have started a week or two ago.

I think it may just have been that they went to the gitgitgadget address; I explicitly added you as a cc when I sent the patch with a commit message, which was when I first noticed you weren't cc'd on the earlier bits.

Show 10 quoted lines
> What you cannot see easily, unless you go the route that I offered
> Jonathan (open a PR on gitgitgadget/git which will automatically run the
> test suite on Windows, macOS and Linux, and of course you can do anything
> in a PR, including narrowing down what tests are run) is that sometimes
> those lines in the `trace` file were clearly *incomplete*. That is, even
> if both processes tried to write atomically, one managed to overwrite the
> other's buffer in flight.
> 
> This is a pretty serious thing, even worse than the failing test suite,
> and I don't think that your patch acknowledges how serious this is.

I don't see anything in what you wrote above or in your original cover letter or series that contradicts the notion that O_APPEND is simply not atomic on Windows. Overwriting the same byte ranges in the file is what I would expect on Linux, as well, if the file were opened without O_APPEND.

I have mixed reports from searching online whether an equivalent to O_APPEND exists. Some sources seem to say that FILE_APPEND_DATA is. I couldn't find anything definitive in Microsoft documentation about whether it actually provides atomicity. From my (admittedly limited) digging, that does not seem to be used by the msys2 runtime, so it might be worth exploring.

> And please don't give me that "but it works on Linux" response. Seriously.
> Sheesh.

But it does. And it's designed to. There is literally nothing to fix on Linux.

> Even if you have not managed to trigger it, the POSIX standard seems not
> to define clearly what the behavior is of two competing write() calls,
> unless you lock the files appropriately, as my patch series does.
POSIX says:
  If the O_APPEND flag of the file status flags is set, the file offset
  shall be set to the end of the file prior to each write and no
  intervening file modification operation shall occur between changing
  the file offset and the write operation.
and:
  This volume of POSIX.1-2017 does not specify the behavior of
  concurrent writes to a regular file from multiple threads, except that
  each write is atomic.

I admit the writing is a little turgid, but I think between the two it is promising the behavior that we expect (and I think that interpretation is pretty common in the Unix world).

> So unless you are willing to ignore, to willfully keep this breakage, I
> would suggest not to introduce the ugliness of an overridden upload-pack
> for the sole purpose of disabling the tracing on one side, but instead to
> get this here bug fixed, by helping me with this here patch series.

I'm OK if you want to live with the broken test in the interim. But after your complaining about the imminence of it "infecting" master, I thought you might be happy to see a solution that was more immediate.

I have tried to help with the actual problem, by identifying the root cause (that the trace code's strategy is not fundamentally broken, but that it relies on O_APPEND whose guarantees are obviously not portable to Windows) and exploring possible solutions there (FILE_APPEND_DATA).

Lacking any kind of Windows development environment, I'd just as soon stop there and let more knowledgeable people take over. But please don't characterize my presence in this thread as some kind of willful harm or ignoring of the problem.

-Peff
Junio C Hamano· Aug 10, 2018, 18:40 UTC · re: Jeff King · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

Jeff King <peff@peff.net> writes:
Show 9 quoted lines
> I have tried to help with the actual problem, by identifying the root
> cause (that the trace code's strategy is not fundamentally broken, but
> that it relies on O_APPEND whose guarantees are obviously not portable
> to Windows) and exploring possible solutions there (FILE_APPEND_DATA).
>
> Lacking any kind of Windows development environment, I'd just as soon
> stop there and let more knowledgeable people take over. But please don't
> characterize my presence in this thread as some kind of willful harm or
> ignoring of the problem.
Thanks.

It seems like the other Johannes and the other Jeff are also interested, so we may hopefully see a properly fixed O_APPEND, which would be the real solution that would help appenders that are *not* tracing subsystem, too.

Johannes Schindelin· Aug 10, 2018, 19:34 UTC · re: Jeff King · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

Hi Peff,
On Fri, 10 Aug 2018, Jeff King wrote:
Show 9 quoted lines
> On Fri, Aug 10, 2018 at 06:43:07PM +0200, Johannes Schindelin wrote:
> 
> > So unless you are willing to ignore, to willfully keep this breakage,
> > I would suggest not to introduce the ugliness of an overridden
> > upload-pack for the sole purpose of disabling the tracing on one side,
> > but instead to get this here bug fixed, by helping me with this here
> > patch series.
> 
> I'm OK if you want to live with the broken test in the interim.

I realize that I failed to tell you that I basically spent 2.5 days worth of worktime to figure this out and come up with three iterations of the patch series (you only saw the latest).

I want this patch series in git.git, maybe not in the current form, but in one form or another. I don't want to spend any more minute on trying to figure out the same problem with any other regression test (which might not even be as easily worked around as with a semi-simple --upload-pack option).

Thank you for wanting to help. Please accept my apologies for expressing in a poor way that I appreciate your eagerness to provide a patch, but that I think nevertheless that it would be better to work on the GIT_TRACE concurrency problem and its resolution via file locks. It would solve that class of problems, instead of that single regression test being flakey.

Sorry, Dscho

Johannes Sixt· Aug 10, 2018, 16:15 UTC · re: Johannes Schindelin via GitGitGadget · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

Am 09.08.2018 um 19:35 schrieb Johannes Schindelin via GitGitGadget:
Show 9 quoted lines
> I reported a couple of times that t5552 is not passing reliably. It has now
> reached next, and will no doubt infect master soon.
> 
> Turns out that it is not a Windows-specific issue, even if it occurs a lot
> more often on Windows than elsewhere.
> 
> The culprit is that two processes try simultaneously to write to the same
> file specified via GIT_TRACE_PACKET, and it is not well defined how that
> should work, even on Linux.

Thanks for digging down to the root cause. As has been said, the behavior of O_APPEND is well-defined under POSIX, but last time I looked for equivalent feature on Windows, I did not find any.

Last time was when I worked around the same failure in t5503-tagfollow.sh in my private builds:

https://github.com/j6t/git/commit/9a447a6844b50b43746d9765b3ac809e2793d742
It is basically the same as Peff suggests: log only one side of the fetch.

As this buglet looks like a recurring theme, and a proper fix is preferable over repeated work-arounds. To me it looks like we need some sort of locking on Windows. Unless your friends at Microsoft have an ace in their sleeves that lets us have atomic O_APPEND the POSIX way...

-- Hannes
Jeff Hostetler· Aug 10, 2018, 16:51 UTC · re: Johannes Sixt · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

On 8/10/2018 12:15 PM, Johannes Sixt wrote:
Show 28 quoted lines
> Am 09.08.2018 um 19:35 schrieb Johannes Schindelin via GitGitGadget:
>> I reported a couple of times that t5552 is not passing reliably. It 
>> has now
>> reached next, and will no doubt infect master soon.
>>
>> Turns out that it is not a Windows-specific issue, even if it occurs a 
>> lot
>> more often on Windows than elsewhere.
>>
>> The culprit is that two processes try simultaneously to write to the same
>> file specified via GIT_TRACE_PACKET, and it is not well defined how that
>> should work, even on Linux.
> 
> Thanks for digging down to the root cause. As has been said, the 
> behavior of O_APPEND is well-defined under POSIX, but last time I looked 
> for equivalent feature on Windows, I did not find any.
> 
> Last time was when I worked around the same failure in 
> t5503-tagfollow.sh in my private builds:
> 
> https://github.com/j6t/git/commit/9a447a6844b50b43746d9765b3ac809e2793d742
> 
> It is basically the same as Peff suggests: log only one side of the fetch.
> 
> As this buglet looks like a recurring theme, and a proper fix is 
> preferable over repeated work-arounds. To me it looks like we need some 
> sort of locking on Windows. Unless your friends at Microsoft have an ace 
> in their sleeves that lets us have atomic O_APPEND the POSIX way...

The official Windows CRT for open() does document an O_APPEND, but after looking at the distributed source, I'm not sure I trust it.

I have not looked at the MSYS version of the CRT yet so I cannot comment on it.

I did find that the following code does what we want. Notice the use of FILE_APPEND_DATA in place of the usual GENERIC_READ. (And yes, the docs are very vague here.)

Before we try a locking solution, perhaps we should tweak mingw_open() to use something like this to get a proper HANDLE directly and then use _open_osfhandle() to get a "fd" for it.

Jeff
---------------------------------------------------------------------
#include <Windows.h>
int main()
{
	HANDLE h = CreateFileW(L"foo.txt",
		FILE_APPEND_DATA,
		FILE_SHARE_READ | FILE_SHARE_WRITE | FILE_SHARE_DELETE,
		NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL);
	const char * buf = "this is a test\n";
	DWORD len = strlen(buf);
	DWORD nbw;
	WriteFile(h, buf, len, &nbw, NULL);
	CloseHandle(h);
	return 0;
}
Jeff Hostetler· Aug 10, 2018, 16:57 UTC · re: Jeff Hostetler · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

On 8/10/2018 12:51 PM, Jeff Hostetler wrote:
Show 45 quoted lines
> 
> 
> On 8/10/2018 12:15 PM, Johannes Sixt wrote:
>> Am 09.08.2018 um 19:35 schrieb Johannes Schindelin via GitGitGadget:
>>> I reported a couple of times that t5552 is not passing reliably. It 
>>> has now
>>> reached next, and will no doubt infect master soon.
>>>
>>> Turns out that it is not a Windows-specific issue, even if it occurs 
>>> a lot
>>> more often on Windows than elsewhere.
>>>
>>> The culprit is that two processes try simultaneously to write to the 
>>> same
>>> file specified via GIT_TRACE_PACKET, and it is not well defined how that
>>> should work, even on Linux.
>>
>> Thanks for digging down to the root cause. As has been said, the 
>> behavior of O_APPEND is well-defined under POSIX, but last time I 
>> looked for equivalent feature on Windows, I did not find any.
>>
>> Last time was when I worked around the same failure in 
>> t5503-tagfollow.sh in my private builds:
>>
>> https://github.com/j6t/git/commit/9a447a6844b50b43746d9765b3ac809e2793d742 
>>
>>
>> It is basically the same as Peff suggests: log only one side of the 
>> fetch.
>>
>> As this buglet looks like a recurring theme, and a proper fix is 
>> preferable over repeated work-arounds. To me it looks like we need 
>> some sort of locking on Windows. Unless your friends at Microsoft have 
>> an ace in their sleeves that lets us have atomic O_APPEND the POSIX 
>> way...
> 
> The official Windows CRT for open() does document an O_APPEND, but after
> looking at the distributed source, I'm not sure I trust it.
> 
> I have not looked at the MSYS version of the CRT yet so I cannot comment
> on it.
> 
> I did find that the following code does what we want.  Notice the use of
> FILE_APPEND_DATA in place of the usual GENERIC_READ.  (And yes, the docs
> are very vague here.)
d'oh
s/GENERIC_READ/GENERIC_WRITE/
Show 27 quoted lines
> 
> Before we try a locking solution, perhaps we should tweak mingw_open()
> to use something like this to get a proper HANDLE directly and then use
> _open_osfhandle() to get a "fd" for it.
> 
> Jeff
> 
> ---------------------------------------------------------------------
> 
> #include <Windows.h>
> 
> int main()
> {
>      HANDLE h = CreateFileW(L"foo.txt",
>          FILE_APPEND_DATA,
>          FILE_SHARE_READ | FILE_SHARE_WRITE | FILE_SHARE_DELETE,
>          NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL);
> 
>      const char * buf = "this is a test\n";
>      DWORD len = strlen(buf);
>      DWORD nbw;
> 
>      WriteFile(h, buf, len, &nbw, NULL);
>      CloseHandle(h);
> 
>      return 0;
> }
Johannes Sixt· Aug 10, 2018, 17:08 UTC · re: Jeff Hostetler · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

Am 10.08.2018 um 18:51 schrieb Jeff Hostetler:
Show 38 quoted lines
> 
> 
> On 8/10/2018 12:15 PM, Johannes Sixt wrote:
>> Am 09.08.2018 um 19:35 schrieb Johannes Schindelin via GitGitGadget:
>>> I reported a couple of times that t5552 is not passing reliably. It 
>>> has now
>>> reached next, and will no doubt infect master soon.
>>>
>>> Turns out that it is not a Windows-specific issue, even if it occurs 
>>> a lot
>>> more often on Windows than elsewhere.
>>>
>>> The culprit is that two processes try simultaneously to write to the 
>>> same
>>> file specified via GIT_TRACE_PACKET, and it is not well defined how that
>>> should work, even on Linux.
>>
>> Thanks for digging down to the root cause. As has been said, the 
>> behavior of O_APPEND is well-defined under POSIX, but last time I 
>> looked for equivalent feature on Windows, I did not find any.
>>
>> Last time was when I worked around the same failure in 
>> t5503-tagfollow.sh in my private builds:
>>
>> https://github.com/j6t/git/commit/9a447a6844b50b43746d9765b3ac809e2793d742 
>>
>>
>> It is basically the same as Peff suggests: log only one side of the 
>> fetch.
>>
>> As this buglet looks like a recurring theme, and a proper fix is 
>> preferable over repeated work-arounds. To me it looks like we need 
>> some sort of locking on Windows. Unless your friends at Microsoft have 
>> an ace in their sleeves that lets us have atomic O_APPEND the POSIX 
>> way...
> 
> The official Windows CRT for open() does document an O_APPEND, but after
> looking at the distributed source, I'm not sure I trust it.
I looked at the CRT code, too, and no, we can't trust it.
Show 6 quoted lines
> I have not looked at the MSYS version of the CRT yet so I cannot comment
> on it.
> 
> I did find that the following code does what we want.  Notice the use of
> FILE_APPEND_DATA in place of the usual GENERIC_READ.  (And yes, the docs
> are very vague here.)

As far as I understand, FILE_APPEND_DATA is just a permission flag (I'm not sure why that would be necessary), but at least the documentation states that it is still necessary for the caller to set the file pointer.

But I haven't tried your code below, yet. Should it append the line of text on each invocation? And if so, is it an atomic operation?

Show 27 quoted lines
> Before we try a locking solution, perhaps we should tweak mingw_open()
> to use something like this to get a proper HANDLE directly and then use
> _open_osfhandle() to get a "fd" for it.
> 
> Jeff
> 
> ---------------------------------------------------------------------
> 
> #include <Windows.h>
> 
> int main()
> {
>      HANDLE h = CreateFileW(L"foo.txt",
>          FILE_APPEND_DATA,
>          FILE_SHARE_READ | FILE_SHARE_WRITE | FILE_SHARE_DELETE,
>          NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL);
> 
>      const char * buf = "this is a test\n";
>      DWORD len = strlen(buf);
>      DWORD nbw;
> 
>      WriteFile(h, buf, len, &nbw, NULL);
>      CloseHandle(h);
> 
>      return 0;
> }
> 
Junio C Hamano· Aug 10, 2018, 18:34 UTC · re: Johannes Sixt · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

Johannes Sixt <j6t@kdbg.org> writes:
Show 5 quoted lines
> As this buglet looks like a recurring theme, and a proper fix is
> preferable over repeated work-arounds. To me it looks like we need
> some sort of locking on Windows. Unless your friends at Microsoft have
> an ace in their sleeves that lets us have atomic O_APPEND the POSIX
> way...

Just to put the severity of the issue in context, we use O_APPEND in a few codepaths, and the trace thing for debugging is the only thing that could have multiple writers. Other users of O_APPEND are:

 * refs/files-backend.c uses it so that a reflog entry can be
   appended at the end, but because update to each ref is protected
   from racing at a lot higher layer with a lock, no two people
   would try to append to the same reflog file, so atomicity of
   O_APPEND does not matter here.
 * sequencer.c wants to use it when moving one insn from the todo
   list to the 'done' list when it finishes one operation.  If you
   are running two sequences in a single repository, intermixed
   'done' list would be the least of your problem, so presumably we
   are fine here.

It may make sense to allow GIT_TRACE to have a placeholder (e.g. "/tmp/traceout.$$") to help debuggers arrange to give different processes their own trace output file, which perhaps may be a simpler and less impactful to the performance solution than having to make locks at an application layer.

Jeff King· Aug 10, 2018, 18:56 UTC · re: Junio C Hamano · lore

Re: [PATCH 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

On Fri, Aug 10, 2018 at 11:34:59AM -0700, Junio C Hamano wrote:
Show 17 quoted lines
> Johannes Sixt <j6t@kdbg.org> writes:
> 
> > As this buglet looks like a recurring theme, and a proper fix is
> > preferable over repeated work-arounds. To me it looks like we need
> > some sort of locking on Windows. Unless your friends at Microsoft have
> > an ace in their sleeves that lets us have atomic O_APPEND the POSIX
> > way...
> 
> Just to put the severity of the issue in context, we use O_APPEND in
> a few codepaths, and the trace thing for debugging is the only thing
> that could have multiple writers.  Other users of O_APPEND are:
> 
>  * refs/files-backend.c uses it so that a reflog entry can be
>    appended at the end, but because update to each ref is protected
>    from racing at a lot higher layer with a lock, no two people
>    would try to append to the same reflog file, so atomicity of
>    O_APPEND does not matter here.

Just an interesting side note, but I think one of the reasons we use dot-locks and not flock() is that the former generally works on network filesystems. I think O_APPEND also is not reliable for non-local files, though, so short of actually dot-locking trace files (yuck) I don't think there's a great solution there.

Show 5 quoted lines
> It may make sense to allow GIT_TRACE to have a placeholder
> (e.g. "/tmp/traceout.$$") to help debuggers arrange to give
> different processes their own trace output file, which perhaps may
> be a simpler and less impactful to the performance solution than
> having to make locks at an application layer.

Heh, I actually wrote that patch several years ago, as part of an abandoned effort to have config-triggered tracing (e.g., on the server side where you're getting hundreds of requests and you want to enable tracing on a repo for a slice of time).

One annoying thing for a case like the test in question is that you don't actually know the pid of the process you're interested in. So we'd generate two trace files, and then you'd have to figure out which one is which. In my earlier work, I coupled it with some magic to allow per-command config, like:

  [trace "fetch"]
  packet = /tmp/trace.%p
but you could also imagine a "%n" which uses the command name.

I don't remember why I abandoned it, but I think a lot had to do with violating the "don't look at config" rules for our repo startup code. A lot of that has been fixed since then, but I haven't really needed it. If anybody is really interested, the patches are at:

  https://github.com/peff/git jk/trace-stdin

(my ultimate goal was to record stdin for pack-objects to replay slow fetches, but I ended up hacking together a patch to pack-objects instead).

-Peff
Johannes Sixt· Aug 13, 2018, 19:02 UTC · re: Junio C Hamano · lore

[PATCH] mingw: enable atomic O_APPEND

The Windows CRT implements O_APPEND "manually": on write() calls, the file pointer is set to EOF before the data is written. Clearly, this is not atomic. And in fact, this is the root cause of failures observed in t5552-skipping-fetch-negotiator.sh and t5503-tagfollow.sh, where different processes write to the same trace file simultanously; it also occurred in t5400-send-pack.sh, but there it was worked around in 71406ed4d6 ("t5400: avoid concurrent writes into a trace file", 2017-05-18).

Fortunately, Windows does support atomic O_APPEND semantics using the file access mode FILE_APPEND_DATA. Provide an implementation that does.

This implementation is minimal in such a way that it only implements the open modes that are actually used in the Git code base. Emulation for other modes can be added as necessary later. To become aware of the necessity early, the unusal error ENOSYS is reported if an unsupported mode is encountered.

Diagnosed-by: Johannes Schindelin <Johannes.Schindelin@gmx.de>
Helped-by: Jeff Hostetler <git@jeffhostetler.com>
Signed-off-by: Johannes Sixt <j6t@kdbg.org>
---
 compat/mingw.c | 41 +++++++++++++++++++++++++++++++++++++++--
 1 file changed, 39 insertions(+), 2 deletions(-)
Show changes to compat/mingw.c +39 −2
diff --git a/compat/mingw.c b/compat/mingw.c
index 6ded1c859f..858ca14a57 100644
--- a/compat/mingw.c
+++ b/compat/mingw.c
@@ -341,12 +341,44 @@ int mingw_mkdir(const char *path, int mode)
 	return ret;
 }
 
+static int mingw_open_append(wchar_t const *wfilename, int oflags, ...)
+{
+	HANDLE handle;
+	int fd;
+	DWORD create = (oflags & O_CREAT) ? OPEN_ALWAYS : OPEN_EXISTING;
+
+	/* only these flags are supported */
+	if ((oflags & ~O_CREAT) != (O_WRONLY | O_APPEND))
+		return errno = ENOSYS, -1;
+
+	/*
+	 * FILE_SHARE_WRITE is required to permit child processes
+	 * to append to the file.
+	 */
+	handle = CreateFileW(wfilename, FILE_APPEND_DATA,
+			FILE_SHARE_WRITE | FILE_SHARE_READ,
+			NULL, create, FILE_ATTRIBUTE_NORMAL, NULL);
+	if (handle == INVALID_HANDLE_VALUE)
+		return errno = err_win_to_posix(GetLastError()), -1;
+	/*
+	 * No O_APPEND here, because the CRT uses it only to reset the
+	 * file pointer to EOF on write(); but that is not necessary
+	 * for a file created with FILE_APPEND_DATA.
+	 */
+	fd = _open_osfhandle((intptr_t)handle, O_BINARY);
+	if (fd < 0)
+		CloseHandle(handle);
+	return fd;
+}
+
 int mingw_open (const char *filename, int oflags, ...)
 {
+	typedef int (*open_fn_t)(wchar_t const *wfilename, int oflags, ...);
 	va_list args;
 	unsigned mode;
 	int fd;
 	wchar_t wfilename[MAX_PATH];
+	open_fn_t open_fn;
 
 	va_start(args, oflags);
 	mode = va_arg(args, int);
@@ -355,9 +387,14 @@ int mingw_open (const char *filename, int oflags, ...)
 	if (filename && !strcmp(filename, "/dev/null"))
 		filename = "nul";
 
+	if (oflags & O_APPEND)
+		open_fn = mingw_open_append;
+	else
+		open_fn = _wopen;
+
 	if (xutftowcs_path(wfilename, filename) < 0)
 		return -1;
-	fd = _wopen(wfilename, oflags, mode);
+	fd = open_fn(wfilename, oflags, mode);
 
 	if (fd < 0 && (oflags & O_ACCMODE) != O_RDONLY && errno == EACCES) {
 		DWORD attrs = GetFileAttributesW(wfilename);
@@ -375,7 +412,7 @@ int mingw_open (const char *filename, int oflags, ...)
 		 * CREATE_ALWAYS flag of CreateFile()).
 		 */
 		if (fd < 0 && errno == EACCES)
-			fd = _wopen(wfilename, oflags & ~O_CREAT, mode);
+			fd = open_fn(wfilename, oflags & ~O_CREAT, mode);
 		if (fd >= 0 && set_hidden_flag(wfilename, 1))
 			warning("could not mark '%s' as hidden.", filename);
 	}
-- 
2.18.0.rc0.112.g5f42c6ebd3
Junio C Hamano· Aug 13, 2018, 20:20 UTC · re: Johannes Sixt · lore

Re: [PATCH] mingw: enable atomic O_APPEND

Johannes Sixt <j6t@kdbg.org> writes:
Show 24 quoted lines
> The Windows CRT implements O_APPEND "manually": on write() calls, the
> file pointer is set to EOF before the data is written. Clearly, this is
> not atomic. And in fact, this is the root cause of failures observed in
> t5552-skipping-fetch-negotiator.sh and t5503-tagfollow.sh, where
> different processes write to the same trace file simultanously; it also
> occurred in t5400-send-pack.sh, but there it was worked around in
> 71406ed4d6 ("t5400: avoid concurrent writes into a trace file",
> 2017-05-18).
>
> Fortunately, Windows does support atomic O_APPEND semantics using the
> file access mode FILE_APPEND_DATA. Provide an implementation that does.
>
> This implementation is minimal in such a way that it only implements
> the open modes that are actually used in the Git code base. Emulation
> for other modes can be added as necessary later. To become aware of
> the necessity early, the unusal error ENOSYS is reported if an
> unsupported mode is encountered.
>
> Diagnosed-by: Johannes Schindelin <Johannes.Schindelin@gmx.de>
> Helped-by: Jeff Hostetler <git@jeffhostetler.com>
> Signed-off-by: Johannes Sixt <j6t@kdbg.org>
> ---
>  compat/mingw.c | 41 +++++++++++++++++++++++++++++++++++++++--
>  1 file changed, 39 insertions(+), 2 deletions(-)
Nice.

I wonder how much more expensive using this implementation is compared with the original "race susceptible" open(), when raciness is known not to be an issue (e.g. there is higher level lock that protects the appending).

If it turns out to be quite more costly, I do not think we'd mind introducing a thin wrapper

#ifndef race_safe_append_open #ifndef race_safe_append_open(fn) open(fn, O_WRONLY|O_APPEND|O_CREAT, 0666) #endif

in git-compat-util.h after it includes "compat/mingw.h" and replace the call to open(... O_APPEND ...) in trace.c::get_trace_fd() with a call to that wrapper. That way, other codepaths that use O_APPEND (namely, reflog and todo-list writers) can avoid the additional cost, if any.

Some may find it beneficial from code readability POV because that approach marks the codepath that needs to have non-racy fd more explicitly.

I am assuming that in this case other users of O_APPEND are not performance critical, so hopefully the following is only theoretical and not necessary.

 git-compat-util.h | 5 +++++
 trace.c           | 2 +-
 2 files changed, 6 insertions(+), 1 deletion(-)
Show changes to 2 files +6 −1

git-compat-util.h, trace.c

diff --git a/git-compat-util.h b/git-compat-util.h
index 9a64998b24..a981c50800 100644
--- a/git-compat-util.h
+++ b/git-compat-util.h
@@ -218,6 +218,11 @@
 #else
 #include <stdint.h>
 #endif
+
+#ifndef race_safe_append_open
+#define race_safe_append_open(fn) open(fn, O_WRONLY|O_APPEND|O_CREAT, 0666)
+#endif
+
 #ifdef NO_INTPTR_T
 /*
  * On I16LP32, ILP32 and LP64 "long" is the save bet, however
diff --git a/trace.c b/trace.c
index fc623e91fd..bef9cee1da 100644
--- a/trace.c
+++ b/trace.c
@@ -47,7 +47,7 @@ static int get_trace_fd(struct trace_key *key)
 	else if (strlen(trace) == 1 && isdigit(*trace))
 		key->fd = atoi(trace);
 	else if (is_absolute_path(trace)) {
-		int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666);
+		int fd = race_safe_append_open(trace);
 		if (fd == -1) {
 			warning("could not open '%s' for tracing: %s",
 				trace, strerror(errno));
Johannes Sixt· Aug 13, 2018, 21:05 UTC · re: Junio C Hamano · lore

Re: [PATCH] mingw: enable atomic O_APPEND

Am 13.08.2018 um 22:20 schrieb Junio C Hamano:
Show 33 quoted lines
> Johannes Sixt <j6t@kdbg.org> writes:
> 
>> The Windows CRT implements O_APPEND "manually": on write() calls, the
>> file pointer is set to EOF before the data is written. Clearly, this is
>> not atomic. And in fact, this is the root cause of failures observed in
>> t5552-skipping-fetch-negotiator.sh and t5503-tagfollow.sh, where
>> different processes write to the same trace file simultanously; it also
>> occurred in t5400-send-pack.sh, but there it was worked around in
>> 71406ed4d6 ("t5400: avoid concurrent writes into a trace file",
>> 2017-05-18).
>>
>> Fortunately, Windows does support atomic O_APPEND semantics using the
>> file access mode FILE_APPEND_DATA. Provide an implementation that does.
>>
>> This implementation is minimal in such a way that it only implements
>> the open modes that are actually used in the Git code base. Emulation
>> for other modes can be added as necessary later. To become aware of
>> the necessity early, the unusal error ENOSYS is reported if an
>> unsupported mode is encountered.
>>
>> Diagnosed-by: Johannes Schindelin <Johannes.Schindelin@gmx.de>
>> Helped-by: Jeff Hostetler <git@jeffhostetler.com>
>> Signed-off-by: Johannes Sixt <j6t@kdbg.org>
>> ---
>>   compat/mingw.c | 41 +++++++++++++++++++++++++++++++++++++++--
>>   1 file changed, 39 insertions(+), 2 deletions(-)
> 
> Nice.
> 
> I wonder how much more expensive using this implementation is
> compared with the original "race susceptible" open(), when raciness
> is known not to be an issue (e.g. there is higher level lock that
> protects the appending).

Certainly, the former way that uses two syscalls (SetFilePointer+WriteFile) is more costly than this new way with just one syscall (WriteFile). Of course, I don't know how atomic append would be implemented in the kernel, but I can't think of a reason why it should be slow on Windows, but fast on POSIX.

(But I can't provide numbers to back up my gut feeling...)

(And I also assume that you are not worried about the performance of open() itself.)

Show 9 quoted lines
> ...[define race_safe_append_open]... and replace
> the call to open(... O_APPEND ...) in trace.c::get_trace_fd() with a
> call to that wrapper.  That way, other codepaths that use O_APPEND
> (namely, reflog and todo-list writers) can avoid the additional
> cost, if any.
> 
> Some may find it beneficial from code readability POV because that
> approach marks the codepath that needs to have non-racy fd more
> explicitly.

O_APPEND is POSIX and means race-free append. If you mark some call sites with O_APPEND, then that must be the ones that need race-free append. Hence, you would have to go the other route: Mark those call sites that do _not_ need race-free append with some custom function/macro. (Or mark both with different helpers and avoid writing down O_APPEND.)

-- Hannes
Ævar Arnfjörð Bjarmason· Aug 13, 2018, 21:22 UTC · re: Johannes Sixt · lore

Re: [PATCH] mingw: enable atomic O_APPEND

On Mon, Aug 13 2018, Johannes Sixt wrote:
Show 62 quoted lines
> Am 13.08.2018 um 22:20 schrieb Junio C Hamano:
>> Johannes Sixt <j6t@kdbg.org> writes:
>>
>>> The Windows CRT implements O_APPEND "manually": on write() calls, the
>>> file pointer is set to EOF before the data is written. Clearly, this is
>>> not atomic. And in fact, this is the root cause of failures observed in
>>> t5552-skipping-fetch-negotiator.sh and t5503-tagfollow.sh, where
>>> different processes write to the same trace file simultanously; it also
>>> occurred in t5400-send-pack.sh, but there it was worked around in
>>> 71406ed4d6 ("t5400: avoid concurrent writes into a trace file",
>>> 2017-05-18).
>>>
>>> Fortunately, Windows does support atomic O_APPEND semantics using the
>>> file access mode FILE_APPEND_DATA. Provide an implementation that does.
>>>
>>> This implementation is minimal in such a way that it only implements
>>> the open modes that are actually used in the Git code base. Emulation
>>> for other modes can be added as necessary later. To become aware of
>>> the necessity early, the unusal error ENOSYS is reported if an
>>> unsupported mode is encountered.
>>>
>>> Diagnosed-by: Johannes Schindelin <Johannes.Schindelin@gmx.de>
>>> Helped-by: Jeff Hostetler <git@jeffhostetler.com>
>>> Signed-off-by: Johannes Sixt <j6t@kdbg.org>
>>> ---
>>>   compat/mingw.c | 41 +++++++++++++++++++++++++++++++++++++++--
>>>   1 file changed, 39 insertions(+), 2 deletions(-)
>>
>> Nice.
>>
>> I wonder how much more expensive using this implementation is
>> compared with the original "race susceptible" open(), when raciness
>> is known not to be an issue (e.g. there is higher level lock that
>> protects the appending).
>
> Certainly, the former way that uses two syscalls
> (SetFilePointer+WriteFile) is more costly than this new way with just
> one syscall (WriteFile). Of course, I don't know how atomic append
> would be implemented in the kernel, but I can't think of a reason why
> it should be slow on Windows, but fast on POSIX.
>
> (But I can't provide numbers to back up my gut feeling...)
>
> (And I also assume that you are not worried about the performance of
> open() itself.)
>
>> ...[define race_safe_append_open]... and replace
>> the call to open(... O_APPEND ...) in trace.c::get_trace_fd() with a
>> call to that wrapper.  That way, other codepaths that use O_APPEND
>> (namely, reflog and todo-list writers) can avoid the additional
>> cost, if any.
>>
>> Some may find it beneficial from code readability POV because that
>> approach marks the codepath that needs to have non-racy fd more
>> explicitly.
>
> O_APPEND is POSIX and means race-free append. If you mark some call
> sites with O_APPEND, then that must be the ones that need race-free
> append. Hence, you would have to go the other route: Mark those call
> sites that do _not_ need race-free append with some custom
> function/macro. (Or mark both with different helpers and avoid writing
> down O_APPEND.)

O_APPEND in POSIX is race-free only up to PIPE_MAX bytes written at a time, which is e.g. 2^12 by default on linux, after that all bets are off and the kernel is free to interleave different write calls.

I've written code (not for git.git) that implements such a "write_non_racy" function in the past, and the first thing it needs to do is to assert that the length of the buffer being written doesn't exceed PIPE_MAX.

So there's still a use for a race_safe_append_open() wrapper function, to O_APPEND and do the PIPE_MAX assertion. Otherwise you're calling a "safe" function which isn't safe at all anymore.

I have no idea what the equivalent of that PIPE_MAX caveat is on non-POSIX (e.g. Windows), but would be interested to find out.

Junio C Hamano· Aug 13, 2018, 21:55 UTC · re: Ævar Arnfjörð Bjarmason · lore

Re: [PATCH] mingw: enable atomic O_APPEND

Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes:
> O_APPEND in POSIX is race-free only up to PIPE_MAX bytes written at a
> time, which is e.g. 2^12 by default on linux, after that all bets are
> off and the kernel is free to interleave different write calls.

We are only interested in the use of race-safe append in the tracing, so we should be OK in practice. but then ...

> So there's still a use for a race_safe_append_open() wrapper function,
> to O_APPEND and do the PIPE_MAX assertion. Otherwise you're calling a
> "safe" function which isn't safe at all anymore.

... having an assert that would never trigger is not all that bad ;-)

Jeff King· Aug 13, 2018, 22:37 UTC · re: Ævar Arnfjörð Bjarmason · lore

Re: [PATCH] mingw: enable atomic O_APPEND

On Mon, Aug 13, 2018 at 11:22:10PM +0200, Ævar Arnfjörð Bjarmason wrote:
Show 10 quoted lines
> > O_APPEND is POSIX and means race-free append. If you mark some call
> > sites with O_APPEND, then that must be the ones that need race-free
> > append. Hence, you would have to go the other route: Mark those call
> > sites that do _not_ need race-free append with some custom
> > function/macro. (Or mark both with different helpers and avoid writing
> > down O_APPEND.)
> 
> O_APPEND in POSIX is race-free only up to PIPE_MAX bytes written at a
> time, which is e.g. 2^12 by default on linux, after that all bets are
> off and the kernel is free to interleave different write calls.

This is a claim I've run across often, but I've never seen a good citation for it.

Certainly atomic writes to _pipes_ are determined by PIPE_BUF (which IIRC is not even a constant on Linux, but can be changed at run-time). But is it relevant for regular-file writes?

Another gem I found while digging on this O_APPEND/FILE_APPEND_DATA stuff the other day: somebody claimed that the max atomic-append size on Linux is 4096 and 1024 on Windows. But their experimental script was done in bash! So I suspect they were really just measuring the size of stdio buffers.

Here's my attempt at a test setup. This C program forces two processes to write simultaneously to the same file with O_APPEND:

-- >8 -- #include <stdlib.h> #include <string.h> #include <stdio.h> #include <sys/types.h> #include <fcntl.h> #include <unistd.h>

static void doit(int size, const char *fn, char c)
{
	int fd;
	char *buf;
	fd = open(fn, O_WRONLY|O_APPEND|O_CREAT, 0666);
	if (fd < 0) {
		perror("open");
		return;
	}
	buf = malloc(size);
	memset(buf, c, size);
	while (1)
		write(fd, buf, size);
}
int main(int argc, const char **argv)
{
	int size = atoi(argv[1]);
	if (fork())
		doit(size, argv[2], '1');
	else
		doit(size, argv[2], '2');
	return 0;
}
-- 8< --

and then this program checks that we saw atomic units of the correct size:

-- >8 -- #include <stdlib.h> #include <stdio.h> #include <unistd.h>

int main(int argc, const char **argv)
{
	int size = atoi(argv[1]);
	char *buf;
	buf = malloc(size);
	while (1) {
		int i;
		/* assume atomic reads, i.e., no signals */
		int r = read(0, buf, size);
		if (!r)
			break;
		for (i = 1; i < size; i++) {
			if (buf[i] != buf[0]) {
				fprintf(stderr, "overlap\n");
				return 1;
			}
		}
	}
	return 0;
}
-- 8< --
And then you can do something like:
  for size in 4097 8193 16385 32769 65537 131073 262145 524289 1048577; do
    >out ;# clean up from last run
    echo "Trying $size..."
    timeout 5 ./write $size out
    if ! ./check $size <out; then
      echo "$size failed"
      break
    fi
  done

On my Linux system, each of those seems to write several gigabytes without overlapping. I did manage to hit some failing cases, but they were never sheared writes, but rather cases where there was an incomplete write at the end-of-file.

So obviously this is all a bit of a tangent. I'd be fine declaring that trace output is generally small enough not to worry about this in the first place. But those results show that it shouldn't matter even if we're writing 1MB trace lines on Linux. I wouldn't be at all surprised to see different results on other operating systems, though.

-Peff
Ævar Arnfjörð Bjarmason· Aug 14, 2018, 13:47 UTC · re: Jeff King · lore

Re: [PATCH] mingw: enable atomic O_APPEND

On Mon, Aug 13 2018, Jeff King wrote:
Show 12 quoted lines
> On Mon, Aug 13, 2018 at 11:22:10PM +0200, Ævar Arnfjörð Bjarmason wrote:
>
>> > O_APPEND is POSIX and means race-free append. If you mark some call
>> > sites with O_APPEND, then that must be the ones that need race-free
>> > append. Hence, you would have to go the other route: Mark those call
>> > sites that do _not_ need race-free append with some custom
>> > function/macro. (Or mark both with different helpers and avoid writing
>> > down O_APPEND.)
>>
>> O_APPEND in POSIX is race-free only up to PIPE_MAX bytes written at a
>> time, which is e.g. 2^12 by default on linux, after that all bets are
>> off and the kernel is free to interleave different write calls.
[I should have said PIPE_BUF, not PIPE_MAX]
> This is a claim I've run across often, but I've never seen a good
> citation for it.

To clarify I'm claiming that this is not a guarantee POSIX or linux support. Not that in practice it doesn't work on some systems.

The relevant POSIX docs are here: http://pubs.opengroup.org/onlinepubs/9699919799/functions/write.html

    Write requests of {PIPE_BUF} bytes or less shall not be interleaved
    with data from other processes doing writes on the same pipe. Writes
    of greater than {PIPE_BUF} bytes may have data interleaved, on
    arbitrary boundaries, with writes by other processes, whether or not
    the O_NONBLOCK flag of the file status flags is set.

And the Linux docs at http://man7.org/linux/man-pages/man7/pipe.7.html say something similar:

    Writes of more than PIPE_BUF bytes may be nonatomic: the kernel may
    interleave the data with data written by other processes.  POSIX.1
    requires PIPE_BUF to be at least 512 bytes.  (On Linux, PIPE_BUF is
    4096 bytes.)
> Certainly atomic writes to _pipes_ are determined by PIPE_BUF (which
> IIRC is not even a constant on Linux, but can be changed at run-time).
> But is it relevant for regular-file writes?

I believe it's hardcoded at PIPE_BUF which is defined as PAGE_SIZE on linux. I think you may be thinking of /proc/sys/fs/pipe-max-pages which is the number of pages that a pipe will take before filling up, but I may be wrong.

Show 5 quoted lines
> Another gem I found while digging on this O_APPEND/FILE_APPEND_DATA
> stuff the other day: somebody claimed that the max atomic-append size on
> Linux is 4096 and 1024 on Windows. But their experimental script was
> done in bash! So I suspect they were really just measuring the size of
> stdio buffers.

Yes, and some tests for this are wrong because they use e.g. "print" in some higher-level language which'll always split stuff into writes of 1024 or something.

Show 88 quoted lines
> Here's my attempt at a test setup. This C program forces two processes
> to write simultaneously to the same file with O_APPEND:
>
> -- >8 --
> #include <stdlib.h>
> #include <string.h>
> #include <stdio.h>
> #include <sys/types.h>
> #include <fcntl.h>
> #include <unistd.h>
>
> static void doit(int size, const char *fn, char c)
> {
> 	int fd;
> 	char *buf;
>
> 	fd = open(fn, O_WRONLY|O_APPEND|O_CREAT, 0666);
> 	if (fd < 0) {
> 		perror("open");
> 		return;
> 	}
>
> 	buf = malloc(size);
> 	memset(buf, c, size);
>
> 	while (1)
> 		write(fd, buf, size);
> }
>
> int main(int argc, const char **argv)
> {
> 	int size = atoi(argv[1]);
>
> 	if (fork())
> 		doit(size, argv[2], '1');
> 	else
> 		doit(size, argv[2], '2');
> 	return 0;
> }
> -- 8< --
>
> and then this program checks that we saw atomic units of the correct
> size:
>
> -- >8 --
> #include <stdlib.h>
> #include <stdio.h>
> #include <unistd.h>
>
> int main(int argc, const char **argv)
> {
> 	int size = atoi(argv[1]);
> 	char *buf;
>
> 	buf = malloc(size);
> 	while (1) {
> 		int i;
> 		/* assume atomic reads, i.e., no signals */
> 		int r = read(0, buf, size);
> 		if (!r)
> 			break;
> 		for (i = 1; i < size; i++) {
> 			if (buf[i] != buf[0]) {
> 				fprintf(stderr, "overlap\n");
> 				return 1;
> 			}
> 		}
> 	}
> 	return 0;
> }
> -- 8< --
>
> And then you can do something like:
>
>   for size in 4097 8193 16385 32769 65537 131073 262145 524289 1048577; do
>     >out ;# clean up from last run
>     echo "Trying $size..."
>     timeout 5 ./write $size out
>     if ! ./check $size <out; then
>       echo "$size failed"
>       break
>     fi
>   done
>
> On my Linux system, each of those seems to write several gigabytes
> without overlapping. I did manage to hit some failing cases, but they
> were never sheared writes, but rather cases where there was an
> incomplete write at the end-of-file.

Yeah I can't make that fail experimentally either, except in the case you mentioned. I also checked on a NetBSD & OpenBSD and OpenBSD box I have access to, same thing.

Show 5 quoted lines
> So obviously this is all a bit of a tangent. I'd be fine declaring that
> trace output is generally small enough not to worry about this in the
> first place. But those results show that it shouldn't matter even if
> we're writing 1MB trace lines on Linux. I wouldn't be at all surprised
> to see different results on other operating systems, though.

I don't know how this works internally in the kernel, but I'd be very careful to make that assertion. Most likely this in practice depends on what FS you're using, its mount options, whether fsync() is involved, I/O pressure etc.

FWIW this is something I've ran into in the past on Linux as a practical matter, but that was many kernel versions ago, so maybe the semantics changed.

We had an ad-hoc file format with each chunk a "<start marker><length><content><end marker>\n" format (and the <content> was guaranteed not to contain "\n"). These would be written to the same file by N workers. We would get corrupt data because of this in cases where we were writing more than PIPE_BUF, e.g. start markers for unrelated payloads interleaved with content, lines that were incorrectly formed etc.

But yeah, whether this is a practical concern for git trace output is another matter. I just wanted to chime in to note that atomic appends to files are only portable on POSIX up to PIPE_BUF.

Jeff King· Aug 14, 2018, 14:53 UTC · re: Ævar Arnfjörð Bjarmason · lore

Re: [PATCH] mingw: enable atomic O_APPEND

On Tue, Aug 14, 2018 at 03:47:54PM +0200, Ævar Arnfjörð Bjarmason wrote:
Show 8 quoted lines
> The relevant POSIX docs are here:
> http://pubs.opengroup.org/onlinepubs/9699919799/functions/write.html
> 
>     Write requests of {PIPE_BUF} bytes or less shall not be interleaved
>     with data from other processes doing writes on the same pipe. Writes
>     of greater than {PIPE_BUF} bytes may have data interleaved, on
>     arbitrary boundaries, with writes by other processes, whether or not
>     the O_NONBLOCK flag of the file status flags is set.

Right, this is the part I've seen, but it's pretty clearly only about pipes, not regular files.

Show 8 quoted lines
> > Certainly atomic writes to _pipes_ are determined by PIPE_BUF (which
> > IIRC is not even a constant on Linux, but can be changed at run-time).
> > But is it relevant for regular-file writes?
> 
> I believe it's hardcoded at PIPE_BUF which is defined as PAGE_SIZE on
> linux. I think you may be thinking of /proc/sys/fs/pipe-max-pages which
> is the number of pages that a pipe will take before filling up, but I
> may be wrong.
Yeah, you're probably right.
Show 10 quoted lines
> > So obviously this is all a bit of a tangent. I'd be fine declaring that
> > trace output is generally small enough not to worry about this in the
> > first place. But those results show that it shouldn't matter even if
> > we're writing 1MB trace lines on Linux. I wouldn't be at all surprised
> > to see different results on other operating systems, though.
> 
> I don't know how this works internally in the kernel, but I'd be very
> careful to make that assertion. Most likely this in practice depends on
> what FS you're using, its mount options, whether fsync() is involved,
> I/O pressure etc.

Definitely it depends on the filesystem (and I'm pretty sure that at least old versions of NFS could not possibly do O_APPEND correctly, because the protocol did not support an atomic seek+write).

I agree that the experiment I did doesn't really tell us anything for sure. It _seems_ to work, but the machine was not under any kind of memory or I/O pressure.

I'd feel pretty confident that writes under a page are always going to be fine, but anything else is "seems to work". To me that's enough for tracing, as the absolute worst case is jumbled output, not an on-disk corruption.

Show 11 quoted lines
> FWIW this is something I've ran into in the past on Linux as a practical
> matter, but that was many kernel versions ago, so maybe the semantics
> changed.
> 
> We had an ad-hoc file format with each chunk a "<start
> marker><length><content><end marker>\n" format (and the <content> was
> guaranteed not to contain "\n"). These would be written to the same file
> by N workers. We would get corrupt data because of this in cases where
> we were writing more than PIPE_BUF, e.g. start markers for unrelated
> payloads interleaved with content, lines that were incorrectly formed
> etc.

Interesting. I wonder if it is because of PIPE_BUF, or it is simply the page size, which also happens to be the value of PIPE_BUF.

> But yeah, whether this is a practical concern for git trace output is
> another matter. I just wanted to chime in to note that atomic appends to
> files are only portable on POSIX up to PIPE_BUF.

I still think POSIX doesn't say anything either way here. The PIPE_BUF bits are _just_ about pipes. At any rate, I think we have a decent handle on what systems actually _do_, which is more important than POSIX anyway.

-Peff
Johannes Sixt· Aug 14, 2018, 18:29 UTC · re: Jeff King · lore

Re: [PATCH] mingw: enable atomic O_APPEND

Am 14.08.2018 um 00:37 schrieb Jeff King:
Show 16 quoted lines
> And then you can do something like:
> 
>    for size in 4097 8193 16385 32769 65537 131073 262145 524289 1048577; do
>      >out ;# clean up from last run
>      echo "Trying $size..."
>      timeout 5 ./write $size out
>      if ! ./check $size <out; then
>        echo "$size failed"
>        break
>      fi
>    done
> 
> On my Linux system, each of those seems to write several gigabytes
> without overlapping. I did manage to hit some failing cases, but they
> were never sheared writes, but rather cases where there was an
> incomplete write at the end-of-file.

I used your programs with necessary adjustments (as fork() is not available), and did similar tests with concurrent processes. With packet sizes 1025, 4093, 7531 (just to include some odd number), and 8193 I did not observe any overlapping or short writes.

I'm now very confident that we are on the safe side for our purposes.
-- Hannes
Jeff King· Aug 14, 2018, 19:17 UTC · re: Johannes Sixt · lore

Re: [PATCH] mingw: enable atomic O_APPEND

On Tue, Aug 14, 2018 at 08:29:04PM +0200, Johannes Sixt wrote:
Show 24 quoted lines
> Am 14.08.2018 um 00:37 schrieb Jeff King:
> > And then you can do something like:
> > 
> >    for size in 4097 8193 16385 32769 65537 131073 262145 524289 1048577; do
> >      >out ;# clean up from last run
> >      echo "Trying $size..."
> >      timeout 5 ./write $size out
> >      if ! ./check $size <out; then
> >        echo "$size failed"
> >        break
> >      fi
> >    done
> > 
> > On my Linux system, each of those seems to write several gigabytes
> > without overlapping. I did manage to hit some failing cases, but they
> > were never sheared writes, but rather cases where there was an
> > incomplete write at the end-of-file.
> 
> I used your programs with necessary adjustments (as fork() is not
> available), and did similar tests with concurrent processes. With packet
> sizes 1025, 4093, 7531 (just to include some odd number), and 8193 I did not
> observe any overlapping or short writes.
> 
> I'm now very confident that we are on the safe side for our purposes.
Great, thanks for testing!

Re-reading what I wrote about end-of-file above and thinking about the conversation with Ævar elsewhere in the thread, I suspect it _is_ easy to get overlapping writes if the processes are receiving signals (since clearly the TERM signal caused a partial write).

My experiment doesn't simulate that at all. I suppose the parent process could send SIGUSR1 to the child in each loop, and the child would catch it but keep going.

Hmm, that was easy enough to do (programs below for reference), but surprisingly it didn't fail for me (except for the normal end-of-file truncation). It's like the OS is willing to truncate the write of a dying program but not one for a signal that is getting handled. Which is great for us, since it's exactly what we want, but makes me even more suspicious that a non-Linux kernel might behave completely differently.

I still think we're fine in practice, as I'd expect any kernel to be atomic under the page size. So this was mostly just for my own edification.

-Peff

-- >8 -- /* check.c, with separate short-read reporting */ #include <stdlib.h> #include <stdio.h> #include <unistd.h>

int main(int argc, const char **argv)
{
	int size = atoi(argv[1]);
	int block = 0;
	char *buf;
	buf = malloc(size);
	while (1) {
		int i;
		/* assume atomic reads */
		int r = read(0, buf, size);
		if (!r)
			break;
		if (r < size) {
			fprintf(stderr, "short read\n");
			return 1;
		}
		for (i = 1; i < size; i++) {
			if (buf[i] != buf[0]) {
				fprintf(stderr, "overlap in block %d\n", block);
				return 1;
			}
		}
		block++;
	}
}
-- >8 --
-- >8 --
/* write.c with signals; you can also confirm via strace
   that each write is atomic */
#include <stdlib.h>
#include <string.h>
#include <stdio.h>
#include <sys/types.h>
#include <fcntl.h>
#include <unistd.h>
#include <signal.h>
void handle_signal(int sig)
{
	/* do nothing */
}
static void doit(int size, const char *fn, char c, pid_t pid)
{
	int fd;
	char *buf;
	fd = open(fn, O_WRONLY|O_APPEND|O_CREAT, 0666);
	if (fd < 0) {
		perror("open");
		return;
	}
	buf = malloc(size);
	memset(buf, c, size);
	while (1) {
		if (pid)
			kill(pid, SIGUSR1);
		write(fd, buf, size);
	}
}
int main(int argc, const char **argv)
{
	int size = atoi(argv[1]);
	pid_t pid;
	signal(SIGUSR1, handle_signal);
	pid = fork();
	if (pid)
		doit(size, argv[2], '1', pid);
	else
		doit(size, argv[2], '2', pid);
	return 0;
}
-- >8 --
Jeff Hostetler· Aug 14, 2018, 13:01 UTC · re: Johannes Sixt · lore

Re: [PATCH] mingw: enable atomic O_APPEND

On 8/13/2018 3:02 PM, Johannes Sixt wrote:
Show 25 quoted lines
> The Windows CRT implements O_APPEND "manually": on write() calls, the
> file pointer is set to EOF before the data is written. Clearly, this is
> not atomic. And in fact, this is the root cause of failures observed in
> t5552-skipping-fetch-negotiator.sh and t5503-tagfollow.sh, where
> different processes write to the same trace file simultanously; it also
> occurred in t5400-send-pack.sh, but there it was worked around in
> 71406ed4d6 ("t5400: avoid concurrent writes into a trace file",
> 2017-05-18).
> 
> Fortunately, Windows does support atomic O_APPEND semantics using the
> file access mode FILE_APPEND_DATA. Provide an implementation that does.
> 
> This implementation is minimal in such a way that it only implements
> the open modes that are actually used in the Git code base. Emulation
> for other modes can be added as necessary later. To become aware of
> the necessity early, the unusal error ENOSYS is reported if an
> unsupported mode is encountered.
> 
> Diagnosed-by: Johannes Schindelin <Johannes.Schindelin@gmx.de>
> Helped-by: Jeff Hostetler <git@jeffhostetler.com>
> Signed-off-by: Johannes Sixt <j6t@kdbg.org>
> ---
>   compat/mingw.c | 41 +++++++++++++++++++++++++++++++++++++++--
>   1 file changed, 39 insertions(+), 2 deletions(-)
> 
[...]
This looks good.  Thanks for following up on this.
Jeff
Junio C Hamano· Aug 14, 2018, 14:38 UTC · re: Jeff Hostetler · lore

Re: [PATCH] mingw: enable atomic O_APPEND

Jeff Hostetler <git@jeffhostetler.com> writes:
Show 12 quoted lines
> On 8/13/2018 3:02 PM, Johannes Sixt wrote:
>>
>> Fortunately, Windows does support atomic O_APPEND semantics using the
>> file access mode FILE_APPEND_DATA. Provide an implementation that does.
>> ...
>>
>> Diagnosed-by: Johannes Schindelin <Johannes.Schindelin@gmx.de>
>> Helped-by: Jeff Hostetler <git@jeffhostetler.com>
>> Signed-off-by: Johannes Sixt <j6t@kdbg.org>
>> ---
>
> This looks good.  Thanks for following up on this.
Thanks, all.  Will queue.
Johannes Schindelin via GitGitGadget· Aug 10, 2018, 19:47 UTC · re: Johannes Schindelin via GitGitGadget · lore

[PATCH v2 0/4] t5552: fix flakiness by introducing proper locking for GIT_TRACE

I reported a couple of times that t5552 is not passing reliably. It has now reached next, and will no doubt infect master soon.

Turns out that it is not a Windows-specific issue, even if it occurs a lot more often on Windows than elsewhere. (And even if it is apparently impossible to trigger on Linux.)

The culprit is that two processes try to write simultaneously to the same file specified via GIT_TRACE_PACKET, and it is not well defined how that should work, even when only looking at the POSIX specification (the documentation of write() [http://pubs.opengroup.org/onlinepubs/9699919799/functions/write.html] says "Applications should use some form of concurrency control.").

This patch series addresses that by locking the trace fd. I chose to use fcntl() for the Unix(-y) platforms we support instead of flock() (even if the latter has much simpler semantics) because fcntl() is in POSIX while flock() is not. On Windows, I use the Win32 API function LockFileEx() [https://docs.microsoft.com/en-us/windows/desktop/api/fileapi/nf-fileapi-lockfileex] .

Of course, I have to admit that I am not super solid on the fcntl() semantics. Junio was nice enough to educate me on l_len = 0 meaning the entire file. If anybody has more experience with locking file descriptors referring not to files, but, say, to pipes or to an interactive terminal, I would be very thankful for help (while the POSIX documentation states that the errno should be EINVAL on a file descriptor that cannot be locked, apparently macOS sets errno to EBADF when trying to lock a redirected stdout )?

Changes since v1:
 * Touched up the cover letter and the first commit message (in particular,
   removed the bogus squash! line giving away just how much I rely on the 
   --autosquash feature these days).
 * Now we're locking the entire file via l_len = 0 (except on Windows).
 * To cover all bases, EINVAL is now also treated as "cannot lock this fd"
   (in addition to EBADF).
 * Removed some superfluous flock()-related left-overs from a previous
   attempt (that caused a lot of me fighting with Linux).
Johannes Schindelin (4):
  Introduce a function to lock/unlock file descriptors when appending
  mingw: implement lock_or_unlock_fd_for_appending()
  trace: lock the trace file to avoid racy trace_write() calls
  trace: verify that locking works
 Makefile               |   1 +
 compat/mingw.c         |  19 ++++++
 compat/mingw.h         |   3 +
 git-compat-util.h      |   2 +
 t/helper/test-tool.c   |   1 +
 t/helper/test-tool.h   |   1 +
 t/helper/test-trace.c  | 130 +++++++++++++++++++++++++++++++++++++++++
 t/t0070-fundamental.sh |   6 ++
 trace.c                |  11 +++-
 wrapper.c              |  16 +++++
 10 files changed, 189 insertions(+), 1 deletion(-)
 create mode 100644 t/helper/test-trace.c
base-commit: 42cc7485a2ec49ecc440c921d2eb0cae4da80549
Published-As: https://github.com/gitgitgadget/git/releases/tags/pr-17%2Fdscho%2Ffetch-negotiator-skipping-v2
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-17/dscho/fetch-negotiator-skipping-v2
Pull-Request: https://github.com/gitgitgadget/git/pull/17
Range-diff vs v1:
 1:  e449ed75f ! 1:  a19904682 Introduce a function to lock/unlock file descriptors when appending
     @@ -30,7 +30,7 @@
          added in this commit.
      
          But fcntl() allows a lot more versatile file region locking that we
     -    actually need, to by necessity the fcntl() emulation would be quite
     +    actually need, so by necessity the fcntl() emulation would be quite
          complex: To support the `l_whence = SEEK_CUR` (which we would use, if it
          did not require so much book-keeping due to our writing between locking
          and unlocking the file), we would have to call `SetFilePointerEx()`
     @@ -47,18 +47,16 @@
          to do, as we would once again fail to have an abstraction that clearly
          says what *exact*functionality we want to use.
      
     -    To set a precedent for a better approach, let's introduce a proper
     -    abstraction: a function that says in its name precisely what Git
     -    wants it to do (as opposed to *how* it does it on Linux):
     -    lock_or_unlock_fd_for_appending().
     +    This commit expressly tries to set a precedent for a better approach:
     +    Let's introduce a proper abstraction: a function that says in its name
     +    precisely what Git wants it to do (as opposed to *how* it does it on
     +    Linux): lock_or_unlock_fd_for_appending().
      
          The next commit will provide a Windows-specific implementation of this
          function/functionality.
      
          Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
      
     -    squash! Introduce a function to lock/unlock file descriptors when appending
     -
      diff --git a/git-compat-util.h b/git-compat-util.h
      --- a/git-compat-util.h
      +++ b/git-compat-util.h
     @@ -86,9 +84,11 @@
      +	struct flock flock;
      +
      +	flock.l_type = lock_it ? F_WRLCK : F_UNLCK;
     ++
     ++	/* (un-)lock the whole file */
      +	flock.l_whence = SEEK_SET;
      +	flock.l_start = 0;
     -+	flock.l_len = 0xffffffff; /* arbitrary number of bytes */
     ++	flock.l_len = 0;
      +
      +	return fcntl(fd, F_SETLKW, &flock);
      +}
 2:  8dda2d530 ! 2:  fa0c282aa mingw: implement lock_or_unlock_fd_for_appending()
     @@ -54,24 +54,3 @@
       #define has_dos_drive_prefix(path) \
       	(isalpha(*(path)) && (path)[1] == ':' ? 2 : 0)
       int mingw_skip_dos_drive_prefix(char **path);
     -
     -diff --git a/config.mak.uname b/config.mak.uname
     ---- a/config.mak.uname
     -+++ b/config.mak.uname
     -@@
     - 	NO_POSIX_GOODIES = UnfortunatelyYes
     - 	NATIVE_CRLF = YesPlease
     - 	DEFAULT_HELP_FORMAT = html
     -+	HAVE_FLOCK = YesWeEmulate
     - 
     - 	CC = compat/vcbuild/scripts/clink.pl
     - 	AR = compat/vcbuild/scripts/lib.pl
     -@@
     - 	NO_INET_NTOP = YesPlease
     - 	NO_POSIX_GOODIES = UnfortunatelyYes
     - 	DEFAULT_HELP_FORMAT = html
     -+	HAVE_FLOCK = YesWeEmulate
     -+
     - 	COMPAT_CFLAGS += -DNOGDI -Icompat -Icompat/win32
     - 	COMPAT_CFLAGS += -DSTRIP_EXTENSION=\".exe\"
     - 	COMPAT_OBJS += compat/mingw.o compat/winansi.o \
 3:  a53e72198 ! 3:  1f5c15c7e trace: lock the trace file to avoid racy trace_write() calls
     @@ -14,6 +14,17 @@
          To remedy this, let's lock the file descriptors for exclusive writing,
          using the function we just introduced in the previous commit.
      
     +    Note: while the POSIX documentation of fcntl() at
     +    http://pubs.opengroup.org/onlinepubs/9699919799/functions/fcntl.html
     +    suggests that the `errno` is set to `EINVAL` when being asked to
     +    lock a file descriptor that cannot be locked, on macOS it results in
     +    `EBADF` when trying to lock a redirected `stdout` (which the
     +    documentation claims should indicate that the file descriptor is not
     +    valid for writing).
     +
     +    To cover all our bases, we simply treat both `EINVAL` and `EBADF` as
     +    indicators that we cannot lock/unlock this file descriptor.
     +
          Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
      
      diff --git a/trace.c b/trace.c
     @@ -27,7 +38,7 @@
      +	int fd = get_trace_fd(key), locked;
      +
      +	locked = !lock_or_unlock_fd_for_appending(fd, 1);
     -+	if (!locked && errno != EBADF)
     ++	if (!locked && errno != EBADF && errno != EINVAL)
      +		warning("unable to lock file descriptor for %s: %s",
      +			key->key, strerror(errno));
      +	if (write_in_full(fd, buf, len) < 0) {
 4:  f57234154 ! 4:  38358ac74 trace: verify that locking works
     @@ -131,13 +131,13 @@
      +		strbuf_rtrim(&buf);
      +		if (!strcmp("lock", buf.buf)) {
      +			if (lock_or_unlock_fd_for_appending(fd, 1) < 0 &&
     -+			    errno != EBADF)
     ++			    errno != EBADF && errno != EINVAL)
      +				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)
     ++			    errno != EBADF && errno != EINVAL)
      +				die_errno("'%s': unlock", child_name);
      +			ACK("unlock");
      +			locked = 0;
-- 
gitgitgadget
Johannes Schindelin via GitGitGadget· Aug 10, 2018, 19:47 UTC · re: Johannes Schindelin via GitGitGadget · lore

[PATCH v2 1/4] Introduce a function to lock/unlock file descriptors when appending

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

This function will be used to make write accesses in trace_write() a bit safer.

Note: this patch takes a very different approach for cross-platform
support than Git is historically taking: the original approach is to
first implement everything on Linux, using the functions available on
Linux, and then trying to emulate these functions on platforms that do
not have those functions such as Windows.

This leads to all kinds of undesirable quirks in Git's source code (and performance characteristics) because of the lack of a proper abstraction layer: instead of declaring functions for the functionality we *actually* need, we abuse POSIX functions to say what we need, even if those functions serve much broader purposes (and do not make at all clear what the caller wants of them).

For example, when Git wants to determine whether a path refers to a symbolic link, it calls lstat(). That POSIX function has to be emulated on Windows, painstakingly filling all the information lstat() would, only for the caller to throw away everything except that one bit of information, and all of the time figuring out the mtime/atime/ctime and file size and whatnot was spent in vain.

If we were to follow that approach, we would extend the fcntl() emulation in compat/mingw.c after this commit, to support the function added in this commit.

But fcntl() allows a lot more versatile file region locking that we actually need, so by necessity the fcntl() emulation would be quite complex: To support the `l_whence = SEEK_CUR` (which we would use, if it did not require so much book-keeping due to our writing between locking and unlocking the file), we would have to call `SetFilePointerEx()` (after obtaining the `HANDLE` on which all Win32 API functions work instead of the integer file descriptors used by all POSIX functions). Multiplying the number of Win32 API round-trips. Of course, we could implement an incomplete emulation of fcntl()'s F_WRLCK, but that would be unsatisfying.

An alternative approach would be to use the `flock()` function, whose semantics are much closer to existing Win32 API. But `flock()` is not even a POSIX standard, so we would have to implement emulation of `flock()` for *other* platforms. And it would again be the wrong thing to do, as we would once again fail to have an abstraction that clearly says what *exact*functionality we want to use.

This commit expressly tries to set a precedent for a better approach: Let's introduce a proper abstraction: a function that says in its name precisely what Git wants it to do (as opposed to *how* it does it on Linux): lock_or_unlock_fd_for_appending().

The next commit will provide a Windows-specific implementation of this function/functionality.

Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
---
 git-compat-util.h |  2 ++
 wrapper.c         | 16 ++++++++++++++++
 2 files changed, 18 insertions(+)
Show changes to 2 files +18 −0

git-compat-util.h, wrapper.c

diff --git a/git-compat-util.h b/git-compat-util.h
index 9a64998b2..13b83bade 100644
--- a/git-compat-util.h
+++ b/git-compat-util.h
@@ -1202,6 +1202,8 @@ struct tm *git_gmtime_r(const time_t *, struct tm *);
 #define getc_unlocked(fh) getc(fh)
 #endif
 
+extern int lock_or_unlock_fd_for_appending(int fd, int lock_it);
+
 /*
  * Our code often opens a path to an optional file, to work on its
  * contents when we can successfully open it.  We can ignore a failure
diff --git a/wrapper.c b/wrapper.c
index e4fa9d84c..5aecbda34 100644
--- a/wrapper.c
+++ b/wrapper.c
@@ -690,3 +690,19 @@ int xgethostname(char *buf, size_t len)
 		buf[len - 1] = 0;
 	return ret;
 }
+
+#ifndef GIT_WINDOWS_NATIVE
+int lock_or_unlock_fd_for_appending(int fd, int lock_it)
+{
+	struct flock flock;
+
+	flock.l_type = lock_it ? F_WRLCK : F_UNLCK;
+
+	/* (un-)lock the whole file */
+	flock.l_whence = SEEK_SET;
+	flock.l_start = 0;
+	flock.l_len = 0;
+
+	return fcntl(fd, F_SETLKW, &flock);
+}
+#endif
-- 
gitgitgadget
Junio C Hamano· Aug 10, 2018, 20:05 UTC · re: Johannes Schindelin via GitGitGadget · lore

Re: [PATCH v2 1/4] Introduce a function to lock/unlock file descriptors when appending

"Johannes Schindelin via GitGitGadget" <gitgitgadget@gmail.com> writes:

Show 16 quoted lines
> +
> +#ifndef GIT_WINDOWS_NATIVE
> +int lock_or_unlock_fd_for_appending(int fd, int lock_it)
> +{
> +	struct flock flock;
> +
> +	flock.l_type = lock_it ? F_WRLCK : F_UNLCK;
> +
> +	/* (un-)lock the whole file */
> +	flock.l_whence = SEEK_SET;
> +	flock.l_start = 0;
> +	flock.l_len = 0;
> +
> +	return fcntl(fd, F_SETLKW, &flock);
> +}
> +#endif

I think people already told you that this is not needed on systems with properly working O_APPEND [*1*]

	Side note #1: and with network filesystems where O_APPEND
        may not work reliably, fcntl based range locking would not
        work either, so having this would not help.

I saw other Johannes and other Jeff peeking into fixing O_APPEND; I do not know how well that effort goes, but it would be preferrable if we can successfully go that route.

As I said in my review of the first patch in v1 series, I am not fundamentally opposed to a few "lock here to work around lack of O_APPEND" and "unlock here for the same reason" calls to limited codepaths as a workaround, as the damage is limited (that is why I earlier looked at our use of O_APPEND), but that would be the last resort if O_APPEND cannot be made to work reliably on Windows.

But even if we end up doing so, on systems with POSIX O_APPEND working, I think that function should be

    #define lock_or_unlock_for_appending(fd, lock) 0 /* nothing to do */
Johannes Schindelin· Aug 10, 2018, 21:31 UTC · re: Junio C Hamano · lore

Re: [PATCH v2 1/4] Introduce a function to lock/unlock file descriptors when appending

Hi Junio,
On Fri, 10 Aug 2018, Junio C Hamano wrote:
Show 22 quoted lines
> "Johannes Schindelin via GitGitGadget" <gitgitgadget@gmail.com>
> writes:
> 
> > +
> > +#ifndef GIT_WINDOWS_NATIVE
> > +int lock_or_unlock_fd_for_appending(int fd, int lock_it)
> > +{
> > +	struct flock flock;
> > +
> > +	flock.l_type = lock_it ? F_WRLCK : F_UNLCK;
> > +
> > +	/* (un-)lock the whole file */
> > +	flock.l_whence = SEEK_SET;
> > +	flock.l_start = 0;
> > +	flock.l_len = 0;
> > +
> > +	return fcntl(fd, F_SETLKW, &flock);
> > +}
> > +#endif
> 
> I think people already told you that this is not needed on systems
> with properly working O_APPEND [*1*]

I also wanted to safeguard against other (well-behaved) programs writing to the trace file.

Granted, this is a bit theoretical, but it is quite possible that other Git implementations do things differently than our trace.c. But with the file locking that even that POSIX man page I quoted recommends, all this is not an issue.

And this patch series implements that locking.
> 	Side note #1: and with network filesystems where O_APPEND
>         may not work reliably, fcntl based range locking would not
>         work either, so having this would not help.
At least on Windows, it would help, though.

And if there *is* a way to lock via NFS (which is the only network filesystem I am aware of that has these locking issues, at least *some* others are just fine), we would at least already have that function where to implement it.

> I saw other Johannes and other Jeff peeking into fixing O_APPEND;
> I do not know how well that effort goes, but it would be preferrable
> if we can successfully go that route.  

As I pointed out previously, my mail provider is losing mails left and right for me. Could I ask for a pointer?

Show 11 quoted lines
> As I said in my review of the first patch in v1 series, I am not
> fundamentally opposed to a few "lock here to work around lack of
> O_APPEND" and "unlock here for the same reason" calls to limited
> codepaths as a workaround, as the damage is limited (that is why I
> earlier looked at our use of O_APPEND), but that would be the last
> resort if O_APPEND cannot be made to work reliably on Windows.
> 
> But even if we end up doing so, on systems with POSIX O_APPEND
> working, I think that function should be
> 
>     #define lock_or_unlock_for_appending(fd, lock) 0 /* nothing to do */

I think that that would be only appropriate if there were no other Git implementations.

Ciao, Dscho

Johannes Schindelin via GitGitGadget· Aug 10, 2018, 19:47 UTC · re: Johannes Schindelin via GitGitGadget · lore

[PATCH v2 2/4] mingw: implement lock_or_unlock_fd_for_appending()

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

For some reason, t/t5552-skipping-fetch-negotiator.sh fails particularly often on Windows due to racy tracing where the `git upload-pack` and the `git fetch` processes compete for the same file.

We just introduced a remedy that uses fcntl(), but Windows does not have fcntl(). So let's implement an alternative.

Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
---
 compat/mingw.c | 19 +++++++++++++++++++
 compat/mingw.h |  3 +++
 2 files changed, 22 insertions(+)
Show changes to 2 files +22 −0

compat/mingw.c, compat/mingw.h

diff --git a/compat/mingw.c b/compat/mingw.c
index 6ded1c859..6da9ce861 100644
--- a/compat/mingw.c
+++ b/compat/mingw.c
@@ -514,6 +514,25 @@ int mingw_chmod(const char *filename, int mode)
 	return _wchmod(wfilename, mode);
 }
 
+int mingw_lock_or_unlock_fd_for_appending(int fd, int lock_it)
+{
+	HANDLE handle = (HANDLE)_get_osfhandle(fd);
+	OVERLAPPED overlapped = { 0 };
+	DWORD err;
+
+	if (!lock_it && UnlockFileEx(handle, 0, -1, 0, &overlapped))
+		return 0;
+	if (lock_it &&
+	    LockFileEx(handle, LOCKFILE_EXCLUSIVE_LOCK, 0, -1, 0, &overlapped))
+		return 0;
+
+	err = GetLastError();
+	/* LockFileEx() cannot lock pipes */
+	errno = err == ERROR_INVALID_FUNCTION ?
+		EBADF : err_win_to_posix(GetLastError());
+	return -1;
+}
+
 /*
  * The unit of FILETIME is 100-nanoseconds since January 1, 1601, UTC.
  * Returns the 100-nanoseconds ("hekto nanoseconds") since the epoch.
diff --git a/compat/mingw.h b/compat/mingw.h
index 571019d0b..0f76d89a9 100644
--- a/compat/mingw.h
+++ b/compat/mingw.h
@@ -397,6 +397,9 @@ HANDLE winansi_get_osfhandle(int fd);
  * git specific compatibility
  */
 
+int mingw_lock_or_unlock_fd_for_appending(int fd, int lock_it);
+#define lock_or_unlock_fd_for_appending mingw_lock_or_unlock_fd_for_appending
+
 #define has_dos_drive_prefix(path) \
 	(isalpha(*(path)) && (path)[1] == ':' ? 2 : 0)
 int mingw_skip_dos_drive_prefix(char **path);
-- 
gitgitgadget
Johannes Schindelin via GitGitGadget· Aug 10, 2018, 19:47 UTC · re: Johannes Schindelin via GitGitGadget · lore

[PATCH v2 3/4] trace: lock the trace file to avoid racy trace_write() calls

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

When multiple processes try to write to the same file, it is not guaranteed that everything works as expected: those writes can overlap, and in the worst case even lose messages.

This happens in t/t5552-skipping-fetch-negotiator.sh, where we abuse the `GIT_TRACE` facility to write traces of two concurrent processes (`git fetch` and `git upload-pack`) to the same file, and then verify that the trace contains certain expected breadcrumbs.

To remedy this, let's lock the file descriptors for exclusive writing, using the function we just introduced in the previous commit.

Note: while the POSIX documentation of fcntl() at
http://pubs.opengroup.org/onlinepubs/9699919799/functions/fcntl.html
suggests that the `errno` is set to `EINVAL` when being asked to
lock a file descriptor that cannot be locked, on macOS it results in
`EBADF` when trying to lock a redirected `stdout` (which the
documentation claims should indicate that the file descriptor is not
valid for writing).

To cover all our bases, we simply treat both `EINVAL` and `EBADF` as indicators that we cannot lock/unlock this file descriptor.

Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
---
 trace.c | 11 ++++++++++-
 1 file changed, 10 insertions(+), 1 deletion(-)
Show changes to trace.c +10 −1
diff --git a/trace.c b/trace.c
index fc623e91f..16abdb816 100644
--- a/trace.c
+++ b/trace.c
@@ -114,11 +114,20 @@ static int prepare_trace_line(const char *file, int line,
 
 static void trace_write(struct trace_key *key, const void *buf, unsigned len)
 {
-	if (write_in_full(get_trace_fd(key), buf, len) < 0) {
+	int fd = get_trace_fd(key), locked;
+
+	locked = !lock_or_unlock_fd_for_appending(fd, 1);
+	if (!locked && errno != EBADF && errno != EINVAL)
+		warning("unable to lock file descriptor for %s: %s",
+			key->key, strerror(errno));
+	if (write_in_full(fd, buf, len) < 0) {
 		warning("unable to write trace for %s: %s",
 			key->key, strerror(errno));
 		trace_disable(key);
 	}
+	if (locked && lock_or_unlock_fd_for_appending(fd, 0) < 0)
+		warning("failed to remove lock on fd for %s: %s",
+			key->key, strerror(errno));
 }
 
 void trace_verbatim(struct trace_key *key, const void *buf, unsigned len)
-- 
gitgitgadget
Johannes Schindelin via GitGitGadget· Aug 10, 2018, 19:47 UTC · re: Johannes Schindelin via GitGitGadget · lore

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

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
Show changes to 5 files +139 −0

Makefile, t/helper/test-tool.c, t/helper/test-tool.h, t/helper/test-trace.c, t/t0070-fundamental.sh

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..04159c77a
--- /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 && errno != EINVAL)
+				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 && errno != EINVAL)
+				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

← back to recent threads