[2.54.0] fixup! gvfs: add global command pre and post hook procs#955
Conversation
derrickstolee
force-pushed
the
post-command-recurse
branch
from
fb765fd to
d9610f0
Compare
|
I had a test in an earlier version, but it was a copilot test that broke in some cases and also didn't actually break without the code change. I'm not sure how to reproduce it, but the code seems obviously correct to me. |
| */ | ||
| if (!run_post_hook) | ||
| return 0; | ||
| run_post_hook = 0; |
There was a problem hiding this comment.
@derrickstolee I think that this cannot recurse in the same process, as the caller in the atexit() handler should only be called well after the three other callers (all on the main thread):
- in
run_builtin() - in
execv_dashed_external() - in
cmd_main()(the early "usage" code path when no arguments at all were passed along).
So I wonder whether this change on its own can do anything to help the issue.
I rather suspect that the infinite loop might happen due to the post-command hook calling another Git command? If that is the case, then we'd also have to move the setenv("COMMAND_HOOK_LOCK", "false", 1); call right after the COMMAND_HOOK_LOCK guard, too, not just the run_post_hook = 0; assignment?
There was a problem hiding this comment.
I'm still trying to figure out a reproducer or at least a trace of the issue, but if we get a die() between this point and the child process kickoff it may start recursing here. At least, that's my theory.
There was a problem hiding this comment.
The repeated fatal: recursion detected in die handler wouldn't happen from just a recursion within the post-command hook calling another git process. And the user output looks like
fatal: recursion detected in die handler
fatal: recursion detected in die handler
fatal: recursion detected in die handler
fatal: recursion detected in die handler
fatal: recursion detected in die handler
fatal: recursion detected in die handler
fatal: recursion detected in die handler
fatal: recursion detected in die handler
and continues until they kill the process.
There was a problem hiding this comment.
@dscho I did end up finding a trace that could be helpful, leading to a change in the trace2 code. I'll polish that up for upstream soon, but I'd like your feedback here.
There was a problem hiding this comment.
Ah, so the problem is a die() in the atexit() path? That does make sense to me.
There was a problem hiding this comment.
And things are finally coming together: this happens when the atexit event is traced as part of GIT_TRACE2_EVENT, which is set for these users to an instance of the trace2collector.
derrickstolee
force-pushed
the
post-command-recurse
branch
from
d9610f0 to
205ad4f
Compare
| gmtime_r(&secs, &tm); | ||
|
|
||
| xsnprintf(tb->buf, sizeof(tb->buf), | ||
| vsnprintf(tb->buf, sizeof(tb->buf), |
There was a problem hiding this comment.
I fear that we have to check the return value and fill the buffer with something deterministic upon failure.
There was a problem hiding this comment.
Oh, and it should be snprintf() most likely, since that function takes a variable number of arguments, while vsnprintf() expects a va_list as 4th parameter (and no parameter after that, see e.g. these docs.
There was a problem hiding this comment.
I'm iterating on this final detail in gitgitgadget#2178.
dscho
force-pushed
the
post-command-recurse
branch
from
205ad4f to
be9716e
Compare
derrickstolee
force-pushed
the
post-command-recurse
branch
from
be9716e to
c23e71a
Compare
Signed-off-by: Derrick Stolee <stolee@gmail.com>
Some users reported issues of repeated messages: fatal: recursion detected in die handler This wasn't happening every time, but we eventually captured a GIT_TRACE2_PERF log file with this issue and revealed an interesting internal detail, failing with this message: unable to format message: %4d-%02d-%02dT%02d:%02d:%02d.%06ldZ This specific format string tracks to tr2_tbuf_utc_datetime_extended() in trace2/tr2_tbuf.c. This logic began as tr2_tbuf_utc_time() in ee4512e (trace2: create new combined trace facility, 2019-02-22) but was later split in bad229a (trace2: clarify UTC datetime formatting, 2019-04-15). This use of xsnprintf() is writing a very specific datetime format into a 32-character buffer. The format requires that the input data will not overflow the format digits or the buffer will not hold the result. Since we are using xsnprintf() here, those failures turn into die() events. This method and its siblings, tr2_tbuf_local_time() and tr2_tbuf_utc_datetime(), are used in the tracing library. The extended form is used only for the 'event' format, which these users were using via a config setting for use in client-side telemetry. The non-extended form is used to help generate the 'SID' that defines the process in the traces. Not only are these inappropriate times for a failure, but the extended method is called specifially during the 'atexit' event, which was triggering this problem in a loop as the 'atexit' event would be retriggered by the die(). I could not determine the exact cause of why these errors started occuring in a bunch. My best guess is that these users are dogfooding an early operating system version that is more likely to fail in the gettimeofday() function and thus leaves the structures uninitialized and potentially violating the expected values. However, for full defense-in-depth I made several modifications: 1. Both 'tv' and 'tm' structs are initialized with zero values, allowing an erroring gettimeofday() or gmtime_r() method to leave them zero-valued. A zero-valued date is better than a die() here. 2. Replace the use of xsnprintf() with snprintf() to avoid the possibility of calling die() here. Instead, check the response to see if there was a failure. On failure, put a blank value into the buffer instead of possibly allowing a value that would not format correctly for a trace2 consumer. This value should be seen as obviously wrong and therefore signals a problem. As the core issue in this code seems to require a system method returning an error, no test accompanies this change. This change removes all uses of xsnprintf() from the trace2/ directory. There are two uses of xstrdup() that could be considered for removal, but they only die() on out-of-memory errors instead of formatting issues. I chose to leave those in place for now. Signed-off-by: Derrick Stolee <stolee@gmail.com>
derrickstolee
force-pushed
the
post-command-recurse
branch
from
c23e71a to
3b682fb
Compare
dscho
left a comment
dscho
left a comment
There was a problem hiding this comment.
Awesome, I forgot to look around for similar instances, but you didn't forget!
Users were noticing some cases of infinite loops with the error message: ``` fatal: recursion detected in die handler ``` It's only happening for repos with a post-command hook, but it's not deterministic. I'm not sure what is triggering the problem, but the post-command hook is definitely able to recurse with its existing logic around the `run_post_hook` variable. Move this earlier to avoid a potential double-call. It's a fixup to the introduction of the method, which may cause conflicts with later adjustments to this method still in the branch thicket (but maybe those should be squashed, too). See #955 for the version on 2.54.0.
|
This is now available via https://github.com/microsoft/git/releases/tag/v2.54.0.vfs.0.5, which I plan on promoting to a full release either later today, or early tomorrow. |
2 participants
Users were noticing some cases of infinite loops with the error message:
It's only happening for repos with a post-command hook, but it's not deterministic. I'm not sure what is triggering the problem, but the post-command hook is definitely able to recurse with its existing logic around the
run_post_hookvariable.Move this earlier to avoid a potential double-call. It's a fixup to the introduction of the method, which may cause conflicts with later adjustments to this method still in the branch thicket (but maybe those should be squashed, too).