fsmonitor deadlock / macOS CI hangs

fsmonitor deadlock / macOS CI hangs

[Jeff King]

I did some more digging on the hangs we sometimes see when running the
test suite on macOS. I'm cc-ing Patrick as somebody who dug into this
before, and Johannes as the only still-active person mentioned in the
relevant code.

For those just joining, you can reproduce the issue by running t9211
with --stress on macOS. Some earlier notes are here:

  https://lore.kernel.org/git/20240517081132.GA1517321@coredump.intra.peff.net/

but the gist of it is that we end up with Git processes waiting to read
from fsmonitor, but fsmonitor hanging.

Since then, I swapped out gdb for lldb, which let me see a bit more of
who is doing what.

The test is waiting on a "scalar" process to exit. But that's just in
wait_or_whine() waiting for git-fetch to exit. That git-fetch is in turn
waiting to read() from fsmonitor after sending a command. Here's the
backtrace:

    * frame #0: 0x00007ff81afdbf7e libsystem_kernel.dylib`read + 10
      frame #1: 0x000000010a4fa6ae git`xread(fd=8, buf=0x00007ff7b5d82188, len=4) at wrapper.c:231:8
      frame #2: 0x000000010a4fa8de git`read_in_full(fd=8, buf=0x00007ff7b5d82188, count=4) at wrapper.c:289:20
      frame #3: 0x000000010a417684 git`get_packet_data(fd=8, src_buf=0x0000000000000000, src_size=0x0000000000000000, dst=0x00007ff7b5d82188, size=4, options=9) at pkt-line.c:355:9
      frame #4: 0x000000010a417173 git`packet_read_with_status(fd=8, src_buffer=0x0000000000000000, src_len=0x0000000000000000, buffer="", size=65517, pktlen=0x00007ff7b5d821e4, options=9) at pkt-line.c:421:6
      frame #5: 0x000000010a4178bb git`packet_read(fd=8, buffer="", size=65517, options=9) at pkt-line.c:519:2
      frame #6: 0x000000010a417a07 git`read_packetized_to_strbuf(fd_in=8, sb_out=0x00007ff7b5d82380, options=9) at pkt-line.c:554:16
      frame #7: 0x000000010a508779 git`ipc_client_send_command_to_connection(connection=0x0000600001718000, message="1727469801286015000", message_len=19, answer=0x00007ff7b5d82380) at ipc-unix-socket.c:210:6
      frame #8: 0x000000010a377553 git`fsmonitor_ipc__send_query(since_token="1727469801286015000", answer=0x00007ff7b5d82380) at fsmonitor-ipc.c:94:9
      frame #9: 0x000000010a376149 git`refresh_fsmonitor(istate=0x0000600002910300) at fsmonitor.c:536:20
      frame #10: 0x000000010a376be7 git`add_fsmonitor(istate=0x0000600002910300) at fsmonitor.c:778:3
      frame #11: 0x000000010a376e19 git`tweak_fsmonitor(istate=0x0000600002910300) at fsmonitor.c:818:3
      frame #12: 0x000000010a430840 git`post_read_index_from(istate=0x0000600002910300) at read-cache.c:1968:2

In fsmonitor we have a bunch of threads. The main thread is waiting on
worker threads, which I think is expected:

  * thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
      frame #0: 0x00007ff81afdccce libsystem_kernel.dylib`__ulock_wait + 10
      frame #1: 0x00007ff81b01b9b9 libsystem_pthread.dylib`_pthread_join + 348
    * frame #2: 0x000000010e5ec2b1 git`ipc_server_await(server_data=0x0000600002790000) at ipc-unix-socket.c:971:2
      frame #3: 0x000000010e2d3a3f git`fsmonitor_run_daemon_1(state=0x00007ff7b1ca0420) at fsmonitor--daemon.c:1251:2
      frame #4: 0x000000010e2d35c5 git`fsmonitor_run_daemon at fsmonitor--daemon.c:1399:8

Most of the other threads are just waiting for clients:

  * thread #2
    * frame #0: 0x00007ff81afe2242 libsystem_kernel.dylib`poll + 10
      frame #1: 0x000000010e5ec664 git`accept_thread__wait_for_connection(accept_thread_data=0x000060000129c000) at ipc-unix-socket.c:653:12
      frame #2: 0x000000010e5ebf2a git`accept_thread_proc(_accept_thread_data=0x000060000129c000) at ipc-unix-socket.c:728:19
      frame #3: 0x00007ff81b01a1d3 libsystem_pthread.dylib`_pthread_start + 125
      frame #4: 0x00007ff81b015bd3 libsystem_pthread.dylib`thread_start + 15

which I think is again expected. But not this one, which should be
serving our command:

  * thread #3
    * frame #0: 0x00007ff81afde08e libsystem_kernel.dylib`__psynch_cvwait + 10
      frame #1: 0x00007ff81b01a758 libsystem_pthread.dylib`_pthread_cond_wait + 1242
      frame #2: 0x000000010e2d4a90 git`with_lock__wait_for_cookie(state=0x00007ff7b1ca0420) at fsmonitor--daemon.c:209:3
      frame #3: 0x000000010e2d40f2 git`do_handle_client(state=0x00007ff7b1ca0420, command="1727469801286015000", reply=(git`do_io_reply_callback at ipc-unix-socket.c:431), reply_data=0x0000700007d3af38) at fsmonitor--daemon.c:764:19
      frame #4: 0x000000010e2d3c60 git`handle_client(data=0x00007ff7b1ca0420, command="1727469801286015000", command_len=19, reply=(git`do_io_reply_callback at ipc-unix-socket.c:431), reply_data=0x0000700007d3af38) at fsmonitor--daemon.c:984:11
      frame #5: 0x000000010e5ecaa7 git`worker_thread__do_io(worker_thread_data=0x0000600001c9c000, fd=23) at ipc-unix-socket.c:531:9
      frame #6: 0x000000010e5ec056 git`worker_thread_proc(_worker_thread_data=0x0000600001c9c000) at ipc-unix-socket.c:605:9
      frame #7: 0x00007ff81b01a1d3 libsystem_pthread.dylib`_pthread_start + 125

We got that same command from git-fetch, but we're hanging on a pthread
operation. It's this one, and note the suspicious comment:

          /*
           * Technically, this is an infinite wait (well, unless another
           * thread sends us an abort).  I'd like to change this to
           * use `pthread_cond_timedwait()` and return an error/timeout
           * and let the caller do the trivial response thing, but we
           * don't have that routine in our thread-utils.
           *
           * After extensive beta testing I'm not really worried about
           * this.  Also note that the above open() and unlink() calls
           * will cause at least two FS events on that path, so the odds
           * of getting stuck are pretty slim.
           */
          while (cookie->result == FCIR_INIT)
                  pthread_cond_wait(&state->cookies_cond,
                                    &state->main_lock);

So we're waiting for somebody to trigger the cookies_cond. Who's
supposed to do that? It's done in fsmonitor_publish(), which is
triggered when we actually see filesystem events. The main listening
loop is also waiting on a pthread cond:

  * thread #11
    * frame #0: 0x00007ff81afde08e libsystem_kernel.dylib`__psynch_cvwait + 10
      frame #1: 0x00007ff81b01a758 libsystem_pthread.dylib`_pthread_cond_wait + 1242
      frame #2: 0x000000010e5fab6c git`fsm_listen__loop(state=0x00007ff7b1ca0420) at fsm-listen-darwin.c:520:2
      frame #3: 0x000000010e2d3d76 git`fsm_listen__thread_proc(_state=0x00007ff7b1ca0420) at fsmonitor--daemon.c:1176:2
      frame #4: 0x00007ff81b01a1d3 libsystem_pthread.dylib`_pthread_start + 125
      frame #5: 0x00007ff81b015bd3 libsystem_pthread.dylib`thread_start + 15

which is in this code:

        FSEventStreamSetDispatchQueue(data->stream, data->dq);
        data->stream_scheduled = 1;

        if (!FSEventStreamStart(data->stream)) {
                error(_("Failed to start the FSEventStream"));
                goto force_error_stop_without_loop;
        }
        data->stream_started = 1;

        pthread_mutex_lock(&data->dq_lock);
        pthread_cond_wait(&data->dq_finished, &data->dq_lock);
	pthread_mutex_unlock(&data->dq_lock);

So if I understand fsmonitor correctly, this is expected: we're waiting
for anybody to single dq_finished to tell us it's time to shut down. And
the real work is happening via that FSEventStreamStart(), which will
asynchronously trigger our callback when something happens in the
working tree.

In which case I don't see any particular deadlock. It's just that
somehow establishing our cookie-wait in the thread servicing the client
raced with there being an actual event to report.

I _think_ I un-stuck things at one point by just touching files in the
working tree, but I'm not 100% sure (I was doing a lot of things, and
it's hard to see when things got unstuck). But that would give evidence
to that line of thinking.

I notice there's a similar hang and fix here:

  https://lore.kernel.org/git/pull.1802.git.1727577690390.gitgitgadget@gmail.com/

but I don't think it's quite the same thing. In our repo there are no
submodules (in fact there are no working tree files at all!).

So I'm not sure where to go from here. It seems like a race, but if so
it happened before I attached the debugger. And I'm not at all familiar
with this code, let alone its timing assumptions. I tried turning on
trace2 logging and re-running (since there are some trace2 event calls
in the code that might help us see it more in action), but doing so
seems to make the race go away. :(

The hanging wait comes from b05880d357 (fsmonitor--daemon: use a cookie
file to sync with file system, 2022-03-25). My understanding is that the
author has retired, but Johannes is listed as a co-author. So any
insight is appreciated. :)

-Peff

Re: fsmonitor deadlock / macOS CI hangs

[Koji Nakamaru]

On Tue, Oct 1, 2024 at 4:46 AM Jeff King <peff@peff.net> wrote:
>
> I did some more digging on the hangs we sometimes see when running the
> test suite on macOS. I'm cc-ing Patrick as somebody who dug into this
> before, and Johannes as the only still-active person mentioned in the
> relevant code.
>
> For those just joining, you can reproduce the issue by running t9211
> with --stress on macOS. Some earlier notes are here:
>
>   https://lore.kernel.org/git/20240517081132.GA1517321@coredump.intra.peff.net/
>
> but the gist of it is that we end up with Git processes waiting to read
> from fsmonitor, but fsmonitor hanging.

Perhaps I found the cause. fsmonitor_run_daemon_1() starts the fsevent
listener thread before with_lock__wait_for_cookie() is called.

      /*
       * Start the fsmonitor listener thread to collect filesystem
       * events.
       */
      if (pthread_create(&state->listener_thread, NULL,
                         fsm_listen__thread_proc, state)) {
              ipc_server_stop_async(state->ipc_server_data);
              err = error(_("could not start fsmonitor listener thread"));
              goto cleanup;
      }
      listener_started = 1;

fsm_listen__thread_proc() starts the following:

      fsm_listen__loop(state);

which is defined as below for darwin:

  void fsm_listen__loop(struct fsmonitor_daemon_state *state)
  {
          struct fsm_listen_data *data;

          data = state->listen_data;

          pthread_mutex_init(&data->dq_lock, NULL);
          pthread_cond_init(&data->dq_finished, NULL);
          data->dq = dispatch_queue_create("FSMonitor", NULL);

          FSEventStreamSetDispatchQueue(data->stream, data->dq);
          data->stream_scheduled = 1;

          if (!FSEventStreamStart(data->stream)) {
                  error(_("Failed to start the FSEventStream"));
                  goto force_error_stop_without_loop;
          }
          data->stream_started = 1;

          ...

Normally FSEventStreamStart() is called before
with_lock__wait_for_cookie() creates a cookie file, but this is not
guaranteed. We can reproduce the issue easily if we modify
fsm_listen__loop() as below:

  --- a/compat/fsmonitor/fsm-listen-darwin.c
  +++ b/compat/fsmonitor/fsm-listen-darwin.c
  @@ -510,6 +510,7 @@ void fsm_listen__loop(struct
fsmonitor_daemon_state *state)
          FSEventStreamSetDispatchQueue(data->stream, data->dq);
          data->stream_scheduled = 1;

  +       sleep(1);
          if (!FSEventStreamStart(data->stream)) {
                  error(_("Failed to start the FSEventStream"));
                  goto force_error_stop_without_loop;


Koji Nakamaru

Re: fsmonitor deadlock / macOS CI hangs

[Jeff King]

On Wed, Oct 02, 2024 at 10:46:03AM +0900, Koji Nakamaru wrote:

> Perhaps I found the cause. fsmonitor_run_daemon_1() starts the fsevent
> Normally FSEventStreamStart() is called before
> with_lock__wait_for_cookie() creates a cookie file, but this is not
> guaranteed. We can reproduce the issue easily if we modify
> fsm_listen__loop() as below:
> 
>   --- a/compat/fsmonitor/fsm-listen-darwin.c
>   +++ b/compat/fsmonitor/fsm-listen-darwin.c
>   @@ -510,6 +510,7 @@ void fsm_listen__loop(struct
> fsmonitor_daemon_state *state)
>           FSEventStreamSetDispatchQueue(data->stream, data->dq);
>           data->stream_scheduled = 1;
> 
>   +       sleep(1);
>           if (!FSEventStreamStart(data->stream)) {
>                   error(_("Failed to start the FSEventStream"));
>                   goto force_error_stop_without_loop;

Ah, good catch. Yes, with that sleep it is much easier to create the
situation in the debugger.

So if I understand (and bear with me if you already know this, but I am
just figuring out how fsmonitor is supposed to work), the expected
order of events is:

  - the thread serving the client creates a cookie file (something like
    ".git/fsmonitor--daemon/cookies/1234-0", based on the pid) and then
    waits for the pthread_cond to be triggered

  - the thread listening for fs events should see that cookie file
    creation, which gets us to with_lock__mark_cookies_seen(), which
    then triggers the cond

But with the sleep, the file creation event happens before the fs event
is actually listening, so we never hear it. We can "unstick" it by
doing:

  # where "1234-0" is the unique cookie file, which you can get by
  # looking at the output from GIT_TRACE_FSMONITOR=1
  echo foo >trash directory.t9211-scalar-clone/cloned/src/.git/fsmonitor--daemon/cookies/1234-0

which then triggers us to mark the cookies seen. I have no clue why
there is this elaborate communication for two threads which are already
sharing a memory space, but let's assume for a moment that it's
required.

The solution then is to avoid letting any client threads run (or at
least create cookies) until we know we're listening for fs events.
Naively I would say we should just have the fs event thread signal us
that it's ready before we spawn any of the client threads. But it looks
like we explicitly start those threads first in fsmonitor_run_daemon_1():

       /*
         * Start the IPC thread pool before the we've started the file
         * system event listener thread so that we have the IPC handle
         * before we need it.
         */
        if (ipc_server_run_async(&state->ipc_server_data,
                                 state->path_ipc.buf, &ipc_opts,
                                 handle_client, state))
                return error_errno(
                        _("could not start IPC thread pool on '%s'"),
                        state->path_ipc.buf);

So I guess we need to let the ipc server initialize itself and then wait
to be told to start serving requests. And then the fs event thread can
trigger that "go ahead" once the fs event stream is started. Which is a
little tricky, but possible with an extra mutex.

But hmm. I wonder if we can hack around it like this:

diff --git a/compat/fsmonitor/fsm-listen-darwin.c b/compat/fsmonitor/fsm-listen-darwin.c
index 2fc6744..6b06faf 100644
--- a/compat/fsmonitor/fsm-listen-darwin.c
+++ b/compat/fsmonitor/fsm-listen-darwin.c
@@ -510,11 +510,17 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
	FSEventStreamSetDispatchQueue(data->stream, data->dq);
	data->stream_scheduled = 1;

+	sleep(1);
	if (!FSEventStreamStart(data->stream)) {
		error(_("Failed to start the FSEventStream"));
		goto force_error_stop_without_loop;
	}
	data->stream_started = 1;
+	/*
+	 * In case any clients showed up before we initialized the event stream,
+	 * abort all in-progress ops and start fresh.
+	 */
+	fsmonitor_force_resync(state);

	pthread_mutex_lock(&data->dq_lock);
	pthread_cond_wait(&data->dq_finished, &data->dq_lock);


The forced resync aborts the cookies, which triggers the waiting
clients. I'm not sure how "bad" it is to do a resync like this. It's
something that can happen in the normal course of events, so in theory
it's just non-optimal and nobody will do the wrong thing. And this would
only happen once at the start of fsmonitor, so in most cases nobody
would have connected yet, and we wouldn't have processed any events.

So I dunno. It does make the hang go away in this case.

-Peff

Re: fsmonitor deadlock / macOS CI hangs

[Koji Nakamaru]

On Wed, Oct 2, 2024 at 3:25 PM Jeff King <peff@peff.net> wrote:
> The solution then is to avoid letting any client threads run (or at
> least create cookies) until we know we're listening for fs events.
> Naively I would say we should just have the fs event thread signal us
> that it's ready before we spawn any of the client threads. But it looks
> like we explicitly start those threads first in fsmonitor_run_daemon_1():

I submitted a fix that followed this approach as it is easy to
understand and should not have any unexpected behaviour. Could you
please check it?

https://lore.kernel.org/git/pull.1804.git.1727862424713.gitgitgadget@gmail.com/

Koji Nakamaru