blog · git · desktop · images · contact & privacy · gopher
2022-05-01
Just a minor detail that I came across.
In one of our repos at work, we all have a local post-commit hook on
our laptops. The content of this hook isn’t really relevant for this
blog post – let’s just say it refreshes a local cache: Every time I run
git commit, I want this cache to be updated.
This can take a couple of seconds. As such, the hook forks and then a subshell does the actual work:
#!/bin/sh
(
... do lengthy operation ...
) &
(This can be problematic when you do rebases: The hook will be called for every step in the rebase process, meaning the tool that updates this cache must be prepared to run several times in parallel, if you do forking like this.)
With Git 2.36, this “stopped working”. The hook still ran, but Git blocked until it has finished. This was undesired.
strace (still one of my favorite tools of all time) quickly revealed
what was going on: Git didn’t just wait() for the main process
anymore, it did more than that. This is how it looked like in Git 2.35:
16:35:27.380406 access(".git/hooks/post-commit", X_OK) = 0
...
16:35:27.380572 clone(...) = 119576
...
16:35:27.382301 wait4(119576, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 119576
16:35:27.388232 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=119576, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
If it sees that the file .git/hooks/post-commit is executable, it
fork()s (or clone()s, rather), runs the hook, which then forks again
and exits immediately (not shown in this trace). Git is happy and
quickly resumes its work.
With Git 2.36, I see this:
16:41:59.586443 access(".git/hooks/post-commit", X_OK) = 0
...
16:41:59.586621 pipe2([3, 4], 0) = 0
16:41:59.586654 pipe2([5, 6], 0) = 0
16:41:59.586674 openat(AT_FDCWD, "/dev/null", O_RDWR|O_CLOEXEC) = 7
...
16:41:59.586770 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7ff87e69de50) = 120480
...
[120480] 16:41:59.586973 dup2(7, 0) = 0
[120480] 16:41:59.586989 dup2(4, 2) = 2
[120480] 16:41:59.587035 dup2(2, 1) = 1
...
16:41:59.588637 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
16:41:59.594249 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=120480, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
16:41:59.594261 restart_syscall(<... resuming interrupted poll ...>) = 0
16:41:59.688960 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:41:59.789465 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:41:59.889939 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:41:59.990234 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:00.090559 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:00.191009 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:00.291429 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:00.391829 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:00.492257 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:00.592750 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:00.693189 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:00.793596 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:00.894033 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:00.994416 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:01.094724 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:01.195124 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:01.295521 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:01.395946 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:01.496360 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 0 (Timeout)
16:42:01.596745 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 1 ([{fd=3, revents=POLLIN}])
16:42:01.608419 read(3, "ok\n", 8192) = 3
16:42:01.608527 write(2, "ok\n", 3) = 3
16:42:01.608605 poll([{fd=3, events=POLLIN|POLLHUP}], 1, 100) = 1 ([{fd=3, revents=POLLHUP}])
16:42:01.608768 read(3, "", 8192) = 0
16:42:01.608810 close(3) = 0
16:42:01.608883 wait4(120480, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 120480
Note the delay in time. Git now connects pipes to stdout and stderr
in the child process and its stdin becomes /dev/null. As you can
tell by the SIGCHLD signal, process 120480 still quickly exits (this
is .git/hooks/post-commit, which then proceeds to fork again), but Git
now insists on fully reading the pipe. “Fully reading” means it has to
wait until the other end (my hook) has closed those file descriptors.
This doesn’t happen until the forked part of my hook finally exits.
Hence my hook blocked.
One workaround to avoid this blocking, is to close the file descriptors explicitly:
#!/bin/sh
(
exec 0<&-
exec 1>&-
exec 2>&-
... do lengthy operation ...
) &
Or, if you don’t want to lose the output:
#!/bin/sh
(
exec 0</dev/tty
exec 1>/dev/tty
exec 2>/dev/tty
... do lengthy operation ...
) &
/dev/tty corresponds to the controlling terminal of your process.
Interestingly, this special file is really old, it is already mentioned
in the book The Unix Programming Environment
from 1984:
/dev/ttyis particularly useful when a program needs to interact with a user even though its standard input and output are connected to files rather than the terminal.
Later in the book, they use it again in their pick script.
Alright, back to topic.
At first, I thought this change could have been made intentionally. Maybe they wanted to do a better job at tracking if hooks really finished … ? Would have been a bit flaky, though, because a simple redirection of the output to a file breaks it. So, probably not intentional … ?
I took the time to bisect this today and this is the offending commit:
convert {pre-commit,prepare-commit-msg} hook to hook.h
Still a bit hard to tell if intentional or not.
Searching the Git mailing lists revealed this report by Anthony Sottile. He found the same commit, but he noticed the change some other way, I quote:
I maintain a git hooks framework which uses
isattyto detect whether it's appropriate to color the output. many tools utilize the same check.
Of course, now that there’s a pipe, this check doesn’t work anymore.
After a short discussion, they classified it as a regression and a set of patches is now “cooking”, so it’s probably going to be fixed soon.