{"thread":{"id":"57000","subject":"[RFC PATCH] vreportf: ensure sensible ordering of normal and error output","startedAt":"2021-11-30T04:40:30Z","lastAt":"2021-12-02T00:43:57Z","messageCount":17,"participants":["Eric Sunshine","Junio C Hamano","Jeff King","Ævar Arnfjörð Bjarmason"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"442599","messageId":"20211130043946.19987-1-sunshine@sunshineco.com","threadId":"57000","inReplyTo":null,"subject":"[RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Eric Sunshine","fromEmail":"sunshine@sunshineco.com","sentAt":"2021-11-30T04:39:46Z","receivedAt":"2021-11-30T04:40:30Z","isPatch":true,"sender":{"key":"sunshine@sunshineco.com","avatar":"https://avatars.githubusercontent.com/u/163641?v=4"},"body":"The order in which the stdout and stderr streams are flushed is not\nguaranteed to be the same across platforms or `libc` implementations.\nThis lack of determinism can lead to anomalous and potentially confusing\noutput if normal (stdout) output is flushed after error (stderr) output.\nFor instance, the following output which clearly indicates a failure due\nto a fatal error:\n\n % git worktree add ../foo bar\n Preparing worktree (checking out 'bar')\n fatal: 'bar' is already checked out at '.../wherever'\n\nhas been reported[1] on Microsoft Windows to appear as:\n\n % git worktree add ../foo bar\n fatal: 'bar' is already checked out at '.../wherever'\n Preparing worktree (checking out 'bar')\n\nwhich may confuse the reader into thinking that the command somehow\nrecovered and ran to completion despite the error.\n\nRather than attempting to address this issue on a case by case basis,\naddress it by making vreportf() -- which is the heart of error-reporting\nfunctions die(), error(), warn(), etc. -- flush stdout before emitting\nthe error message to stderr.\n\n[1]: https://lore.kernel.org/git/CA+34VNLj6VB1kCkA=MfM7TZR+6HgqNi5-UaziAoCXacSVkch4A@mail.gmail.com/T/\n\nSigned-off-by: Eric Sunshine \n---\n\nThis is RFC because I naturally worry about potential fallout from\nmaking a change to such a core function. I can't think of any case that\nit wouldn't be advantageous to flush stdout before stderr, so this\nchange _seems_ safe, however, it may be that I'm just not imaginative\nenough, hence my hesitancy.\n\n usage.c | 1 +\n 1 file changed, 1 insertion(+)\n\ndiff --git a/usage.c b/usage.c\nindex c7d233b0de..0fc7640b25 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -27,6 +27,7 @@ void vreportf(const char *prefix, const char *err, va_list params)\n \t}\n \n \t*(p++) = '\\n'; /* we no longer need a NUL */\n+\tfflush(stdout);\n \tfflush(stderr);\n \twrite_in_full(2, msg, p - msg);\n }\n-- \n2.34.1.75.gabe6bb3905\n\n"},{"id":"442602","messageId":"xmqqtufu2pll.fsf@gitster.g","threadId":"57000","inReplyTo":"20211130043946.19987-1-sunshine@sunshineco.com","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-11-30T05:13:10Z","receivedAt":"2021-11-30T05:13:17Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Eric Sunshine writes:\n\n> This is RFC because I naturally worry about potential fallout from\n> making a change to such a core function. I can't think of any case that\n> it wouldn't be advantageous to flush stdout before stderr, so this\n> change _seems_ safe, however, it may be that I'm just not imaginative\n> enough, hence my hesitancy.\n\nIf stdout and stderr are both going to the same place (e.g. the\nuser's terminal), this would probably is an improvement, but if the\nstandard output is going to a pipe talking to another process, which\nmay care when the output is flushed, this may hurt.\n\nBut as long as the calling code is using stdio, it cannot precisely\ncontrol when the buffered contents are flushed anyway, so as long as\nthe caller has working standard output, this may be OK.\n\nHits from \"git grep -l vreportf\" includes http-backend.c; where is\nits standard output connected, and can it have some unflushed stuff\nin its standard output buffer, I wonder?\n\n> usage.c | 1 +\n> 1 file changed, 1 insertion(+)\n>\n> diff --git a/usage.c b/usage.c\n> index c7d233b0de..0fc7640b25 100644\n> --- a/usage.c\n> +++ b/usage.c\n> @@ -27,6 +27,7 @@ void vreportf(const char *prefix, const char *err, va_list params)\n> \t}\n> \n> \t*(p++) = '\\n'; /* we no longer need a NUL */\n> +\tfflush(stdout);\n> \tfflush(stderr);\n> \twrite_in_full(2, msg, p - msg);\n> }\n"},{"id":"442611","messageId":"YaXPUe9Sz3JBlzYL@coredump.intra.peff.net","threadId":"57000","inReplyTo":"xmqqtufu2pll.fsf@gitster.g","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-30T07:14:25Z","receivedAt":"2021-11-30T07:14:34Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Nov 29, 2021 at 09:13:10PM -0800, Junio C Hamano wrote:\n\n> Eric Sunshine writes:\n> \n> > This is RFC because I naturally worry about potential fallout from\n> > making a change to such a core function. I can't think of any case that\n> > it wouldn't be advantageous to flush stdout before stderr, so this\n> > change _seems_ safe, however, it may be that I'm just not imaginative\n> > enough, hence my hesitancy.\n> \n> If stdout and stderr are both going to the same place (e.g. the\n> user's terminal), this would probably is an improvement, but if the\n> standard output is going to a pipe talking to another process, which\n> may care when the output is flushed, this may hurt.\n> \n> But as long as the calling code is using stdio, it cannot precisely\n> control when the buffered contents are flushed anyway, so as long as\n> the caller has working standard output, this may be OK.\n\nYeah, I think this logic applies to the \"happy\" case. Any caller which\nis depending on the time of flush is already racily buggy.\n\nWhat I wonder about is the error case. What can happen if flushing\nfails? There are two interesting cases I can think of:\n\n - flushing causes an error (which is quite likely, as we may\n vreportf() because of an error on stdout). We should be OK, as we do\n not care about the return value here, nor eventually checking\n ferror(stdout). We may overwrite errno, but at this point in\n vreportf(), we are committed to whatever error we're going to show\n (and obviously the stderr flush below could cause the same issues).\n\n - flushing causes us to block. This implies our stdout is connected to\n a pipe or socket, and the other side is not expecting to read. A\n plausible case here is a client sending us a big input which we find\n to be bogus (maybe index-pack checking an incoming pack). We call\n die() to complain about the input, but the client is still writing.\n In the current code, we'd write out our error and then exit; the\n client would get SIGPIPE or a write() error and abort. But with a\n flush here, we could block writing back to the client, and now we're\n in a deadlock; they are trying to write to us but we are no longer\n reading, and we are blocked trying to get out a little bit of\n irrelevant stdout data.\n\n I _think_ we're probably OK here. The scenario above means that the\n caller is already doing asynchronous I/O via stdio and is subject to\n deadlock. Because the segment of buffer we try to flush here _could_\n have been flushed already under the hood, which would have caused\n the same blocking. A careful caller might be using select() or\n similar to decide when it is OK to write, but I find it highly\n unlikely they'd be using stdio in that case.\n\nOf the two, the deadlock case worries me more, just because it would be\nquiet subtle and racy. As I said, I think we may be OK, but my reasoning\nthere is pretty hand-wavy.\n\n-Peff\n"},{"id":"442612","messageId":"YaXQ/HinYZH1wL7E@coredump.intra.peff.net","threadId":"57000","inReplyTo":"20211130043946.19987-1-sunshine@sunshineco.com","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-30T07:21:32Z","receivedAt":"2021-11-30T07:21:35Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Nov 29, 2021 at 11:39:46PM -0500, Eric Sunshine wrote:\n\n> The order in which the stdout and stderr streams are flushed is not\n> guaranteed to be the same across platforms or `libc` implementations.\n> This lack of determinism can lead to anomalous and potentially confusing\n> output if normal (stdout) output is flushed after error (stderr) output.\n> For instance, the following output which clearly indicates a failure due\n> to a fatal error:\n> \n> % git worktree add ../foo bar\n> Preparing worktree (checking out 'bar')\n> fatal: 'bar' is already checked out at '.../wherever'\n> \n> has been reported[1] on Microsoft Windows to appear as:\n> \n> % git worktree add ../foo bar\n> fatal: 'bar' is already checked out at '.../wherever'\n> Preparing worktree (checking out 'bar')\n> \n> which may confuse the reader into thinking that the command somehow\n> recovered and ran to completion despite the error.\n> \n> Rather than attempting to address this issue on a case by case basis,\n> address it by making vreportf() -- which is the heart of error-reporting\n> functions die(), error(), warn(), etc. -- flush stdout before emitting\n> the error message to stderr.\n\nI left some thoughts on whether this flush is safe elsewhere in the\nthread. But for this particular case, two things occur to me:\n\n - shouldn't status messages like this go to stderr anyway? I know some\n people follow the \"unless it is an error, it should not to go\n stderr\" philosophy. But I think in general our approach in Git is\n more \"if it is the main output of the program, it goes to stdout; if\n it is chatter or progress for the user, it goes to stderr\".\n\n - the reason it works consistently on glibc is that stdout to a\n terminal is line buffered by default, so the \"preparing\" line is\n flushed immediately. If that isn't the case on Windows, should we\n consider calling setlinebuf() preemptively when isatty(1)?\n\n That only covers most cases, of course (both to a terminal, or\n separated stdout/stderr). Even on Linux, if you do:\n\n git worktree add ../foo bar >out 2>&1\n\n you'll get the stderr result before stdout. That implies again to me\n that this kind of message really ought to be part of the stderr\n stream.\n\n-Peff\n"},{"id":"442614","messageId":"YaXRd2YBQR+ifNTE@coredump.intra.peff.net","threadId":"57000","inReplyTo":"YaXPUe9Sz3JBlzYL@coredump.intra.peff.net","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-30T07:23:35Z","receivedAt":"2021-11-30T07:23:37Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Nov 30, 2021 at 02:14:25AM -0500, Jeff King wrote:\n\n> - flushing causes us to block. This implies our stdout is connected to\n> a pipe or socket, and the other side is not expecting to read. A\n> plausible case here is a client sending us a big input which we find\n> to be bogus (maybe index-pack checking an incoming pack). We call\n> die() to complain about the input, but the client is still writing.\n> In the current code, we'd write out our error and then exit; the\n> client would get SIGPIPE or a write() error and abort. But with a\n> flush here, we could block writing back to the client, and now we're\n> in a deadlock; they are trying to write to us but we are no longer\n> reading, and we are blocked trying to get out a little bit of\n> irrelevant stdout data.\n> \n> I _think_ we're probably OK here. The scenario above means that the\n> caller is already doing asynchronous I/O via stdio and is subject to\n> deadlock. Because the segment of buffer we try to flush here _could_\n> have been flushed already under the hood, which would have caused\n> the same blocking. A careful caller might be using select() or\n> similar to decide when it is OK to write, but I find it highly\n> unlikely they'd be using stdio in that case.\n> \n> Of the two, the deadlock case worries me more, just because it would be\n> quiet subtle and racy. As I said, I think we may be OK, but my reasoning\n> there is pretty hand-wavy.\n\nThinking on this a bit more: I guess as soon as we exit libc would call\nthe equivalent of fflush(NULL) anyway, and try that same flush. So in a\nsense this is just ordering a bit differently, and not introducing any\nnew problems. (Unless libc is clever enough to avoid blocking, but that\ndoesn't seem like something we could or should rely on in general).\n\n-Peff\n"},{"id":"442652","messageId":"CAPig+cRQqm8Ce29PnkndT47NNxM3UhJv12RZGZZJD-AyGVC7Zw@mail.gmail.com","threadId":"57000","inReplyTo":"YaXQ/HinYZH1wL7E@coredump.intra.peff.net","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Eric Sunshine","fromEmail":"sunshine@sunshineco.com","sentAt":"2021-11-30T14:05:54Z","receivedAt":"2021-11-30T14:06:07Z","isPatch":true,"sender":{"key":"sunshine@sunshineco.com","avatar":"https://avatars.githubusercontent.com/u/163641?v=4"},"body":"On Tue, Nov 30, 2021 at 2:21 AM Jeff King wrote:\n> On Mon, Nov 29, 2021 at 11:39:46PM -0500, Eric Sunshine wrote:\n> > Rather than attempting to address this issue on a case by case basis,\n> > address it by making vreportf() -- which is the heart of error-reporting\n> > functions die(), error(), warn(), etc. -- flush stdout before emitting\n> > the error message to stderr.\n>\n> I left some thoughts on whether this flush is safe elsewhere in the\n> thread. But for this particular case, two things occur to me:\n>\n> - shouldn't status messages like this go to stderr anyway? I know some\n> people follow the \"unless it is an error, it should not to go\n> stderr\" philosophy. But I think in general our approach in Git is\n> more \"if it is the main output of the program, it goes to stdout; if\n> it is chatter or progress for the user, it goes to stderr\".\n\nI considered this as well and agree that it would be a nicer localized\nfix, but...\n\n(1) I don't think the practice is documented anywhere, so people --\nincluding me when I wrote builtin/worktree.c -- might not know about\nit. Indeed, we don't seem to be entirely consistent about doing it\nthis way. Randomly picking submodule-helper.c, for instance, I see\nstatus-like messages going to stdout:\n\n printf(_(\"Entering '%s'\\n\"), displaypath);\n printf(_(\"Synchronizing submodule url for '%s'\\n\"), ...);\n\n if (...)\n format = _(\"Cleared directory '%s'\\n\");\n else\n format = _(\"Could not remove submodule work tree '%s'\\n\");\n printf(format, displaypath);\n\n(2) With git-worktree being four or five years old, for\nbackward-compatibility concerns, I worry that \"that ship has sailed\",\nwhere 'that' is the freedom to relocate those status-like messages\nfrom stdout to stderr. I don't want to break tooling which exists\naround git-worktree.\n\nI'd be happy to be wrong on the second point -- indeed, git-worktree\nis still marked \"experimental\" in the man-page, but that may not mean\nanything this late in the game -- and submit a patch which places\ngit-worktree's status-like messages on stderr instead of stdout.\nThoughts?\n\n> - the reason it works consistently on glibc is that stdout to a\n> terminal is line buffered by default, so the \"preparing\" line is\n> flushed immediately. If that isn't the case on Windows, should we\n> consider calling setlinebuf() preemptively when isatty(1)?\n\nI'll let the Windows experts chime in on this (Dscho?). For all I\nknow, that might introduce a bad performance regression on that\nplatform under whatever terminal-like or pseudo-tty-like emulation\nthey are using.\n"},{"id":"442665","messageId":"CAPig+cT4+i-R74Lnt9RgkXkDVqx5nThqEMvKG05SP6iRSSsm2w@mail.gmail.com","threadId":"57000","inReplyTo":"YaXPUe9Sz3JBlzYL@coredump.intra.peff.net","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Eric Sunshine","fromEmail":"sunshine@sunshineco.com","sentAt":"2021-11-30T14:15:04Z","receivedAt":"2021-11-30T14:15:17Z","isPatch":true,"sender":{"key":"sunshine@sunshineco.com","avatar":"https://avatars.githubusercontent.com/u/163641?v=4"},"body":"On Tue, Nov 30, 2021 at 2:14 AM Jeff King wrote:\n> - flushing causes us to block. This implies our stdout is connected to\n> a pipe or socket, and the other side is not expecting to read. A\n> plausible case here is a client sending us a big input which we find\n> to be bogus (maybe index-pack checking an incoming pack). We call\n> die() to complain about the input, but the client is still writing.\n> In the current code, we'd write out our error and then exit; the\n> client would get SIGPIPE or a write() error and abort. But with a\n> flush here, we could block writing back to the client, and now we're\n> in a deadlock; they are trying to write to us but we are no longer\n> reading, and we are blocked trying to get out a little bit of\n> irrelevant stdout data.\n>\n> Of the two, the deadlock case worries me more, just because it would be\n> quiet subtle and racy. As I said, I think we may be OK, but my reasoning\n> there is pretty hand-wavy.\n\nFlushing stdout only if it is attached to a terminal:\n\n if (isatty(1))\n fflush(stdout);\n\nshould address this potential-deadlock concern, I think(?). It's\nrather ugly, though, and entering the realm of\ntoo-much-special-casing; it feels like it has the potential of heading\ndown a rabbit hole where we find more cases which need to be handled\nspecially.\n"},{"id":"442668","messageId":"CAPig+cS1ozLSJQgEJemDb+==NdB0ru5p4xknN11dkp6GJJM9iA@mail.gmail.com","threadId":"57000","inReplyTo":"CAPig+cRQqm8Ce29PnkndT47NNxM3UhJv12RZGZZJD-AyGVC7Zw@mail.gmail.com","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Eric Sunshine","fromEmail":"sunshine@sunshineco.com","sentAt":"2021-11-30T14:57:33Z","receivedAt":"2021-11-30T15:03:25Z","isPatch":true,"sender":{"key":"sunshine@sunshineco.com","avatar":"https://avatars.githubusercontent.com/u/163641?v=4"},"body":"On Tue, Nov 30, 2021 at 9:05 AM Eric Sunshine wrote:\n> (2) With git-worktree being four or five years old, for\n> backward-compatibility concerns, I worry that \"that ship has sailed\",\n> where 'that' is the freedom to relocate those status-like messages\n> from stdout to stderr. I don't want to break tooling which exists\n> around git-worktree.\n>\n> I'd be happy to be wrong on the second point -- indeed, git-worktree\n> is still marked \"experimental\" in the man-page, but that may not mean\n> anything this late in the game -- and submit a patch which places\n> git-worktree's status-like messages on stderr instead of stdout.\n> Thoughts?\n\nIf that ship has indeed sailed, then perhaps the best and safest thing\nto do is admit that git-worktree is an outlier in terms of sending\nstatus-like messages to stdout, and just sprinkle the necessary\nfflush(stdout) around in builtin/worktree.c and live with that\nlocalized ugliness. Thoughts?\n"},{"id":"442671","messageId":"211130.86sfvdd6eo.gmgdl@evledraar.gmail.com","threadId":"57000","inReplyTo":"YaXRd2YBQR+ifNTE@coredump.intra.peff.net","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-11-30T15:10:37Z","receivedAt":"2021-11-30T15:17:46Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Tue, Nov 30 2021, Jeff King wrote:\n\n> On Tue, Nov 30, 2021 at 02:14:25AM -0500, Jeff King wrote:\n>\n>> - flushing causes us to block. This implies our stdout is connected to\n>> a pipe or socket, and the other side is not expecting to read. A\n>> plausible case here is a client sending us a big input which we find\n>> to be bogus (maybe index-pack checking an incoming pack). We call\n>> die() to complain about the input, but the client is still writing.\n>> In the current code, we'd write out our error and then exit; the\n>> client would get SIGPIPE or a write() error and abort. But with a\n>> flush here, we could block writing back to the client, and now we're\n>> in a deadlock; they are trying to write to us but we are no longer\n>> reading, and we are blocked trying to get out a little bit of\n>> irrelevant stdout data.\n>> \n>> I _think_ we're probably OK here. The scenario above means that the\n>> caller is already doing asynchronous I/O via stdio and is subject to\n>> deadlock. Because the segment of buffer we try to flush here _could_\n>> have been flushed already under the hood, which would have caused\n>> the same blocking. A careful caller might be using select() or\n>> similar to decide when it is OK to write, but I find it highly\n>> unlikely they'd be using stdio in that case.\n>> \n>> Of the two, the deadlock case worries me more, just because it would be\n>> quiet subtle and racy. As I said, I think we may be OK, but my reasoning\n>> there is pretty hand-wavy.\n>\n> Thinking on this a bit more: I guess as soon as we exit libc would call\n> the equivalent of fflush(NULL) anyway, and try that same flush. So in a\n> sense this is just ordering a bit differently, and not introducing any\n> new problems. (Unless libc is clever enough to avoid blocking, but that\n> doesn't seem like something we could or should rely on in general).\n\nI think this change is probably OK too, but let's not forget about\nwarning() and error(). I.e. we are not always on a path to a fatal error\nwith vreportf(), that's just with die(), usage() and BUG().\n\nSo e.g. the warning you added recently (and we ejected before v2.34.0)\nabout encodings in \"git log\" would behave differently with this\nchange.\n\nI think probably for the better, but we should also consider those\ncases.\n"},{"id":"442678","messageId":"YaaN0pibKWgjcVk3@coredump.intra.peff.net","threadId":"57000","inReplyTo":"CAPig+cRQqm8Ce29PnkndT47NNxM3UhJv12RZGZZJD-AyGVC7Zw@mail.gmail.com","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-30T20:47:14Z","receivedAt":"2021-11-30T20:47:18Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Nov 30, 2021 at 09:05:54AM -0500, Eric Sunshine wrote:\n\n> > - shouldn't status messages like this go to stderr anyway? I know some\n> > people follow the \"unless it is an error, it should not to go\n> > stderr\" philosophy. But I think in general our approach in Git is\n> > more \"if it is the main output of the program, it goes to stdout; if\n> > it is chatter or progress for the user, it goes to stderr\".\n> \n> I considered this as well and agree that it would be a nicer localized\n> fix, but...\n> \n> (1) I don't think the practice is documented anywhere, so people --\n> including me when I wrote builtin/worktree.c -- might not know about\n> it. Indeed, we don't seem to be entirely consistent about doing it\n> this way. Randomly picking submodule-helper.c, for instance, I see\n> status-like messages going to stdout:\n> \n> printf(_(\"Entering '%s'\\n\"), displaypath);\n> printf(_(\"Synchronizing submodule url for '%s'\\n\"), ...);\n> \n> if (...)\n> format = _(\"Cleared directory '%s'\\n\");\n> else\n> format = _(\"Could not remove submodule work tree '%s'\\n\");\n> printf(format, displaypath);\n\nYeah, we've definitely not been consistent here. There's no silver\nbullet for this aside from vigilance during review, but probably laying\nout guidelines could help.\n\nHere's a past discussion (that actually goes the other way: somebody\ncomplaining that stderr should be on stdout!) where I laid out my mental\nmodel:\n\n https://lore.kernel.org/git/20110907215716.GJ13364@sigill.intra.peff.net/\n\n> (2) With git-worktree being four or five years old, for\n> backward-compatibility concerns, I worry that \"that ship has sailed\",\n> where 'that' is the freedom to relocate those status-like messages\n> from stdout to stderr. I don't want to break tooling which exists\n> around git-worktree.\n\nIMHO it would be OK to change these. They are, after all, marked for\ntranslation, so they're not reliably machine-readable anyway. It's\npossible that some script could not be parsing them, but just trying to\nredirect them. Or even keying on content in stderr as a sign of an error\n(as tcl likes to do). But I don't think that's a guarantee we want to be\nbound by.\n\nSee 68b939b2f0 (clone: send diagnostic messages to stderr, 2013-09-18)\nfor a similar case in the past.\n\n> I'd be happy to be wrong on the second point -- indeed, git-worktree\n> is still marked \"experimental\" in the man-page, but that may not mean\n> anything this late in the game -- and submit a patch which places\n> git-worktree's status-like messages on stderr instead of stdout.\n> Thoughts?\n\nI'm in favor. :)\n\n-Peff\n"},{"id":"442680","messageId":"YaaO8dxOwi7YKbmZ@coredump.intra.peff.net","threadId":"57000","inReplyTo":"211130.86sfvdd6eo.gmgdl@evledraar.gmail.com","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-30T20:52:01Z","receivedAt":"2021-11-30T20:52:06Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Nov 30, 2021 at 04:10:37PM +0100, Ævar Arnfjörð Bjarmason wrote:\n\n> \n> On Tue, Nov 30 2021, Jeff King wrote:\n> \n> > On Tue, Nov 30, 2021 at 02:14:25AM -0500, Jeff King wrote:\n> >\n> >> - flushing causes us to block. This implies our stdout is connected to\n> >> a pipe or socket, and the other side is not expecting to read. A\n> >> plausible case here is a client sending us a big input which we find\n> >> to be bogus (maybe index-pack checking an incoming pack). We call\n> >> die() to complain about the input, but the client is still writing.\n> >> In the current code, we'd write out our error and then exit; the\n> >> client would get SIGPIPE or a write() error and abort. But with a\n> >> flush here, we could block writing back to the client, and now we're\n> >> in a deadlock; they are trying to write to us but we are no longer\n> >> reading, and we are blocked trying to get out a little bit of\n> >> irrelevant stdout data.\n> >> \n> >> I _think_ we're probably OK here. The scenario above means that the\n> >> caller is already doing asynchronous I/O via stdio and is subject to\n> >> deadlock. Because the segment of buffer we try to flush here _could_\n> >> have been flushed already under the hood, which would have caused\n> >> the same blocking. A careful caller might be using select() or\n> >> similar to decide when it is OK to write, but I find it highly\n> >> unlikely they'd be using stdio in that case.\n> >> \n> >> Of the two, the deadlock case worries me more, just because it would be\n> >> quiet subtle and racy. As I said, I think we may be OK, but my reasoning\n> >> there is pretty hand-wavy.\n> >\n> > Thinking on this a bit more: I guess as soon as we exit libc would call\n> > the equivalent of fflush(NULL) anyway, and try that same flush. So in a\n> > sense this is just ordering a bit differently, and not introducing any\n> > new problems. (Unless libc is clever enough to avoid blocking, but that\n> > doesn't seem like something we could or should rely on in general).\n> \n> I think this change is probably OK too, but let's not forget about\n> warning() and error(). I.e. we are not always on a path to a fatal error\n> with vreportf(), that's just with die(), usage() and BUG().\n\nMy gut feeling is that warning() and error() would encounter a subset of\nthe problems that die() would. Because die() is actually changing the\nprogram state in a much more drastic way (by exiting), whereas error and\nwarning would continue and eventually flush anyway. They might care more\nabout things like errno being touched if they continue on, but they\nalready must assume that vreportf() can affect errno (because of the\nexisting flush and write on stderr).\n\nLikewise BUG() is an interesting one. It doesn't call exit(), but\ninstead abort(). So unlike die(), it doesn't actually flush, and the \"we\nwould fflush(NULL) on exit anyway\" caveat above does not apply.\n\nI still suspect that any caller doing async I/O on stdio like this is\nalready flaky, though. It could have decided to flush and blocked during\nany write.\n\n-Peff\n"},{"id":"442735","messageId":"CAPig+cT+YfgBG3Aqszp+y7iy_megboECZy3NkMqUjBj7=Z661A@mail.gmail.com","threadId":"57000","inReplyTo":"YaaN0pibKWgjcVk3@coredump.intra.peff.net","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Eric Sunshine","fromEmail":"sunshine@sunshineco.com","sentAt":"2021-12-01T02:36:42Z","receivedAt":"2021-12-01T02:36:57Z","isPatch":true,"sender":{"key":"sunshine@sunshineco.com","avatar":"https://avatars.githubusercontent.com/u/163641?v=4"},"body":"On Tue, Nov 30, 2021 at 3:47 PM Jeff King wrote:\n> On Tue, Nov 30, 2021 at 09:05:54AM -0500, Eric Sunshine wrote:\n> > (1) I don't think the practice is documented anywhere, so people --\n> > including me when I wrote builtin/worktree.c -- might not know about\n> > it. Indeed, we don't seem to be entirely consistent about doing it\n> > this way. Randomly picking submodule-helper.c, for instance, I see\n> > status-like messages going to stdout:\n>\n> Yeah, we've definitely not been consistent here. There's no silver\n> bullet for this aside from vigilance during review, but probably laying\n> out guidelines could help.\n>\n> Here's a past discussion (that actually goes the other way: somebody\n> complaining that stderr should be on stdout!) where I laid out my mental\n> model:\n>\n> https://lore.kernel.org/git/20110907215716.GJ13364@sigill.intra.peff.net/\n\nThanks for the reference. I'll take a stab at adding a blurb about\nthis to CodingGuidelines.\n\n> > (2) With git-worktree being four or five years old, for\n> > backward-compatibility concerns, I worry that \"that ship has sailed\",\n> > where 'that' is the freedom to relocate those status-like messages\n> > from stdout to stderr. I don't want to break tooling which exists\n> > around git-worktree.\n>\n> IMHO it would be OK to change these. They are, after all, marked for\n> translation, so they're not reliably machine-readable anyway. It's\n> possible that some script could not be parsing them, but just trying to\n> redirect them. Or even keying on content in stderr as a sign of an error\n> (as tcl likes to do). But I don't think that's a guarantee we want to be\n> bound by.\n\nThat's a good point about them being marked for translation. It also\nreminds me that we made some reasonably significant changes to this\nexact message in 2c27002a0a (worktree: improve message when creating a\nnew worktree, 2018-04-24), and we didn't hear any complaints, let\nalone complaints about tool breakage.\n\n> See 68b939b2f0 (clone: send diagnostic messages to stderr, 2013-09-18)\n> for a similar case in the past.\n\nNice. This and the above make me feel much more comfortable with the\nidea of changing git-worktree to send these sorts of messages to\nstderr rather than stdout.\n\n> > I'd be happy to be wrong on the second point -- indeed, git-worktree\n> > is still marked \"experimental\" in the man-page, but that may not mean\n> > anything this late in the game -- and submit a patch which places\n> > git-worktree's status-like messages on stderr instead of stdout.\n> > Thoughts?\n>\n> I'm in favor. :)\n\nThanks. I'll drop this RFC patch and resubmit with a patch which just\nfixes git-worktree to be chatty on stderr instead of stdout.\n"},{"id":"442743","messageId":"CAPig+cRB45nwUin4Lv-j2dAQob1SSu7hGyM2c3E8G2ym_uFB2w@mail.gmail.com","threadId":"57000","inReplyTo":"CAPig+cT+YfgBG3Aqszp+y7iy_megboECZy3NkMqUjBj7=Z661A@mail.gmail.com","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Eric Sunshine","fromEmail":"sunshine@sunshineco.com","sentAt":"2021-12-01T05:38:16Z","receivedAt":"2021-12-01T05:38:54Z","isPatch":true,"sender":{"key":"sunshine@sunshineco.com","avatar":"https://avatars.githubusercontent.com/u/163641?v=4"},"body":"On Tue, Nov 30, 2021 at 9:36 PM Eric Sunshine wrote:\n> On Tue, Nov 30, 2021 at 3:47 PM Jeff King wrote:\n> > On Tue, Nov 30, 2021 at 09:05:54AM -0500, Eric Sunshine wrote:\n> > > (1) I don't think the practice is documented anywhere, so people --\n> > > including me when I wrote builtin/worktree.c -- might not know about\n> > > it. Indeed, we don't seem to be entirely consistent about doing it\n> > > this way. Randomly picking submodule-helper.c, for instance, I see\n> > > status-like messages going to stdout:\n> >\n> > Yeah, we've definitely not been consistent here. There's no silver\n> > bullet for this aside from vigilance during review, but probably laying\n> > out guidelines could help.\n>\n> Thanks for the reference. I'll take a stab at adding a blurb about\n> this to CodingGuidelines.\n\nI just posted a patch which updates CodingGuidelines to talk a bit about this:\nhttps://lore.kernel.org/git/20211201053214.2902-1-sunshine@sunshineco.com/\n"},{"id":"442773","messageId":"211201.86h7bsbf4l.gmgdl@evledraar.gmail.com","threadId":"57000","inReplyTo":"CAPig+cS1ozLSJQgEJemDb+==NdB0ru5p4xknN11dkp6GJJM9iA@mail.gmail.com","subject":"\"breaking\" command output message parsing (was: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output)","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-12-01T13:51:11Z","receivedAt":"2021-12-01T13:59:12Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Tue, Nov 30 2021, Eric Sunshine wrote:\n\n> On Tue, Nov 30, 2021 at 9:05 AM Eric Sunshine wrote:\n>> (2) With git-worktree being four or five years old, for\n>> backward-compatibility concerns, I worry that \"that ship has sailed\",\n>> where 'that' is the freedom to relocate those status-like messages\n>> from stdout to stderr. I don't want to break tooling which exists\n>> around git-worktree.\n>>\n>> I'd be happy to be wrong on the second point -- indeed, git-worktree\n>> is still marked \"experimental\" in the man-page, but that may not mean\n>> anything this late in the game -- and submit a patch which places\n>> git-worktree's status-like messages on stderr instead of stdout.\n>> Thoughts?\n>\n> If that ship has indeed sailed, then perhaps the best and safest thing\n> to do is admit that git-worktree is an outlier in terms of sending\n> status-like messages to stdout, and just sprinkle the necessary\n> fflush(stdout) around in builtin/worktree.c and live with that\n> localized ugliness. Thoughts?\n\nI really don't think that ship has sailed at all. We're at full liberty\nto change these error messages, and have even done so for some plumbing\nin the past (being sensitive to what sort of messages, sometimes they\nare important).\n\nSee e.g. my 9144ba4cf52 (remote: add meaningful exit code on\nmissing/existing, 2020-10-27), that was a case where we knew about a\nin-the-wild parser of the output, and git-remote is in the (I suppose\n\"pseudo-plumbing?\") \"Ancillary Commands\" category.\n\nI think the one grey area here is as in 9144ba4cf52 where we'd expect\npeople to reasonably script around these commands, and parsing the\noutput was the only way to accomplish something reasonable. E.g. in that\ncase automation around adding remotes & the handling of failure\nscenarios. The case of [1] for \"git pull\" is another potential recent\none. I.e. someone grepping \"Everything up-to-date\".\n\nFrom some brief skimming of the worktree.c code that doesn't seem to\napply, i.e. it's just chattyness.\n\nI doubt anyone cares if it's blathering about \"preparing a worktree\" or\nwhatever, it just matters if \"git worktree add\" and the like fail with\nnon-zero, but perhaps there's cases of conflated states, as in that case\nof \"git remote\" and \"git pull\".\n\n1. https://lore.kernel.org/git/211130.86a6hleo84.gmgdl@evledraar.gmail.com/\n"},{"id":"442778","messageId":"CAPig+cQ56HV0fjPkhiWgv3EbRABo2J1-PMxDVmmfjh=t7=6LuA@mail.gmail.com","threadId":"57000","inReplyTo":"211201.86h7bsbf4l.gmgdl@evledraar.gmail.com","subject":"Re: \"breaking\" command output message parsing (was: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output)","fromName":"Eric Sunshine","fromEmail":"sunshine@sunshineco.com","sentAt":"2021-12-01T14:34:15Z","receivedAt":"2021-12-01T14:36:32Z","isPatch":true,"sender":{"key":"sunshine@sunshineco.com","avatar":"https://avatars.githubusercontent.com/u/163641?v=4"},"body":"On Wed, Dec 1, 2021 at 8:59 AM Ævar Arnfjörð Bjarmason wrote:\n> On Tue, Nov 30 2021, Eric Sunshine wrote:\n> > On Tue, Nov 30, 2021 at 9:05 AM Eric Sunshine wrote:\n> >> (2) With git-worktree being four or five years old, for\n> >> backward-compatibility concerns, I worry that \"that ship has sailed\",\n> >> where 'that' is the freedom to relocate those status-like messages\n> >> from stdout to stderr. I don't want to break tooling which exists\n> >> around git-worktree.\n> >>\n> >> I'd be happy to be wrong on the second point -- indeed, git-worktree\n> >> is still marked \"experimental\" in the man-page, but that may not mean\n> >> anything this late in the game -- and submit a patch which places\n> >> git-worktree's status-like messages on stderr instead of stdout.\n> >> Thoughts?\n> >\n> > If that ship has indeed sailed, then perhaps the best and safest thing\n> > to do is admit that git-worktree is an outlier in terms of sending\n> > status-like messages to stdout, and just sprinkle the necessary\n> > fflush(stdout) around in builtin/worktree.c and live with that\n> > localized ugliness. Thoughts?\n>\n> I really don't think that ship has sailed at all. We're at full liberty\n> to change these error messages, and have even done so for some plumbing\n> in the past (being sensitive to what sort of messages, sometimes they\n> are important).\n\nJust to be clear for other readers, I wasn't talking about changing\nerror messages but rather changing the destination of the \"chatty\"\nmessages from stdout to stderr. (I think you probably understand that\neven though you typed \"error message\" above.)\n\n> From some brief skimming of the worktree.c code that doesn't seem to\n> apply, i.e. it's just chattyness.\n>\n> I doubt anyone cares if it's blathering about \"preparing a worktree\" or\n> whatever, it just matters if \"git worktree add\" and the like fail with\n> non-zero, but perhaps there's cases of conflated states, as in that case\n> of \"git remote\" and \"git pull\".\n\nPeff had already managed to allay my worries about that ship having\nsailed[1], so that I decided[2] to drop the RFC patch and resubmit as\na patch which moves the git-worktree \"chatty\" messages from stdout to\nstderr. Nevertheless, it's nice to hear an independent confirmation\nabout that ship.\n\n[1]: https://lore.kernel.org/git/YaaN0pibKWgjcVk3@coredump.intra.peff.net/\n[2]: https://lore.kernel.org/git/CAPig+cT+YfgBG3Aqszp+y7iy_megboECZy3NkMqUjBj7=Z661A@mail.gmail.com/\n"},{"id":"442805","messageId":"211201.86mtlk9fx4.gmgdl@evledraar.gmail.com","threadId":"57000","inReplyTo":"YaaN0pibKWgjcVk3@coredump.intra.peff.net","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-12-01T21:20:11Z","receivedAt":"2021-12-01T21:25:08Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Tue, Nov 30 2021, Jeff King wrote:\n\n> On Tue, Nov 30, 2021 at 09:05:54AM -0500, Eric Sunshine wrote:\n>\n>> > - shouldn't status messages like this go to stderr anyway? I know some\n>> > people follow the \"unless it is an error, it should not to go\n>> > stderr\" philosophy. But I think in general our approach in Git is\n>> > more \"if it is the main output of the program, it goes to stdout; if\n>> > it is chatter or progress for the user, it goes to stderr\".\n>> \n>> I considered this as well and agree that it would be a nicer localized\n>> fix, but...\n>> \n>> (1) I don't think the practice is documented anywhere, so people --\n>> including me when I wrote builtin/worktree.c -- might not know about\n>> it. Indeed, we don't seem to be entirely consistent about doing it\n>> this way. Randomly picking submodule-helper.c, for instance, I see\n>> status-like messages going to stdout:\n>> \n>> printf(_(\"Entering '%s'\\n\"), displaypath);\n>> printf(_(\"Synchronizing submodule url for '%s'\\n\"), ...);\n>> \n>> if (...)\n>> format = _(\"Cleared directory '%s'\\n\");\n>> else\n>> format = _(\"Could not remove submodule work tree '%s'\\n\");\n>> printf(format, displaypath);\n>\n> Yeah, we've definitely not been consistent here. There's no silver\n> bullet for this aside from vigilance during review, but probably laying\n> out guidelines could help.\n>\n> Here's a past discussion (that actually goes the other way: somebody\n> complaining that stderr should be on stdout!) where I laid out my mental\n> model:\n>\n> https://lore.kernel.org/git/20110907215716.GJ13364@sigill.intra.peff.net/\n\n...and a third way (which git doesn't conform to at all), which is that\nstd*err* is really what we should be using for errors only.\n\nYou shouldn't write anything that isn't an error there, or at least\nthat's what I've seen some software in the wild assume.\n\nI've run into occasional problems with git over the years because it\nwrites to stderr routinely for non-errors, which flies in the face\nassumptions made by various third-party software that assumes the\n\"that's for errors\" model of the world.\n\nE.g. look at the (very useful) \"chronic\" utility, which is in\n\"moreutils\" in Debian. From its manpage:\n\n -e Stderr triggering. Triggers output when stderr output length is non-zero.\n Without -e chronic needs non-zero return value to trigger output.\n\n In this mode, chronic's return value will be 2 if the command's\n return value is 0 but the command printed to stderr.\n\nRight now I'm failing to recall what, but I remember dealing with that\nbehavior from git in some other contexts.\n"},{"id":"442840","messageId":"xmqq35nbygxs.fsf@gitster.g","threadId":"57000","inReplyTo":"211201.86mtlk9fx4.gmgdl@evledraar.gmail.com","subject":"Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-12-02T00:43:43Z","receivedAt":"2021-12-02T00:43:57Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Ævar Arnfjörð Bjarmason writes:\n\n>> Here's a past discussion (that actually goes the other way: somebody\n>> complaining that stderr should be on stdout!) where I laid out my mental\n>> model:\n>>\n>> https://lore.kernel.org/git/20110907215716.GJ13364@sigill.intra.peff.net/\n>\n> ...and a third way (which git doesn't conform to at all), which is that\n> std*err* is really what we should be using for errors only.\n>\n> You shouldn't write anything that isn't an error there, or at least\n> that's what I've seen some software in the wild assume.\n\nThat is already covered in the old thread Peff cited (not in the\nmessage from Peff, but you can find what others said on the topic\nback then from that page). We saw programs that declare any output\nto standard error by programs they spawn indicates an error, instead\nof checking the exit status of the programs they spawn, which would\nof course break when they try to drive git.\n"}]}