[PATCH 0/1] vreportf: Fix interleaving issues, remove 4096 limitation

[PATCH 0/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Alexandr Miloslavskiy via GitGitGadget]

This fixes t5516 on Windows. For detailed explanation please refer to code
comments in this commit.

There was a lot of back-and-forth already in vreportf(): d048a96e
(2007-11-09) - 'char msg[256]' is introduced to avoid interleaving 389d1767
(2009-03-25) - Buffer size increased to 1024 to avoid truncation 625a860c
(2009-11-22) - Buffer size increased to 4096 to avoid truncation f4c3edc0
(2015-08-11) - Buffer removed to avoid truncation b5a9e435 (2017-01-11) -
Reverts f4c3edc0 to be able to replace control chars before sending to
stderr

This fix attempts to solve all issues:

1) avoid multiple fprintf() interleaving 2) avoid truncation 3) avoid char
interleaving in fprintf() on some platforms 4) avoid buffer block
interleaving when output is large 5) avoid Out-of-order messages 6) replace
control characters in output

Other commits worthy of notice: 9ac13ec9 (2006-10-11) - Another attempt to
solve interleaving. This is seemingly related to d048a96e. 137a0d0e
(2007-11-19) - Addresses out-of-order for display() 34df8aba (2009-03-10) -
Switches xwrite() to fprintf() in recv_sideband() to support UTF-8 emulation
eac14f89 (2012-01-14) - Removes the need for fprintf() for UTF-8 emulation,
so it's safe to use xwrite() again 5e5be9e2 (2016-06-28) - recv_sideband()
uses xwrite() again

Signed-off-by: Alexandr Miloslavskiy alexandr.miloslavskiy@syntevo.com
[alexandr.miloslavskiy@syntevo.com]

Alexandr Miloslavskiy (1):
  vreportf: Fix interleaving issues, remove 4096 limitation

 usage.c | 154 +++++++++++++++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 148 insertions(+), 6 deletions(-)


base-commit: d966095db01190a2196e31195ea6fa0c722aa732
Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-407%2FSyntevoAlex%2F%230194_t5516_fixes-v1
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-407/SyntevoAlex/#0194_t5516_fixes-v1
Pull-Request: https://github.com/gitgitgadget/git/pull/407
-- 
gitgitgadget

[PATCH 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Alexandr Miloslavskiy via GitGitGadget]

From: Alexandr Miloslavskiy <alexandr.miloslavskiy@syntevo.com>

This also fixes t5516 on Windows VS build.
For detailed explanation please refer to code comments in this commit.

There was a lot of back-and-forth already in vreportf():
d048a96e (2007-11-09) - 'char msg[256]' is introduced to avoid interleaving
389d1767 (2009-03-25) - Buffer size increased to 1024 to avoid truncation
625a860c (2009-11-22) - Buffer size increased to 4096 to avoid truncation
f4c3edc0 (2015-08-11) - Buffer removed to avoid truncation
b5a9e435 (2017-01-11) - Reverts f4c3edc0 to be able to replace control
                        chars before sending to stderr

This fix attempts to solve all issues:
1) avoid multiple fprintf() interleaving
2) avoid truncation
3) avoid char interleaving in fprintf() on some platforms
4) avoid buffer block interleaving when output is large
5) avoid out-of-order messages
6) replace control characters in output

Other commits worthy of notice:
9ac13ec9 (2006-10-11) - Another attempt to solve interleaving.
						This is seemingly related to d048a96e.
137a0d0e (2007-11-19) - Addresses out-of-order for display()
34df8aba (2009-03-10) - Switches xwrite() to fprintf() in recv_sideband()
						to support UTF-8 emulation
eac14f89 (2012-01-14) - Removes the need for fprintf() for UTF-8 emulation,
						so it's safe to use xwrite() again
5e5be9e2 (2016-06-28) - recv_sideband() uses xwrite() again

Signed-off-by: Alexandr Miloslavskiy <alexandr.miloslavskiy@syntevo.com>
---
 usage.c | 154 +++++++++++++++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 148 insertions(+), 6 deletions(-)

diff --git a/usage.c b/usage.c
index 2fdb20086b..ccdd91a7b9 100644
--- a/usage.c
+++ b/usage.c
@@ -6,17 +6,159 @@
 #include "git-compat-util.h"
 #include "cache.h"
 
+static void replace_control_chars(char* str, size_t size, char replacement)
+{
+	size_t i;
+
+	for (i = 0; i < size; i++) {
+    		if (iscntrl(str[i]) && str[i] != '\t' && str[i] != '\n')
+			str[i] = replacement;
+	}
+}
+
+/*
+ * Atomically report (prefix + vsnprintf(err, params) + '\n') to stderr.
+ * Always returns desired buffer size.
+ * Doesn't write to stderr if content didn't fit.
+ *
+ * This function composes everything into a single buffer before
+ * sending to stderr. This is to defeat various non-atomic issues:
+ * 1) If stderr is fully buffered:
+ *    the ordering of stdout and stderr messages could be wrong,
+ *    because stderr output waits for the buffer to become full.
+ * 2) If stderr has any type of buffering:
+ *    buffer has fixed size, which could lead to interleaved buffer
+ *    blocks when two threads/processes write at the same time.
+ * 3) If stderr is not buffered:
+ *    There are two problems, one with atomic fprintf() and another
+ *    for non-atomic fprintf(), and both occur depending on platform
+ *    (see details below). If atomic, this function still writes 3
+ *    parts, which could get interleaved with multiple threads. If
+ *    not atomic, then fprintf() will basically write char-by-char,
+ *    which leads to unreadable char-interleaved writes if two
+ *    processes write to stderr at the same time (threads are OK
+ *    because fprintf() usually locks file in current process). This
+ *    for example happens in t5516 where 'git-upload-pack' detects
+ *    an error, reports it to parent 'git fetch' and both die() at the
+ *    same time.
+ *
+ *    Behaviors, at the moment of writing:
+ *    a) libc - fprintf()-interleaved
+ *       fprintf() enables temporary stream buffering.
+ *       See: buffered_vfprintf()
+ *    b) VC++ - char-interleaved
+ *       fprintf() enables temporary stream buffering, but only if
+ *       stream was not set to no buffering. This has no effect,
+ *       because stderr is not buffered by default, and git takes
+ *       an extra step to ensure that in swap_osfhnd().
+ *       See: _iob[_IOB_ENTRIES],
+ *            __acrt_stdio_temporary_buffering_guard,
+ *            has_any_buffer()
+ *    c) MinGW - char-interleaved (console), full buffering (file)
+ *       fprintf() obeys stderr buffering. But it uses old MSVCRT.DLL,
+ *       which eventually calls _flsbuf(), which enables buffering unless
+ *       isatty(stderr) or buffering is disabled. Buffering is not disabled
+ *       by default for stderr. Therefore, buffering is enabled for
+ *       file-redirected stderr.
+ *       See: __mingw_vfprintf(),
+ *            __pformat_wcputs(),
+ *            _fputc_nolock(),
+ *            _flsbuf(),
+ *            _iob[_IOB_ENTRIES]
+ * 4) If stderr is line buffered: MinGW/VC++ will enable full
+ *    buffering instead. See MSDN setvbuf().
+ */
+static size_t vreportf_buf(char *buf, size_t buf_size, const char *prefix, const char *err, va_list params)
+{
+	int printf_ret = 0;
+	size_t prefix_size = 0;
+	size_t total_size = 0;
+
+	/*
+	 * NOTE: Can't use strbuf functions here, because it can be called when
+	 * malloc() is no longer possible, and strbuf will recurse die().
+	 */
+
+	/* Prefix */
+	prefix_size = strlen(prefix);
+	if (total_size + prefix_size <= buf_size)
+		memcpy(buf + total_size, prefix, prefix_size);
+	
+	total_size += prefix_size;
+
+	/* Formatted message */
+	if (total_size <= buf_size)
+		printf_ret = vsnprintf(buf + total_size, buf_size - total_size, err, params);
+	else
+		printf_ret = vsnprintf(NULL, 0, err, params);
+
+	if (printf_ret < 0)
+		BUG("your vsnprintf is broken (returned %d)", printf_ret);
+
+	/*
+	 * vsnprintf() returns _desired_ size (without terminating null).
+	 * If vsnprintf() was truncated that will be seen when appending '\n'.
+	 */
+	total_size += printf_ret;
+
+	/* Trailing \n */
+	if (total_size + 1 <= buf_size)
+		buf[total_size] = '\n';
+
+	total_size += 1;
+
+	/* Send the buffer, if content fits */
+	if (total_size <= buf_size) {
+	    replace_control_chars(buf, total_size, '?');
+	    fwrite(buf, total_size, 1, stderr);
+	}
+
+	return total_size;
+}
+
 void vreportf(const char *prefix, const char *err, va_list params)
 {
+	size_t res = 0;
+	char *buf = NULL;
+	size_t buf_size = 0;
+
+	/*
+	 * NOTE: This can be called from failed xmalloc(). Any malloc() can
+	 * fail now. Let's try to report with a fixed size stack based buffer.
+	 * Also, most messages should fit, and this path is faster.
+	 */
 	char msg[4096];
-	char *p;
+	res = vreportf_buf(msg, sizeof(msg), prefix, err, params);
+	if (res <= sizeof(msg)) {
+		/* Success */
+		return;
+	}
 
-	vsnprintf(msg, sizeof(msg), err, params);
-	for (p = msg; *p; p++) {
-		if (iscntrl(*p) && *p != '\t' && *p != '\n')
-			*p = '?';
+	/*
+	 * Try to allocate a suitable sized malloc(), if possible.
+	 * NOTE: Do not use xmalloc(), because on failure it will call
+	 * die() or warning() and lead to recursion.
+	 */
+	buf_size = res;
+	buf = malloc(buf_size);
+	if (buf) {
+		res = vreportf_buf(buf, buf_size, prefix, err, params);
+		FREE_AND_NULL(buf);
+
+		if (res <= buf_size) {
+			/* Success */
+			return;
+		}
 	}
-	fprintf(stderr, "%s%s\n", prefix, msg);
+
+	/* 
+	 * When everything fails, report in parts.
+	 * This can have all problems prevented by vreportf_buf().
+	 */
+	fprintf(stderr, "vreportf: not enough memory (tried to allocate %lu bytes)\n", (unsigned long)buf_size);
+	fputs(prefix, stderr);
+	vfprintf(stderr, err, params);
+	fputc('\n', stderr);
 }
 
 static NORETURN void usage_builtin(const char *err, va_list params)
-- 
gitgitgadget

[PATCH v2 0/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Alexandr Miloslavskiy via GitGitGadget]

This fixes t5516 on Windows. For detailed explanation please refer to code
comments in this commit.

There was a lot of back-and-forth already in vreportf(): d048a96e
(2007-11-09) - 'char msg[256]' is introduced to avoid interleaving 389d1767
(2009-03-25) - Buffer size increased to 1024 to avoid truncation 625a860c
(2009-11-22) - Buffer size increased to 4096 to avoid truncation f4c3edc0
(2015-08-11) - Buffer removed to avoid truncation b5a9e435 (2017-01-11) -
Reverts f4c3edc0 to be able to replace control chars before sending to
stderr

This fix attempts to solve all issues:

1) avoid multiple fprintf() interleaving 2) avoid truncation 3) avoid char
interleaving in fprintf() on some platforms 4) avoid buffer block
interleaving when output is large 5) avoid Out-of-order messages 6) replace
control characters in output

Other commits worthy of notice: 9ac13ec9 (2006-10-11) - Another attempt to
solve interleaving. This is seemingly related to d048a96e. 137a0d0e
(2007-11-19) - Addresses out-of-order for display() 34df8aba (2009-03-10) -
Switches xwrite() to fprintf() in recv_sideband() to support UTF-8 emulation
eac14f89 (2012-01-14) - Removes the need for fprintf() for UTF-8 emulation,
so it's safe to use xwrite() again 5e5be9e2 (2016-06-28) - recv_sideband()
uses xwrite() again

Signed-off-by: Alexandr Miloslavskiy alexandr.miloslavskiy@syntevo.com
[alexandr.miloslavskiy@syntevo.com]

Alexandr Miloslavskiy (1):
  vreportf: Fix interleaving issues, remove 4096 limitation

 usage.c | 154 +++++++++++++++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 148 insertions(+), 6 deletions(-)


base-commit: d966095db01190a2196e31195ea6fa0c722aa732
Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-407%2FSyntevoAlex%2F%230194_t5516_fixes-v2
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-407/SyntevoAlex/#0194_t5516_fixes-v2
Pull-Request: https://github.com/gitgitgadget/git/pull/407

Range-diff vs v1:

 1:  5fd06fa881 ! 1:  54f0d6f6b5 vreportf: Fix interleaving issues, remove 4096 limitation
     @@ -23,12 +23,12 @@
      
          Other commits worthy of notice:
          9ac13ec9 (2006-10-11) - Another attempt to solve interleaving.
     -                                                    This is seemingly related to d048a96e.
     +                            This is seemingly related to d048a96e.
          137a0d0e (2007-11-19) - Addresses out-of-order for display()
          34df8aba (2009-03-10) - Switches xwrite() to fprintf() in recv_sideband()
     -                                                    to support UTF-8 emulation
     +                            to support UTF-8 emulation
          eac14f89 (2012-01-14) - Removes the need for fprintf() for UTF-8 emulation,
     -                                                    so it's safe to use xwrite() again
     +                            so it's safe to use xwrite() again
          5e5be9e2 (2016-06-28) - recv_sideband() uses xwrite() again
      
          Signed-off-by: Alexandr Miloslavskiy <alexandr.miloslavskiy@syntevo.com>

-- 
gitgitgadget

[PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Alexandr Miloslavskiy via GitGitGadget]

From: Alexandr Miloslavskiy <alexandr.miloslavskiy@syntevo.com>

This also fixes t5516 on Windows VS build.
For detailed explanation please refer to code comments in this commit.

There was a lot of back-and-forth already in vreportf():
d048a96e (2007-11-09) - 'char msg[256]' is introduced to avoid interleaving
389d1767 (2009-03-25) - Buffer size increased to 1024 to avoid truncation
625a860c (2009-11-22) - Buffer size increased to 4096 to avoid truncation
f4c3edc0 (2015-08-11) - Buffer removed to avoid truncation
b5a9e435 (2017-01-11) - Reverts f4c3edc0 to be able to replace control
                        chars before sending to stderr

This fix attempts to solve all issues:
1) avoid multiple fprintf() interleaving
2) avoid truncation
3) avoid char interleaving in fprintf() on some platforms
4) avoid buffer block interleaving when output is large
5) avoid out-of-order messages
6) replace control characters in output

Other commits worthy of notice:
9ac13ec9 (2006-10-11) - Another attempt to solve interleaving.
                        This is seemingly related to d048a96e.
137a0d0e (2007-11-19) - Addresses out-of-order for display()
34df8aba (2009-03-10) - Switches xwrite() to fprintf() in recv_sideband()
                        to support UTF-8 emulation
eac14f89 (2012-01-14) - Removes the need for fprintf() for UTF-8 emulation,
                        so it's safe to use xwrite() again
5e5be9e2 (2016-06-28) - recv_sideband() uses xwrite() again

Signed-off-by: Alexandr Miloslavskiy <alexandr.miloslavskiy@syntevo.com>
---
 usage.c | 154 +++++++++++++++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 148 insertions(+), 6 deletions(-)

diff --git a/usage.c b/usage.c
index 2fdb20086b..ccdd91a7b9 100644
--- a/usage.c
+++ b/usage.c
@@ -6,17 +6,159 @@
 #include "git-compat-util.h"
 #include "cache.h"
 
+static void replace_control_chars(char* str, size_t size, char replacement)
+{
+	size_t i;
+
+	for (i = 0; i < size; i++) {
+    		if (iscntrl(str[i]) && str[i] != '\t' && str[i] != '\n')
+			str[i] = replacement;
+	}
+}
+
+/*
+ * Atomically report (prefix + vsnprintf(err, params) + '\n') to stderr.
+ * Always returns desired buffer size.
+ * Doesn't write to stderr if content didn't fit.
+ *
+ * This function composes everything into a single buffer before
+ * sending to stderr. This is to defeat various non-atomic issues:
+ * 1) If stderr is fully buffered:
+ *    the ordering of stdout and stderr messages could be wrong,
+ *    because stderr output waits for the buffer to become full.
+ * 2) If stderr has any type of buffering:
+ *    buffer has fixed size, which could lead to interleaved buffer
+ *    blocks when two threads/processes write at the same time.
+ * 3) If stderr is not buffered:
+ *    There are two problems, one with atomic fprintf() and another
+ *    for non-atomic fprintf(), and both occur depending on platform
+ *    (see details below). If atomic, this function still writes 3
+ *    parts, which could get interleaved with multiple threads. If
+ *    not atomic, then fprintf() will basically write char-by-char,
+ *    which leads to unreadable char-interleaved writes if two
+ *    processes write to stderr at the same time (threads are OK
+ *    because fprintf() usually locks file in current process). This
+ *    for example happens in t5516 where 'git-upload-pack' detects
+ *    an error, reports it to parent 'git fetch' and both die() at the
+ *    same time.
+ *
+ *    Behaviors, at the moment of writing:
+ *    a) libc - fprintf()-interleaved
+ *       fprintf() enables temporary stream buffering.
+ *       See: buffered_vfprintf()
+ *    b) VC++ - char-interleaved
+ *       fprintf() enables temporary stream buffering, but only if
+ *       stream was not set to no buffering. This has no effect,
+ *       because stderr is not buffered by default, and git takes
+ *       an extra step to ensure that in swap_osfhnd().
+ *       See: _iob[_IOB_ENTRIES],
+ *            __acrt_stdio_temporary_buffering_guard,
+ *            has_any_buffer()
+ *    c) MinGW - char-interleaved (console), full buffering (file)
+ *       fprintf() obeys stderr buffering. But it uses old MSVCRT.DLL,
+ *       which eventually calls _flsbuf(), which enables buffering unless
+ *       isatty(stderr) or buffering is disabled. Buffering is not disabled
+ *       by default for stderr. Therefore, buffering is enabled for
+ *       file-redirected stderr.
+ *       See: __mingw_vfprintf(),
+ *            __pformat_wcputs(),
+ *            _fputc_nolock(),
+ *            _flsbuf(),
+ *            _iob[_IOB_ENTRIES]
+ * 4) If stderr is line buffered: MinGW/VC++ will enable full
+ *    buffering instead. See MSDN setvbuf().
+ */
+static size_t vreportf_buf(char *buf, size_t buf_size, const char *prefix, const char *err, va_list params)
+{
+	int printf_ret = 0;
+	size_t prefix_size = 0;
+	size_t total_size = 0;
+
+	/*
+	 * NOTE: Can't use strbuf functions here, because it can be called when
+	 * malloc() is no longer possible, and strbuf will recurse die().
+	 */
+
+	/* Prefix */
+	prefix_size = strlen(prefix);
+	if (total_size + prefix_size <= buf_size)
+		memcpy(buf + total_size, prefix, prefix_size);
+	
+	total_size += prefix_size;
+
+	/* Formatted message */
+	if (total_size <= buf_size)
+		printf_ret = vsnprintf(buf + total_size, buf_size - total_size, err, params);
+	else
+		printf_ret = vsnprintf(NULL, 0, err, params);
+
+	if (printf_ret < 0)
+		BUG("your vsnprintf is broken (returned %d)", printf_ret);
+
+	/*
+	 * vsnprintf() returns _desired_ size (without terminating null).
+	 * If vsnprintf() was truncated that will be seen when appending '\n'.
+	 */
+	total_size += printf_ret;
+
+	/* Trailing \n */
+	if (total_size + 1 <= buf_size)
+		buf[total_size] = '\n';
+
+	total_size += 1;
+
+	/* Send the buffer, if content fits */
+	if (total_size <= buf_size) {
+	    replace_control_chars(buf, total_size, '?');
+	    fwrite(buf, total_size, 1, stderr);
+	}
+
+	return total_size;
+}
+
 void vreportf(const char *prefix, const char *err, va_list params)
 {
+	size_t res = 0;
+	char *buf = NULL;
+	size_t buf_size = 0;
+
+	/*
+	 * NOTE: This can be called from failed xmalloc(). Any malloc() can
+	 * fail now. Let's try to report with a fixed size stack based buffer.
+	 * Also, most messages should fit, and this path is faster.
+	 */
 	char msg[4096];
-	char *p;
+	res = vreportf_buf(msg, sizeof(msg), prefix, err, params);
+	if (res <= sizeof(msg)) {
+		/* Success */
+		return;
+	}
 
-	vsnprintf(msg, sizeof(msg), err, params);
-	for (p = msg; *p; p++) {
-		if (iscntrl(*p) && *p != '\t' && *p != '\n')
-			*p = '?';
+	/*
+	 * Try to allocate a suitable sized malloc(), if possible.
+	 * NOTE: Do not use xmalloc(), because on failure it will call
+	 * die() or warning() and lead to recursion.
+	 */
+	buf_size = res;
+	buf = malloc(buf_size);
+	if (buf) {
+		res = vreportf_buf(buf, buf_size, prefix, err, params);
+		FREE_AND_NULL(buf);
+
+		if (res <= buf_size) {
+			/* Success */
+			return;
+		}
 	}
-	fprintf(stderr, "%s%s\n", prefix, msg);
+
+	/* 
+	 * When everything fails, report in parts.
+	 * This can have all problems prevented by vreportf_buf().
+	 */
+	fprintf(stderr, "vreportf: not enough memory (tried to allocate %lu bytes)\n", (unsigned long)buf_size);
+	fputs(prefix, stderr);
+	vfprintf(stderr, err, params);
+	fputc('\n', stderr);
 }
 
 static NORETURN void usage_builtin(const char *err, va_list params)
-- 
gitgitgadget

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Johannes Schindelin]

Hi Alex,


On Tue, 22 Oct 2019, Alexandr Miloslavskiy via GitGitGadget wrote:

> From: Alexandr Miloslavskiy <alexandr.miloslavskiy@syntevo.com>
>
> This also fixes t5516 on Windows VS build.

Maybe this could do with an example? I could imagine that we might want
to use the log of
https://dev.azure.com/git/git/_build/results?buildId=1264&view=ms.vss-test-web.build-test-results-tab&runId=1016906&resultId=101011&paneView=attachments:

-- snip --
[...]
++ eval '
	want_trace && set -x

mkdir -p "$TRASH_DIRECTORY/prereq-test-dir" &&
(
	cd "$TRASH_DIRECTORY/prereq-test-dir" &&
	! git env--helper --type=bool --default=0 --exit-code GIT_TEST_GETTEXT_POISON

)'
+++ want_trace
+++ test t = t
+++ test '' = t
+++ test t = t
+++ set -x
+++ mkdir -p '/d/a/1/s/t/trash directory.t5516-fetch-push/prereq-test-dir'
+++ cd '/d/a/1/s/t/trash directory.t5516-fetch-push/prereq-test-dir'
+++ git env--helper --type=bool --default=0 --exit-code GIT_TEST_GETTEXT_POISON
prerequisite C_LOCALE_OUTPUT ok
error: 'grep remote error:.*not our ref.*64ea4c133d59fa98e86a771eda009872d6ab2886$ err' didn't find a match in:
fatal: git upload-pack: not our ref 64ea4c133d59fa98e86afatal: 771eda009872d6abremote error: upload-pack2: not our re886
f 64ea4c133d59fa98e86a771eda009872d6ab2886
error: last command exited with $?=1
-- snap --

It is quite obvious that this `fatal:` line is garbled ;-)

> For detailed explanation please refer to code comments in this commit.
>
> There was a lot of back-and-forth already in vreportf():
> d048a96e (2007-11-09) - 'char msg[256]' is introduced to avoid interleaving
> 389d1767 (2009-03-25) - Buffer size increased to 1024 to avoid truncation
> 625a860c (2009-11-22) - Buffer size increased to 4096 to avoid truncation
> f4c3edc0 (2015-08-11) - Buffer removed to avoid truncation
> b5a9e435 (2017-01-11) - Reverts f4c3edc0 to be able to replace control
>                         chars before sending to stderr
>
> This fix attempts to solve all issues:
> 1) avoid multiple fprintf() interleaving
> 2) avoid truncation
> 3) avoid char interleaving in fprintf() on some platforms
> 4) avoid buffer block interleaving when output is large
> 5) avoid out-of-order messages
> 6) replace control characters in output
>
> Other commits worthy of notice:
> 9ac13ec9 (2006-10-11) - Another attempt to solve interleaving.
>                         This is seemingly related to d048a96e.
> 137a0d0e (2007-11-19) - Addresses out-of-order for display()
> 34df8aba (2009-03-10) - Switches xwrite() to fprintf() in recv_sideband()
>                         to support UTF-8 emulation
> eac14f89 (2012-01-14) - Removes the need for fprintf() for UTF-8 emulation,
>                         so it's safe to use xwrite() again
> 5e5be9e2 (2016-06-28) - recv_sideband() uses xwrite() again

So far, it makes a lot of sense, and is well-researched. Thank you for
being very diligent.

>
> Signed-off-by: Alexandr Miloslavskiy <alexandr.miloslavskiy@syntevo.com>
> ---
>  usage.c | 154 +++++++++++++++++++++++++++++++++++++++++++++++++++++---
>  1 file changed, 148 insertions(+), 6 deletions(-)
>
> diff --git a/usage.c b/usage.c
> index 2fdb20086b..ccdd91a7b9 100644
> --- a/usage.c
> +++ b/usage.c
> @@ -6,17 +6,159 @@
>  #include "git-compat-util.h"
>  #include "cache.h"
>
> +static void replace_control_chars(char* str, size_t size, char replacement)
> +{
> +	size_t i;
> +
> +	for (i = 0; i < size; i++) {
> +    		if (iscntrl(str[i]) && str[i] != '\t' && str[i] != '\n')
> +			str[i] = replacement;
> +	}
> +}

So this is just factored out from `vreportf()`, right?

> +
> +/*
> + * Atomically report (prefix + vsnprintf(err, params) + '\n') to stderr.
> + * Always returns desired buffer size.
> + * Doesn't write to stderr if content didn't fit.
> + *
> + * This function composes everything into a single buffer before
> + * sending to stderr. This is to defeat various non-atomic issues:
> + * 1) If stderr is fully buffered:
> + *    the ordering of stdout and stderr messages could be wrong,
> + *    because stderr output waits for the buffer to become full.
> + * 2) If stderr has any type of buffering:
> + *    buffer has fixed size, which could lead to interleaved buffer
> + *    blocks when two threads/processes write at the same time.
> + * 3) If stderr is not buffered:
> + *    There are two problems, one with atomic fprintf() and another
> + *    for non-atomic fprintf(), and both occur depending on platform
> + *    (see details below). If atomic, this function still writes 3
> + *    parts, which could get interleaved with multiple threads. If
> + *    not atomic, then fprintf() will basically write char-by-char,
> + *    which leads to unreadable char-interleaved writes if two
> + *    processes write to stderr at the same time (threads are OK
> + *    because fprintf() usually locks file in current process). This
> + *    for example happens in t5516 where 'git-upload-pack' detects
> + *    an error, reports it to parent 'git fetch' and both die() at the
> + *    same time.
> + *
> + *    Behaviors, at the moment of writing:
> + *    a) libc - fprintf()-interleaved
> + *       fprintf() enables temporary stream buffering.
> + *       See: buffered_vfprintf()
> + *    b) VC++ - char-interleaved
> + *       fprintf() enables temporary stream buffering, but only if
> + *       stream was not set to no buffering. This has no effect,
> + *       because stderr is not buffered by default, and git takes
> + *       an extra step to ensure that in swap_osfhnd().
> + *       See: _iob[_IOB_ENTRIES],
> + *            __acrt_stdio_temporary_buffering_guard,
> + *            has_any_buffer()
> + *    c) MinGW - char-interleaved (console), full buffering (file)
> + *       fprintf() obeys stderr buffering. But it uses old MSVCRT.DLL,
> + *       which eventually calls _flsbuf(), which enables buffering unless
> + *       isatty(stderr) or buffering is disabled. Buffering is not disabled
> + *       by default for stderr. Therefore, buffering is enabled for
> + *       file-redirected stderr.
> + *       See: __mingw_vfprintf(),
> + *            __pformat_wcputs(),
> + *            _fputc_nolock(),
> + *            _flsbuf(),
> + *            _iob[_IOB_ENTRIES]
> + * 4) If stderr is line buffered: MinGW/VC++ will enable full
> + *    buffering instead. See MSDN setvbuf().
> + */
> +static size_t vreportf_buf(char *buf, size_t buf_size, const char *prefix, const char *err, va_list params)
> +{
> +	int printf_ret = 0;
> +	size_t prefix_size = 0;
> +	size_t total_size = 0;
> +
> +	/*
> +	 * NOTE: Can't use strbuf functions here, because it can be called when
> +	 * malloc() is no longer possible, and strbuf will recurse die().
> +	 */
> +
> +	/* Prefix */
> +	prefix_size = strlen(prefix);
> +	if (total_size + prefix_size <= buf_size)
> +		memcpy(buf + total_size, prefix, prefix_size);
> +
> +	total_size += prefix_size;
> +
> +	/* Formatted message */
> +	if (total_size <= buf_size)
> +		printf_ret = vsnprintf(buf + total_size, buf_size - total_size, err, params);
> +	else
> +		printf_ret = vsnprintf(NULL, 0, err, params);
> +
> +	if (printf_ret < 0)
> +		BUG("your vsnprintf is broken (returned %d)", printf_ret);
> +
> +	/*
> +	 * vsnprintf() returns _desired_ size (without terminating null).
> +	 * If vsnprintf() was truncated that will be seen when appending '\n'.
> +	 */
> +	total_size += printf_ret;
> +
> +	/* Trailing \n */
> +	if (total_size + 1 <= buf_size)
> +		buf[total_size] = '\n';
> +
> +	total_size += 1;
> +
> +	/* Send the buffer, if content fits */
> +	if (total_size <= buf_size) {
> +	    replace_control_chars(buf, total_size, '?');
> +	    fwrite(buf, total_size, 1, stderr);
> +	}
> +
> +	return total_size;
> +}
> +
>  void vreportf(const char *prefix, const char *err, va_list params)
>  {
> +	size_t res = 0;
> +	char *buf = NULL;
> +	size_t buf_size = 0;
> +
> +	/*
> +	 * NOTE: This can be called from failed xmalloc(). Any malloc() can
> +	 * fail now. Let's try to report with a fixed size stack based buffer.
> +	 * Also, most messages should fit, and this path is faster.
> +	 */
>  	char msg[4096];
> -	char *p;
> +	res = vreportf_buf(msg, sizeof(msg), prefix, err, params);
> +	if (res <= sizeof(msg)) {
> +		/* Success */
> +		return;
> +	}
>
> -	vsnprintf(msg, sizeof(msg), err, params);
> -	for (p = msg; *p; p++) {
> -		if (iscntrl(*p) && *p != '\t' && *p != '\n')
> -			*p = '?';
> +	/*
> +	 * Try to allocate a suitable sized malloc(), if possible.
> +	 * NOTE: Do not use xmalloc(), because on failure it will call
> +	 * die() or warning() and lead to recursion.
> +	 */
> +	buf_size = res;
> +	buf = malloc(buf_size);

Why not `alloca()`?

And to take a step back, I think that previous rounds of patches trying
to essentially address the same problem made the case that it is okay to
cut off insanely-long messages, so I am not sure we would want to open
that can of worms again...

> +	if (buf) {
> +		res = vreportf_buf(buf, buf_size, prefix, err, params);
> +		FREE_AND_NULL(buf);
> +
> +		if (res <= buf_size) {
> +			/* Success */
> +			return;
> +		}
>  	}
> -	fprintf(stderr, "%s%s\n", prefix, msg);
> +
> +	/*
> +	 * When everything fails, report in parts.
> +	 * This can have all problems prevented by vreportf_buf().
> +	 */
> +	fprintf(stderr, "vreportf: not enough memory (tried to allocate %lu bytes)\n", (unsigned long)buf_size);
> +	fputs(prefix, stderr);
> +	vfprintf(stderr, err, params);
> +	fputc('\n', stderr);

Quite honestly, I would love to avoid that amount of complexity,
certainly in a part of the code that we would like to have rock solid
because it is usually exercised when things go very, very wrong and we
need to provide the user who is bitten by it enough information to take
to the Git contributors to figure out the root cause(s).

So let's take another step back and look at the original `vreportf()`:

	void vreportf(const char *prefix, const char *err, va_list params)
	{
		char msg[4096];
		char *p;

		vsnprintf(msg, sizeof(msg), err, params);
		for (p = msg; *p; p++) {
			if (iscntrl(*p) && *p != '\t' && *p != '\n')
				*p = '?';
		}
		fprintf(stderr, "%s%s\n", prefix, msg);
	}

Is the problem that causes those failures with VS the fact that
`fprintf(stderr, ...)` might be interleaved with the output of another
process that _also_ wants to write to `stderr`? I assume that this _is_
the problem.

Further, I guess that the problem is compounded by the fact that we
usually run the tests in a Git Bash on Windows, i.e. in a MinTTY that
emulates a console (there _is_ work under way to support the newly
introduces ptys, but that work is far from done), so the standard error
file handle might behave in unexpected ways in that scenario.

But I do wonder whether replacing that `fprintf()` by a `write()` would
work better. After all, we could write the `prefix` into the `msg`
already:

		size_t off = strlcpy(msg, prefix, sizeof(msg));
		int ret = vsnprintf(msg + off, sizeof(msg) - off, err, params);
		[...]
		if (ret > 0)
			write(2, msg, off + ret);

Would that also work around the problem?

Ciao,
Dscho

>  }
>
>  static NORETURN void usage_builtin(const char *err, va_list params)
> --
> gitgitgadget
>

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Alexandr Miloslavskiy]

> Maybe this could do with an example?

I myself observed results like this when running t5516:
------
fatal: git fatal: remote errouploar: upload-pack: not our ref 
64ea4c133d59fa98e86a771eda009872d6ab2886d-pack: not o
ur ref 64ea4c133d59fa98e86a771eda009872d6ab2886
------

Do you want me to add this garbled string to commit message?

>> +static void replace_control_chars(char* str, size_t size, char replacement)

> So this is just factored out from `vreportf()`, right?

Yes.

>> +	buf = malloc(buf_size);

> Why not `alloca()`?

Allocating large chunks on stack is usually not recommended. There is a 
funny test "init allows insanely long --template" in t0001 which 
demonstrates that sometimes vreportf() can attempt to print very long 
strings. Crashing due to stack overflow doesn't sound like a good thing.

> And to take a step back, I think that previous rounds of patches trying
> to essentially address the same problem made the case that it is okay to
> cut off insanely-long messages, so I am not sure we would want to open
> that can of worms again...

I draw a different conclusion here. Each author thought that "1024 must 
definitely be enough!" but then discovered that it's not enough again, 
for example due to long "usage" output. At some point, f4c3edc0 even 
tried to remove all limits after a chain of limits that were too small. 
So I would say that this is still a problem.

> Quite honestly, I would love to avoid that amount of complexity,
> certainly in a part of the code that we would like to have rock solid
> because it is usually exercised when things go very, very wrong and we
> need to provide the user who is bitten by it enough information to take
> to the Git contributors to figure out the root cause(s).

It's a choice between simpler code and trying to account for everything 
that could happen. I think we'd rather have more complex code that 
handles more cases, exactly to try and deliver output to user no matter 
what.

> Is the problem that causes those failures with VS the fact that
> `fprintf(stderr, ...)` might be interleaved with the output of another
> process that _also_ wants to write to `stderr`? I assume that this _is_
> the problem.

This is where I started. But if you look at comment in vreportf_buf, 
there are more problems, such as interleaving blocks of larger messages, 
which could happen on any platform. I tried to make it work in most 
cases possible.

> Further, I guess that the problem is compounded by the fact that we
> usually run the tests in a Git Bash on Windows, i.e. in a MinTTY that
> emulates a console (there _is_ work under way to support the newly
> introduces ptys, but that work is far from done), so the standard error
> file handle might behave in unexpected ways in that scenario.

To my knowledge, this is not related. t5516 failures are because git 
explicitly wants stderr to be unbuffered. VC++ and MinGW runtimes take 
that literally. fprintf() outputs char-by-char, and all of that results 
in char-interleaving.

> But I do wonder whether replacing that `fprintf()` by a `write()` would
> work better. After all, we could write the `prefix` into the `msg`
> already:
> 
> 	size_t off = strlcpy(msg, prefix, sizeof(msg));
> 	int ret = vsnprintf(msg + off, sizeof(msg) - off, err, params);
> 	[...]
> 	if (ret > 0)
> 		write(2, msg, off + ret);
> 
> Would that also work around the problem?

You forgot to add '\'n. But yes, that would solve many problems, except 
truncation to 4096. Then I would expect a patch to increase buffer size 
to 8192 in the next couple years. And if you also try to solve 
truncation, it will get you very close to my code.

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Johannes Schindelin]

Hi Alex,

On Fri, 25 Oct 2019, Alexandr Miloslavskiy wrote:

> > Maybe this could do with an example?
>
> I myself observed results like this when running t5516:
> ------
> fatal: git fatal: remote errouploar: upload-pack: not our ref
> 64ea4c133d59fa98e86a771eda009872d6ab2886d-pack: not o
> ur ref 64ea4c133d59fa98e86a771eda009872d6ab2886
> ------
>
> Do you want me to add this garbled string to commit message?

I think that would make things a lot more relatable ;-)

My example is even worse (read: more convincing), though:

fatal: git uploadfata-lp: raemcokte :error:  upload-pnot our arcef k6: n4ot our ea4cr1e3f 36d45ea94fca1398e86a771eda009872d63adb28598f6a9
8e86a771eda009872d6ab2886

So maybe you want to use that?

> > > +	buf = malloc(buf_size);
>
> > Why not `alloca()`?
>
> Allocating large chunks on stack is usually not recommended. There is a funny
> test "init allows insanely long --template" in t0001 which demonstrates that
> sometimes vreportf() can attempt to print very long strings. Crashing due to
> stack overflow doesn't sound like a good thing.

Indeed. A clipped message will be a lot more helpful in such a scenario.

> > And to take a step back, I think that previous rounds of patches trying
> > to essentially address the same problem made the case that it is okay to
> > cut off insanely-long messages, so I am not sure we would want to open
> > that can of worms again...
>
> I draw a different conclusion here. Each author thought that "1024 must
> definitely be enough!" but then discovered that it's not enough again, for
> example due to long "usage" output. At some point, f4c3edc0 even tried to
> remove all limits after a chain of limits that were too small. So I would say
> that this is still a problem.

The most important aspect of `vreportf()` is, at least as far as I am
concerned, to "get the message out".

As such, no, I don't want it to fail, neither due to `alloca()` nor due
to `malloc()`. I'd rather have it produce a cut-off message that at
least shows the first 4095 bytes of the message.

> > Quite honestly, I would love to avoid that amount of complexity,
> > certainly in a part of the code that we would like to have rock
> > solid because it is usually exercised when things go very, very
> > wrong and we need to provide the user who is bitten by it enough
> > information to take to the Git contributors to figure out the root
> > cause(s).
>
> It's a choice between simpler code and trying to account for
> everything that could happen. I think we'd rather have more complex
> code that handles more cases, exactly to try and deliver output to
> user no matter what.

Complex code usually has more bugs than simple code. I don't want
`vreportf()` to have potential bugs that we don't know about.

> > Is the problem that causes those failures with VS the fact that
> > `fprintf(stderr, ...)` might be interleaved with the output of
> > another process that _also_ wants to write to `stderr`? I assume
> > that this _is_ the problem.
>
> This is where I started. But if you look at comment in vreportf_buf,
> there are more problems, such as interleaving blocks of larger
> messages, which could happen on any platform. I tried to make it work
> in most cases possible.

Again, I don't think that it is wise to try to make this work for
arbitrary sizes of error messages.

At some stage, the scrollback of the console won't be large enough to
fix that message!

So I think it is very sane to say that at some point, enough is enough.

Four thousand bytes seems a really long message, anyway.

> > Further, I guess that the problem is compounded by the fact that we
> > usually run the tests in a Git Bash on Windows, i.e. in a MinTTY
> > that emulates a console (there _is_ work under way to support the
> > newly introduces ptys, but that work is far from done), so the
> > standard error file handle might behave in unexpected ways in that
> > scenario.
>
> To my knowledge, this is not related. t5516 failures are because git
> explicitly wants stderr to be unbuffered. VC++ and MinGW runtimes take
> that literally. fprintf() outputs char-by-char, and all of that
> results in char-interleaving.

Yes, as my example above demonstrates. (Ugh!)

> > But I do wonder whether replacing that `fprintf()` by a `write()` would
> > work better. After all, we could write the `prefix` into the `msg`
> > already:
> >
> >  size_t off = strlcpy(msg, prefix, sizeof(msg));
> >  int ret = vsnprintf(msg + off, sizeof(msg) - off, err, params);
> >  [...]
> >  if (ret > 0)
> >   write(2, msg, off + ret);
> >
> > Would that also work around the problem?
>
> You forgot to add '\'n. But yes, that would solve many problems,


... and indeed, I verified that this patch fixes the problem:

-- snip --
diff --git a/usage.c b/usage.c
index 2fdb20086bd..7f5bdfb0f40 100644
--- a/usage.c
+++ b/usage.c
@@ -10,13 +10,16 @@ void vreportf(const char *prefix, const char *err, va_list params)
 {
 	char msg[4096];
 	char *p;
-
-	vsnprintf(msg, sizeof(msg), err, params);
+	size_t off = strlcpy(msg, prefix, sizeof(msg));
+	int ret = vsnprintf(msg + off, sizeof(msg) - off, err, params);
 	for (p = msg; *p; p++) {
 		if (iscntrl(*p) && *p != '\t' && *p != '\n')
 			*p = '?';
 	}
-	fprintf(stderr, "%s%s\n", prefix, msg);
+	if (ret > 0) {
+		msg[off + ret] = '\n'; /* we no longer need a NUL */
+		write_in_full(2, msg, off + ret + 1);
+	}
 }

 static NORETURN void usage_builtin(const char *err, va_list params)
-- snap --

> except truncation to 4096. Then I would expect a patch to increase
> buffer size to 8192 in the next couple years. And if you also try to
> solve truncation, it will get you very close to my code.

My point is: I don't want to "fix" truncation. I actually think of it as
a feature. An error message that is longer than the average news article
I read is too long, period.

BTW I have a couple more tidbits to add to the commit message, if you
would be so kind as to pick them up: I know _which_ two processes battle
for `stderr`. I instrumented the code slightly, and this is what I got:

-- snip --
$ GIT_TRACE=1 GIT_TEST_PROTOCOL_VERSION= ../git.exe --exec-path=$PWD/..  -C trash\ directory.t5516-fetch-push/shallow2/  fetch ../testrepo/.git 64ea4c133d59fa98e86a771eda009872d6ab2886
14:55:55.360382 exec-cmd.c:238          trace: resolved executable dir: C:/git-sdk-64/usr/src/vs2017-test
14:55:55.362379 exec-cmd.c:54           RUNTIME_PREFIX requested, but prefix computation failed.  Using static fallback '/mingw64'.
14:55:55.387189 git.c:444               trace: built-in (pid=21620): git fetch ../testrepo/.git 64ea4c133d59fa98e86a771eda009872d6ab2886
14:55:55.392644 run-command.c:663       trace: run_command: unset GIT_PREFIX; 'git-upload-pack '\''../testrepo/.git'\'''
14:55:55.659992 exec-cmd.c:238          trace: resolved executable dir: C:/git-sdk-64/usr/src/vs2017-test
14:55:55.661762 exec-cmd.c:54           RUNTIME_PREFIX requested, but prefix computation failed.  Using static fallback '/mingw64'.
14:55:55.662759 git.c:444               trace: built-in (pid=27452): git upload-pack ../testrepo/.git
14:55:55.681188 run-command.c:663       trace: run_command: git rev-list --stdin
fatal: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886
fatal: remote error (pid=21620): upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886
-- snap --

As you can see, the two error messages stem from the `git fetch` process
(with the prefix "remote error:") and the process it spawned, `git upload-pack`.

BTW if you pick up the indicated patch and the tidbits for the commit
message and then send out a new iteration via GitGitGadget, I would not
mind being co-author at all ;-)

Ciao,
Dscho

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Alexandr Miloslavskiy]

On 25.10.2019 16:02, Johannes Schindelin wrote:
> My example is even worse (read: more convincing), though:
> 
> fatal: git uploadfata-lp: raemcokte :error:  upload-pnot our arcef k6: n4ot our ea4cr1e3f 36d45ea94fca1398e86a771eda009872d63adb28598f6a9
> 8e86a771eda009872d6ab2886
> 
> So maybe you want to use that?

OK.

> Again, I don't think that it is wise to try to make this work for
> arbitrary sizes of error messages.

 > My point is: I don't want to "fix" truncation. I actually think of it
 > as a feature

It would be helpful to hear opinions from someone else, before the patch 
is reworked significantly.

> I know _which_ two processes battle for `stderr`.

I think I said the same in code comment, bullet 3, near t5516?

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Johannes Schindelin]

Hi Alex,

On Fri, 25 Oct 2019, Alexandr Miloslavskiy wrote:

> On 25.10.2019 16:02, Johannes Schindelin wrote:
> > My example is even worse (read: more convincing), though:
> >
> > fatal: git uploadfata-lp: raemcokte :error:  upload-pnot our arcef k6: n4ot
> > our ea4cr1e3f 36d45ea94fca1398e86a771eda009872d63adb28598f6a9
> > 8e86a771eda009872d6ab2886
> >
> > So maybe you want to use that?
>
> OK.
>
> > Again, I don't think that it is wise to try to make this work for
> > arbitrary sizes of error messages.
>
> > My point is: I don't want to "fix" truncation. I actually think of it
> > as a feature
>
> It would be helpful to hear opinions from someone else, before the patch is
> reworked significantly.

If you must wait, well, then you must.

The commits you found seem to suggest already that there is support for
clipping the message, but hey, what do I know, maybe the mood changed
over the years.

Since I have to re-run CI/PR builds regularly that failed due to t5516,
I will be very tempted _not_ to wait, though.

> > I know _which_ two processes battle for `stderr`.
>
> I think I said the same in code comment, bullet 3, near t5516?

Probably.

A code comment about a test case that is not in the very vicinity of
said comment is _prone_ to get stale.

In other words: this information does not belong into a code comment. It
belongs into the commit message.

If you needed any indication that this is true: I would not have missed
this important piece if it had been in the commit message (instead of
the code with whose added complexity I disagree).

Ciao,
Dscho

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Jeff King]

On Fri, Oct 25, 2019 at 04:02:36PM +0200, Johannes Schindelin wrote:

> ... and indeed, I verified that this patch fixes the problem:
> 
> -- snip --
> diff --git a/usage.c b/usage.c
> index 2fdb20086bd..7f5bdfb0f40 100644
> --- a/usage.c
> +++ b/usage.c
> @@ -10,13 +10,16 @@ void vreportf(const char *prefix, const char *err, va_list params)
>  {
>  	char msg[4096];
>  	char *p;
> -
> -	vsnprintf(msg, sizeof(msg), err, params);
> +	size_t off = strlcpy(msg, prefix, sizeof(msg));
> +	int ret = vsnprintf(msg + off, sizeof(msg) - off, err, params);
>  	for (p = msg; *p; p++) {
>  		if (iscntrl(*p) && *p != '\t' && *p != '\n')
>  			*p = '?';
>  	}
> -	fprintf(stderr, "%s%s\n", prefix, msg);
> +	if (ret > 0) {
> +		msg[off + ret] = '\n'; /* we no longer need a NUL */
> +		write_in_full(2, msg, off + ret + 1);
> +	}
>  }

Heh. This is quite similar to what I posted in:

  https://public-inbox.org/git/20190828145412.GB14432@sigill.intra.peff.net/

though I missed the cleverness with "we no longer need a NUL" to get an
extra byte. ;)

> > except truncation to 4096. Then I would expect a patch to increase
> > buffer size to 8192 in the next couple years. And if you also try to
> > solve truncation, it will get you very close to my code.
> 
> My point is: I don't want to "fix" truncation. I actually think of it as
> a feature. An error message that is longer than the average news article
> I read is too long, period.

Yeah. As the person responsible for many of the "avoid truncation" works
referenced in the original patch, I have come to the conclusion that it
is not worth the complexity. Even when we do manage to produce a
gigantic error message correctly, it's generally not very readable.

That's basically what I came here to say, and I was pleased to find that
you had already argued for it quite well. So I'll just add my support
for the direction you've taken the conversation.

I _do_ wish we could do the truncation more intelligently. I'd much
rather see:

  error: unable to open 'absurdly-long-file-name...': permission denied

than:

  error: unable to open 'absurdly-long-file-name-that-goes-on-forever-and-ev

But I don't think it's possible without reimplementing snprintf
ourselves.

-Peff

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Alexandr Miloslavskiy]

On 26.10.2019 0:11, Jeff King wrote:
> Yeah. As the person responsible for many of the "avoid truncation" works
> referenced in the original patch, I have come to the conclusion that it
> is not worth the complexity. Even when we do manage to produce a
> gigantic error message correctly, it's generally not very readable.
> 
> That's basically what I came here to say, and I was pleased to find that
> you had already argued for it quite well. So I'll just add my support
> for the direction you've taken the conversation.


Thanks! Truncation, then :)

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Johannes Schindelin]

Hi Peff,

On Fri, 25 Oct 2019, Jeff King wrote:

> On Fri, Oct 25, 2019 at 04:02:36PM +0200, Johannes Schindelin wrote:
>
> > ... and indeed, I verified that this patch fixes the problem:
> >
> > -- snip --
> > diff --git a/usage.c b/usage.c
> > index 2fdb20086bd..7f5bdfb0f40 100644
> > --- a/usage.c
> > +++ b/usage.c
> > @@ -10,13 +10,16 @@ void vreportf(const char *prefix, const char *err, va_list params)
> >  {
> >  	char msg[4096];
> >  	char *p;
> > -
> > -	vsnprintf(msg, sizeof(msg), err, params);
> > +	size_t off = strlcpy(msg, prefix, sizeof(msg));
> > +	int ret = vsnprintf(msg + off, sizeof(msg) - off, err, params);
> >  	for (p = msg; *p; p++) {
> >  		if (iscntrl(*p) && *p != '\t' && *p != '\n')
> >  			*p = '?';
> >  	}
> > -	fprintf(stderr, "%s%s\n", prefix, msg);
> > +	if (ret > 0) {
> > +		msg[off + ret] = '\n'; /* we no longer need a NUL */
> > +		write_in_full(2, msg, off + ret + 1);
> > +	}
> >  }
>
> Heh. This is quite similar to what I posted in:
>
>   https://public-inbox.org/git/20190828145412.GB14432@sigill.intra.peff.net/
>
> though I missed the cleverness with "we no longer need a NUL" to get an
> extra byte. ;)

:-)

I also use `xwrite()` instead of `write()`...

> > > except truncation to 4096. Then I would expect a patch to increase
> > > buffer size to 8192 in the next couple years. And if you also try to
> > > solve truncation, it will get you very close to my code.
> >
> > My point is: I don't want to "fix" truncation. I actually think of it as
> > a feature. An error message that is longer than the average news article
> > I read is too long, period.
>
> Yeah. As the person responsible for many of the "avoid truncation" works
> referenced in the original patch, I have come to the conclusion that it
> is not worth the complexity. Even when we do manage to produce a
> gigantic error message correctly, it's generally not very readable.
>
> That's basically what I came here to say, and I was pleased to find that
> you had already argued for it quite well. So I'll just add my support
> for the direction you've taken the conversation.

Thank you for affirming. I have to admit that I would have loved for my
argument to work on its own, and not require the additional force of a
second opinion. In my mind, there is little opinion required here.

> I _do_ wish we could do the truncation more intelligently. I'd much
> rather see:
>
>   error: unable to open 'absurdly-long-file-name...': permission denied
>
> than:
>
>   error: unable to open 'absurdly-long-file-name-that-goes-on-forever-and-ev
>
> But I don't think it's possible without reimplementing snprintf
> ourselves.

Indeed. I _did_ start to implement `strbuf_vaddf()` from scratch, over
ten years ago:

https://public-inbox.org/git/alpine.LSU.1.00.0803061727120.3941@racer.site/

I am not sure whether we want to resurrect it, it would need to grow
support _at least_ for `%PRIuMAX` and `%PRIdMAX`, but that should not be
hard.

Back to the issue at hand: I did open a GitGitGadget PR with my proposed
change, in the hopes that I could somehow fast-track this fix into the
CI/PR builds over at https://github.com/gitgitgadget/git, but there are
problems: it seems that now there is an at least occasional broken pipe
in the same test when run on macOS.

There _also_ seems to be something spooky going on in t3510.12 and .13,
where the expected output differs from the actual output only by a
re-ordering of the lines:

-- snip --
[...]
+++ diff -u expect advice
--- expect	2019-10-25 22:17:44.982884700 +0000
+++ advice	2019-10-25 22:17:45.278884500 +0000
@@ -1,3 +1,3 @@
 error: cherry-pick is already in progress
-hint: try "git cherry-pick (--continue | --skip | --abort | --quit)"
 fatal: cherry-pick failed
+hint: try "git cherry-pick (--continue | --skip | --abort | --quit)"
-- snap --

For details, see:
https://dev.azure.com/gitgitgadget/git/_build/results?buildId=19336&view=ms.vss-test-web.build-test-results-tab
and
https://dev.azure.com/Git-for-Windows/git/_build/results?buildId=44549&view=ms.vss-test-web.build-test-results-tab
(You need to click on a test case title to open the logs, then inspect
the Attachments to get to the full trace)

So much as I would love to see the flakiness of t5516 be fixed as soon
as possible, I fear we will have to look at the underlying issue a bit
closer: there are two processes writing to `stderr` concurrently. I
don't know whether there would be a good way for the `stderr` of the
`upload-pack` process to be consumed by the `fetch` process, and to be
printed by the latter.

Ciao,
Dscho

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Jeff King]

On Sat, Oct 26, 2019 at 10:56:45PM +0200, Johannes Schindelin wrote:

> Back to the issue at hand: I did open a GitGitGadget PR with my proposed
> change, in the hopes that I could somehow fast-track this fix into the
> CI/PR builds over at https://github.com/gitgitgadget/git, but there are
> problems: it seems that now there is an at least occasional broken pipe
> in the same test when run on macOS.

Yes, I think that's another issue in the same test. There's more
discussion further down in the thread I linked earlier, starting here:

  https://public-inbox.org/git/20190829143805.GB1746@sigill.intra.peff.net/

and I think Gábor's solution here:

  https://public-inbox.org/git/20190830121005.GI8571@szeder.dev/

is the right direction (and note that this _isn't_ just a test artifact,
but a bug that occasionally hits real-world cases, too).

> There _also_ seems to be something spooky going on in t3510.12 and .13,
> where the expected output differs from the actual output only by a
> re-ordering of the lines:
> 
> -- snip --
> [...]
> +++ diff -u expect advice
> --- expect	2019-10-25 22:17:44.982884700 +0000
> +++ advice	2019-10-25 22:17:45.278884500 +0000
> @@ -1,3 +1,3 @@
>  error: cherry-pick is already in progress
> -hint: try "git cherry-pick (--continue | --skip | --abort | --quit)"
>  fatal: cherry-pick failed
> +hint: try "git cherry-pick (--continue | --skip | --abort | --quit)"
> -- snap --

Hrm. I'd have thought those are both coming from the same process. Which
implies that we're not fflushing stderr before calling write(2). But
your patch seems to do so...

<scratches head> Aha. I think you force-pushed up as I am typing this.
:) So I think that is indeed the solution.

> So much as I would love to see the flakiness of t5516 be fixed as soon
> as possible, I fear we will have to look at the underlying issue a bit
> closer: there are two processes writing to `stderr` concurrently. I
> don't know whether there would be a good way for the `stderr` of the
> `upload-pack` process to be consumed by the `fetch` process, and to be
> printed by the latter.

The worst part is that this message already _is_ consumed by fetch: we
send it twice, once over the sideband, and once directly to stderr. In
most cases the stderr version is lost, but some server providers might
be collecting it. I wouldn't mind seeing the direct-to-stderr one
dropped. There's some more discussion in (from the same thread linked
earlier):

  https://public-inbox.org/git/20190828145412.GB14432@sigill.intra.peff.net/

-Peff

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Johannes Schindelin]

Hi Peff,

On Sat, 26 Oct 2019, Johannes Schindelin wrote:

> [...] I did open a GitGitGadget PR with my proposed change,

I should have mentioned the URL:

	https://github.com/gitgitgadget/git/pull/428

FWIW, in the meantime I managed to address below-mentioned breakages
(apart from the broken pipe problem that is discussed over here:
https://public-inbox.org/git/20190828161552.GE8571@szeder.dev/) and the
build is green.

Alex asked to be given time to brush his patch up on Monday, so I am
holding off sending my version (for now...).

Ciao,
Dscho

> in the hopes that I could somehow fast-track this fix into the
> CI/PR builds over at https://github.com/gitgitgadget/git, but there are
> problems: it seems that now there is an at least occasional broken pipe
> in the same test when run on macOS.
>
> There _also_ seems to be something spooky going on in t3510.12 and .13,
> where the expected output differs from the actual output only by a
> re-ordering of the lines:
>
> -- snip --
> [...]
> +++ diff -u expect advice
> --- expect	2019-10-25 22:17:44.982884700 +0000
> +++ advice	2019-10-25 22:17:45.278884500 +0000
> @@ -1,3 +1,3 @@
>  error: cherry-pick is already in progress
> -hint: try "git cherry-pick (--continue | --skip | --abort | --quit)"
>  fatal: cherry-pick failed
> +hint: try "git cherry-pick (--continue | --skip | --abort | --quit)"
> -- snap --
>
> For details, see:
> https://dev.azure.com/gitgitgadget/git/_build/results?buildId=19336&view=ms.vss-test-web.build-test-results-tab
> and
> https://dev.azure.com/Git-for-Windows/git/_build/results?buildId=44549&view=ms.vss-test-web.build-test-results-tab
> (You need to click on a test case title to open the logs, then inspect
> the Attachments to get to the full trace)
>
> So much as I would love to see the flakiness of t5516 be fixed as soon
> as possible, I fear we will have to look at the underlying issue a bit
> closer: there are two processes writing to `stderr` concurrently. I
> don't know whether there would be a good way for the `stderr` of the
> `upload-pack` process to be consumed by the `fetch` process, and to be
> printed by the latter.
>
> Ciao,
> Dscho
>

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Johannes Schindelin]

Sorry, me again,

On Sat, 26 Oct 2019, Johannes Schindelin wrote:

> On Sat, 26 Oct 2019, Johannes Schindelin wrote:
>
> > [...] I did open a GitGitGadget PR with my proposed change,
>
> I should have mentioned the URL:
>
> 	https://github.com/gitgitgadget/git/pull/428

I should have mentioned that I also opened
https://github.com/git-for-windows/git/pull/2373 with the same branch,
which exercizes the Visual Studio build, too, so it is a bit more
informative than the GitGitGadget PR (which only runs the regular GCC
build on Windows which, as per Alex' analysis, is not affected by this
problem).

Ciao,
Dscho

> FWIW, in the meantime I managed to address below-mentioned breakages
> (apart from the broken pipe problem that is discussed over here:
> https://public-inbox.org/git/20190828161552.GE8571@szeder.dev/) and the
> build is green.
>
> Alex asked to be given time to brush his patch up on Monday, so I am
> holding off sending my version (for now...).
>
> Ciao,
> Dscho
>
> > in the hopes that I could somehow fast-track this fix into the
> > CI/PR builds over at https://github.com/gitgitgadget/git, but there are
> > problems: it seems that now there is an at least occasional broken pipe
> > in the same test when run on macOS.
> >
> > There _also_ seems to be something spooky going on in t3510.12 and .13,
> > where the expected output differs from the actual output only by a
> > re-ordering of the lines:
> >
> > -- snip --
> > [...]
> > +++ diff -u expect advice
> > --- expect	2019-10-25 22:17:44.982884700 +0000
> > +++ advice	2019-10-25 22:17:45.278884500 +0000
> > @@ -1,3 +1,3 @@
> >  error: cherry-pick is already in progress
> > -hint: try "git cherry-pick (--continue | --skip | --abort | --quit)"
> >  fatal: cherry-pick failed
> > +hint: try "git cherry-pick (--continue | --skip | --abort | --quit)"
> > -- snap --
> >
> > For details, see:
> > https://dev.azure.com/gitgitgadget/git/_build/results?buildId=19336&view=ms.vss-test-web.build-test-results-tab
> > and
> > https://dev.azure.com/Git-for-Windows/git/_build/results?buildId=44549&view=ms.vss-test-web.build-test-results-tab
> > (You need to click on a test case title to open the logs, then inspect
> > the Attachments to get to the full trace)
> >
> > So much as I would love to see the flakiness of t5516 be fixed as soon
> > as possible, I fear we will have to look at the underlying issue a bit
> > closer: there are two processes writing to `stderr` concurrently. I
> > don't know whether there would be a good way for the `stderr` of the
> > `upload-pack` process to be consumed by the `fetch` process, and to be
> > printed by the latter.
> >
> > Ciao,
> > Dscho
> >
>

Re: [PATCH v2 1/1] vreportf: Fix interleaving issues, remove 4096 limitation

[Johannes Schindelin]

[-- Attachment #1: Type: text/plain, Size: 3122 bytes --]

Hi Peff,

On Sat, 26 Oct 2019, Jeff King wrote:

> On Sat, Oct 26, 2019 at 10:56:45PM +0200, Johannes Schindelin wrote:
>
> > Back to the issue at hand: I did open a GitGitGadget PR with my proposed
> > change, in the hopes that I could somehow fast-track this fix into the
> > CI/PR builds over at https://github.com/gitgitgadget/git, but there are
> > problems: it seems that now there is an at least occasional broken pipe
> > in the same test when run on macOS.
>
> Yes, I think that's another issue in the same test. There's more
> discussion further down in the thread I linked earlier, starting here:
>
>   https://public-inbox.org/git/20190829143805.GB1746@sigill.intra.peff.net/
>
> and I think Gábor's solution here:
>
>   https://public-inbox.org/git/20190830121005.GI8571@szeder.dev/
>
> is the right direction (and note that this _isn't_ just a test artifact,
> but a bug that occasionally hits real-world cases, too).

That sounds good! I guess I should continue _that_ thread.

> > There _also_ seems to be something spooky going on in t3510.12 and .13,
> > where the expected output differs from the actual output only by a
> > re-ordering of the lines:
> >
> > -- snip --
> > [...]
> > +++ diff -u expect advice
> > --- expect	2019-10-25 22:17:44.982884700 +0000
> > +++ advice	2019-10-25 22:17:45.278884500 +0000
> > @@ -1,3 +1,3 @@
> >  error: cherry-pick is already in progress
> > -hint: try "git cherry-pick (--continue | --skip | --abort | --quit)"
> >  fatal: cherry-pick failed
> > +hint: try "git cherry-pick (--continue | --skip | --abort | --quit)"
> > -- snap --
>
> Hrm. I'd have thought those are both coming from the same process. Which
> implies that we're not fflushing stderr before calling write(2). But
> your patch seems to do so...
>
> <scratches head> Aha. I think you force-pushed up as I am typing this.
> :) So I think that is indeed the solution.

Yes, sorry, I had this idea and it worked locally, and I wanted to know
whether it would turn the PR build green.

> > So much as I would love to see the flakiness of t5516 be fixed as soon
> > as possible, I fear we will have to look at the underlying issue a bit
> > closer: there are two processes writing to `stderr` concurrently. I
> > don't know whether there would be a good way for the `stderr` of the
> > `upload-pack` process to be consumed by the `fetch` process, and to be
> > printed by the latter.
>
> The worst part is that this message already _is_ consumed by fetch: we
> send it twice, once over the sideband, and once directly to stderr. In
> most cases the stderr version is lost, but some server providers might
> be collecting it. I wouldn't mind seeing the direct-to-stderr one
> dropped. There's some more discussion in (from the same thread linked
> earlier):
>
>   https://public-inbox.org/git/20190828145412.GB14432@sigill.intra.peff.net/

It is tricky all right.

Full disclosure: I am mainly interested in having lots less failing
builds (which I all re-run manually when I see that a known-flaky test
failed).

Ciao,
Dscho