[PATCH] fsmonitor: fix hangs by delayed fs event listening

[PATCH] fsmonitor: fix hangs by delayed fs event listening

[Koji Nakamaru via GitGitGadget]

From: Koji Nakamaru <koji.nakamaru@gree.net>

The thread serving the client (ipc-thread) calls
with_lock__wait_for_cookie() in which a cookie file is
created. with_lock__wait_for_cookie() then waits for the event caused by
the cookie file from the thread for fs events (fsevent-thread).

However, in high load situations, the fsevent-thread may start actual fs
event listening (triggered by FSEventStreamStart() for Darwin, for
example) *after* the cookie file is created. In this case, the
fsevent-thread cannot detect the cookie file and
with_lock__wait_for_cookie() waits forever, so that the whole daemon
hangs [1].

Extend listen_error_code to express that actual fs event listening
starts. listen_error_code is accessed in a thread-safe manner by
utilizing a dedicated mutex.

[1]: https://lore.kernel.org/git/20241002062539.GA2863841@coredump.intra.peff.net/

Suggested-by: Jeff King <peff@peff.net>
Signed-off-by: Koji Nakamaru <koji.nakamaru@gree.net>
---
    fsmonitor: fix hangs by delayed fs event listening

Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-1804%2FKojiNakamaru%2Ffix%2Ffsmonitor-deadlock-v1
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-1804/KojiNakamaru/fix/fsmonitor-deadlock-v1
Pull-Request: https://github.com/gitgitgadget/git/pull/1804

 builtin/fsmonitor--daemon.c          | 21 +++++++++++++++++++++
 compat/fsmonitor/fsm-listen-darwin.c |  5 +++--
 compat/fsmonitor/fsm-listen-win32.c  |  5 ++---
 fsmonitor--daemon.h                  |  4 ++++
 4 files changed, 30 insertions(+), 5 deletions(-)

diff --git a/builtin/fsmonitor--daemon.c b/builtin/fsmonitor--daemon.c
index dce8a3b2482..ccff2cb8bed 100644
--- a/builtin/fsmonitor--daemon.c
+++ b/builtin/fsmonitor--daemon.c
@@ -172,6 +172,9 @@ static enum fsmonitor_cookie_item_result with_lock__wait_for_cookie(
 	trace_printf_key(&trace_fsmonitor, "cookie-wait: '%s' '%s'",
 			 cookie->name, cookie_pathname.buf);
 
+	while (fsmonitor_get_listen_error_code(state) == 0)
+		sleep_millisec(50);
+
 	/*
 	 * Create the cookie file on disk and then wait for a notification
 	 * that the listener thread has seen it.
@@ -606,6 +609,23 @@ void fsmonitor_force_resync(struct fsmonitor_daemon_state *state)
 	pthread_mutex_unlock(&state->main_lock);
 }
 
+int fsmonitor_get_listen_error_code(struct fsmonitor_daemon_state *state)
+{
+	int error_code;
+
+	pthread_mutex_lock(&state->listen_lock);
+	error_code = state->listen_error_code;
+	pthread_mutex_unlock(&state->listen_lock);
+	return error_code;
+}
+
+void fsmonitor_set_listen_error_code(struct fsmonitor_daemon_state *state, int error_code)
+{
+	pthread_mutex_lock(&state->listen_lock);
+	state->listen_error_code = error_code;
+	pthread_mutex_unlock(&state->listen_lock);
+}
+
 /*
  * Format an opaque token string to send to the client.
  */
@@ -1285,6 +1305,7 @@ static int fsmonitor_run_daemon(void)
 	hashmap_init(&state.cookies, cookies_cmp, NULL, 0);
 	pthread_mutex_init(&state.main_lock, NULL);
 	pthread_cond_init(&state.cookies_cond, NULL);
+	pthread_mutex_init(&state.listen_lock, NULL);
 	state.listen_error_code = 0;
 	state.health_error_code = 0;
 	state.current_token_data = fsmonitor_new_token_data();
diff --git a/compat/fsmonitor/fsm-listen-darwin.c b/compat/fsmonitor/fsm-listen-darwin.c
index 2fc67442eb5..92373ce247f 100644
--- a/compat/fsmonitor/fsm-listen-darwin.c
+++ b/compat/fsmonitor/fsm-listen-darwin.c
@@ -515,6 +515,7 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
 		goto force_error_stop_without_loop;
 	}
 	data->stream_started = 1;
+	fsmonitor_set_listen_error_code(state, 1);
 
 	pthread_mutex_lock(&data->dq_lock);
 	pthread_cond_wait(&data->dq_finished, &data->dq_lock);
@@ -522,7 +523,7 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
 
 	switch (data->shutdown_style) {
 	case FORCE_ERROR_STOP:
-		state->listen_error_code = -1;
+		fsmonitor_set_listen_error_code(state, -1);
 		/* fall thru */
 	case FORCE_SHUTDOWN:
 		ipc_server_stop_async(state->ipc_server_data);
@@ -534,7 +535,7 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
 	return;
 
 force_error_stop_without_loop:
-	state->listen_error_code = -1;
+	fsmonitor_set_listen_error_code(state, -1);
 	ipc_server_stop_async(state->ipc_server_data);
 	return;
 }
diff --git a/compat/fsmonitor/fsm-listen-win32.c b/compat/fsmonitor/fsm-listen-win32.c
index 5a21dade7b8..609efd1d6a8 100644
--- a/compat/fsmonitor/fsm-listen-win32.c
+++ b/compat/fsmonitor/fsm-listen-win32.c
@@ -732,14 +732,13 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
 	DWORD dwWait;
 	int result;
 
-	state->listen_error_code = 0;
-
 	if (start_rdcw_watch(data->watch_worktree) == -1)
 		goto force_error_stop;
 
 	if (data->watch_gitdir &&
 	    start_rdcw_watch(data->watch_gitdir) == -1)
 		goto force_error_stop;
+	fsmonitor_set_listen_error_code(state, 1);
 
 	for (;;) {
 		dwWait = WaitForMultipleObjects(data->nr_listener_handles,
@@ -797,7 +796,7 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
 	}
 
 force_error_stop:
-	state->listen_error_code = -1;
+	fsmonitor_set_listen_error_code(state, -1);
 
 force_shutdown:
 	/*
diff --git a/fsmonitor--daemon.h b/fsmonitor--daemon.h
index 5cbbec8d940..77efc59b7bb 100644
--- a/fsmonitor--daemon.h
+++ b/fsmonitor--daemon.h
@@ -51,6 +51,7 @@ struct fsmonitor_daemon_state {
 	int cookie_seq;
 	struct hashmap cookies;
 
+	pthread_mutex_t listen_lock;
 	int listen_error_code;
 	int health_error_code;
 	struct fsm_listen_data *listen_data;
@@ -167,5 +168,8 @@ void fsmonitor_publish(struct fsmonitor_daemon_state *state,
  */
 void fsmonitor_force_resync(struct fsmonitor_daemon_state *state);
 
+int fsmonitor_get_listen_error_code(struct fsmonitor_daemon_state *state);
+void fsmonitor_set_listen_error_code(struct fsmonitor_daemon_state *state, int error_code);
+
 #endif /* HAVE_FSMONITOR_DAEMON_BACKEND */
 #endif /* FSMONITOR_DAEMON_H */

base-commit: e9356ba3ea2a6754281ff7697b3e5a1697b21e24
-- 
gitgitgadget

Re: [PATCH] fsmonitor: fix hangs by delayed fs event listening

[Jeff King]

On Wed, Oct 02, 2024 at 09:47:04AM +0000, Koji Nakamaru via GitGitGadget wrote:

> From: Koji Nakamaru <koji.nakamaru@gree.net>
> 
> The thread serving the client (ipc-thread) calls
> with_lock__wait_for_cookie() in which a cookie file is
> created. with_lock__wait_for_cookie() then waits for the event caused by
> the cookie file from the thread for fs events (fsevent-thread).
> 
> However, in high load situations, the fsevent-thread may start actual fs
> event listening (triggered by FSEventStreamStart() for Darwin, for
> example) *after* the cookie file is created. In this case, the
> fsevent-thread cannot detect the cookie file and
> with_lock__wait_for_cookie() waits forever, so that the whole daemon
> hangs [1].

First off, thank you for looking into this. I _think_ what you have here
would work, but I had envisioned something a little different. So let me
first try to walk through your solution...

> diff --git a/builtin/fsmonitor--daemon.c b/builtin/fsmonitor--daemon.c
> index dce8a3b2482..ccff2cb8bed 100644
> --- a/builtin/fsmonitor--daemon.c
> +++ b/builtin/fsmonitor--daemon.c
> @@ -172,6 +172,9 @@ static enum fsmonitor_cookie_item_result with_lock__wait_for_cookie(
>  	trace_printf_key(&trace_fsmonitor, "cookie-wait: '%s' '%s'",
>  			 cookie->name, cookie_pathname.buf);
>  
> +	while (fsmonitor_get_listen_error_code(state) == 0)
> +		sleep_millisec(50);
> +
>  	/*
>  	 * Create the cookie file on disk and then wait for a notification
>  	 * that the listener thread has seen it.

OK, so here we're going to basically busy-wait for the error code value
to become non-zero.

That happens in a thread-safe way inside our helper function, and the
matching thread-safe set() is called here:

> diff --git a/compat/fsmonitor/fsm-listen-darwin.c b/compat/fsmonitor/fsm-listen-darwin.c
> index 2fc67442eb5..92373ce247f 100644
> --- a/compat/fsmonitor/fsm-listen-darwin.c
> +++ b/compat/fsmonitor/fsm-listen-darwin.c
> @@ -515,6 +515,7 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
>  		goto force_error_stop_without_loop;
>  	}
>  	data->stream_started = 1;
> +	fsmonitor_set_listen_error_code(state, 1);
>  
>  	pthread_mutex_lock(&data->dq_lock);
>  	pthread_cond_wait(&data->dq_finished, &data->dq_lock);

which then releases all of the waiting clients to start working.

They'd similarly be released on errors such as this one:

> @@ -522,7 +523,7 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
>  
>  	switch (data->shutdown_style) {
>  	case FORCE_ERROR_STOP:
> -		state->listen_error_code = -1;
> +		fsmonitor_set_listen_error_code(state, -1);
>  		/* fall thru */
>  	case FORCE_SHUTDOWN:
>  		ipc_server_stop_async(state->ipc_server_data);

There's some risk that we'd have a code path fails to set the listen
code, in which case our clients might spin forever. But from a cursory
look, I think you've got all spots.

I think your patch has one small bug, which is that you don't
pthread_mutex_destroy() at the end of fsmonitor_run_daemon(). But other
than that I think it should work OK (I haven't tried it in practice yet;
I assume you did?).

My two small-ish complaints are:

  - busy-waiting feels a bit hacky. I think it's not too bad here
    because it only happens during startup (and even then only if we get
    a request) because after that the listen code will already be set to
    "1".

  - the check for the listen code is in the wait_for_cookie() function.
    So even after we've started up, we'll still keep taking a lock to
    check it for every such request. I guess it probably isn't much
    overhead in practice, though.

But what I had envisioned instead was teaching the ipc_server code to
let us control when it starts actually running. We can do that by
holding the existing work lock, and letting the callers (in this case,
the individual fsm backends) tell it when to start operating.

And then we are not introducing a new lock, but rather relying on the
existing lock-checks for getting work to do. So there's no busy-wait.
And after the startup sequence finishes, there are no additional lock
checks.

The patch below implements that. The only complication is that we have
to keep a "started" flag to avoid double-locking during an early
shutdown. Access to the "started" flag is not thread-safe, but I think
that's OK. Until we've started the clients, only the main thread would
do either a start or shutdown operation.

So I dunno. Both solutions have their own little warts, I suppose, and
I'm not sure if one is vastly better than the other.

---
diff --git a/compat/fsmonitor/fsm-listen-darwin.c b/compat/fsmonitor/fsm-listen-darwin.c
index 2fc67442eb..17d0b426e3 100644
--- a/compat/fsmonitor/fsm-listen-darwin.c
+++ b/compat/fsmonitor/fsm-listen-darwin.c
@@ -516,6 +516,12 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
 	}
 	data->stream_started = 1;
 
+	/*
+	 * Our fs event listener is now running, so it's safe to start
+	 * serving client requests.
+	 */
+	ipc_server_start(state->ipc_server_data);
+
 	pthread_mutex_lock(&data->dq_lock);
 	pthread_cond_wait(&data->dq_finished, &data->dq_lock);
 	pthread_mutex_unlock(&data->dq_lock);
diff --git a/compat/fsmonitor/fsm-listen-win32.c b/compat/fsmonitor/fsm-listen-win32.c
index 5a21dade7b..d9a02bc989 100644
--- a/compat/fsmonitor/fsm-listen-win32.c
+++ b/compat/fsmonitor/fsm-listen-win32.c
@@ -741,6 +741,8 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
 	    start_rdcw_watch(data->watch_gitdir) == -1)
 		goto force_error_stop;
 
+	ipc_server_start(state->ipc_server_data);
+
 	for (;;) {
 		dwWait = WaitForMultipleObjects(data->nr_listener_handles,
 						data->hListener,
diff --git a/compat/simple-ipc/ipc-shared.c b/compat/simple-ipc/ipc-shared.c
index cb176d966f..603b60403b 100644
--- a/compat/simple-ipc/ipc-shared.c
+++ b/compat/simple-ipc/ipc-shared.c
@@ -21,6 +21,7 @@ int ipc_server_run(const char *path, const struct ipc_server_opts *opts,
 	if (ret)
 		return ret;
 
+	ipc_server_start(server_data);
 	ret = ipc_server_await(server_data);
 
 	ipc_server_free(server_data);
diff --git a/compat/simple-ipc/ipc-unix-socket.c b/compat/simple-ipc/ipc-unix-socket.c
index 9b3f2cdf8c..9a2e93cff5 100644
--- a/compat/simple-ipc/ipc-unix-socket.c
+++ b/compat/simple-ipc/ipc-unix-socket.c
@@ -328,6 +328,7 @@ struct ipc_server_data {
 	int back_pos;
 	int front_pos;
 
+	int started;
 	int shutdown_requested;
 	int is_stopped;
 };
@@ -888,6 +889,12 @@ int ipc_server_run_async(struct ipc_server_data **returned_server_data,
 	server_data->accept_thread->fd_send_shutdown = sv[0];
 	server_data->accept_thread->fd_wait_shutdown = sv[1];
 
+	/*
+	 * Hold work-available mutex so that no work can start until
+	 * we unlock it.
+	 */
+	pthread_mutex_lock(&server_data->work_available_mutex);
+
 	if (pthread_create(&server_data->accept_thread->pthread_id, NULL,
 			   accept_thread_proc, server_data->accept_thread))
 		die_errno(_("could not start accept_thread '%s'"), path);
@@ -918,6 +925,15 @@ int ipc_server_run_async(struct ipc_server_data **returned_server_data,
 	return 0;
 }
 
+void ipc_server_start(struct ipc_server_data *server_data)
+{
+	if (!server_data || server_data->started)
+		return;
+
+	server_data->started = 1;
+	pthread_mutex_unlock(&server_data->work_available_mutex);
+}
+
 /*
  * Gently tell the IPC server treads to shutdown.
  * Can be run on any thread.
@@ -933,7 +949,9 @@ int ipc_server_stop_async(struct ipc_server_data *server_data)
 
 	trace2_region_enter("ipc-server", "server-stop-async", NULL);
 
-	pthread_mutex_lock(&server_data->work_available_mutex);
+	/* If we haven't started yet, we are already holding lock. */
+	if (!server_data->started)
+		pthread_mutex_lock(&server_data->work_available_mutex);
 
 	server_data->shutdown_requested = 1;
 
diff --git a/simple-ipc.h b/simple-ipc.h
index a849d9f841..764bf7a309 100644
--- a/simple-ipc.h
+++ b/simple-ipc.h
@@ -179,12 +179,21 @@ struct ipc_server_opts
  * When a client IPC message is received, the `application_cb` will be
  * called (possibly on a random thread) to handle the message and
  * optionally compose a reply message.
+ *
+ * This initializes all threads but no actual work will be done until
+ * ipc_server_start() is called.
  */
 int ipc_server_run_async(struct ipc_server_data **returned_server_data,
 			 const char *path, const struct ipc_server_opts *opts,
 			 ipc_server_application_cb *application_cb,
 			 void *application_data);
 
+/*
+ * Let an async server start running. This needs to be called only once
+ * after initialization.
+ */
+void ipc_server_start(struct ipc_server_data *server_data);
+
 /*
  * Gently signal the IPC server pool to shutdown.  No new client
  * connections will be accepted, but existing connections will be

Re: [PATCH] fsmonitor: fix hangs by delayed fs event listening

[Jeff King]

On Mon, Oct 07, 2024 at 01:58:21AM -0400, Jeff King wrote:

> I think your patch has one small bug, which is that you don't
> pthread_mutex_destroy() at the end of fsmonitor_run_daemon(). But other
> than that I think it should work OK (I haven't tried it in practice yet;
> I assume you did?).

I just checked your patch in our CI, using the sleep(1) you suggested
earlier to more predictably lose the race(). It does work reliably (and
I confirmed with some extra trace statements that it does spin on the
sleep_millisec() loop).

I had also previously checked my suggested solution. So I do think
either is a valid solution to the problem.

-Peff

Re: [PATCH] fsmonitor: fix hangs by delayed fs event listening

[Koji Nakamaru]

On Mon, Oct 07, 2024 at 01:58:21AM -0400, Jeff King wrote:
> First off, thank you for looking into this. I _think_ what you have here
> would work, but I had envisioned something a little different. So let me
> first try to walk through your solution...

Thank you very much for looking through my patch in detail and providing
another approach. I agree that busy-waiting is not smart ;) I utilized
it to minimize code modification and not to worry about any new
deadlock. Your approach is more natural if the code is written from
scratch with the problem in mind.

> @@ -933,7 +949,9 @@ int ipc_server_stop_async(struct ipc_server_data *server_data)
>
>       trace2_region_enter("ipc-server", "server-stop-async", NULL);
>
> -     pthread_mutex_lock(&server_data->work_available_mutex);
> +     /* If we haven't started yet, we are already holding lock. */
> +     if (!server_data->started)
> +             pthread_mutex_lock(&server_data->work_available_mutex);
>
>       server_data->shutdown_requested = 1;

Is this condition inverted?

On Mon, Oct 7, 2024 at 3:08 PM Jeff King <peff@peff.net> wrote:
> I just checked your patch in our CI, using the sleep(1) you suggested
> earlier to more predictably lose the race(). It does work reliably (and
> I confirmed with some extra trace statements that it does spin on the
> sleep_millisec() loop).
>
> I had also previously checked my suggested solution. So I do think
> either is a valid solution to the problem.

I also tested your approach on Windows with a few additions to
ipc-win32.c, and it worked correctly.

* define work_available_mutex and started in ipc_server_data.

* call pthread_mutex_lock(&server_data->work_available_mutex) before
creating the server_thread_proc thread.

* define ipc_server_start()

Shall we adopt your approach as it is more natural. Can I ask you to
submit a new patch?

Koji Nakamaru

[PATCH 0/2] alternate approach to fixing fsmonitor hangs

[Jeff King]

On Mon, Oct 07, 2024 at 06:45:22PM +0900, Koji Nakamaru wrote:

> > -     pthread_mutex_lock(&server_data->work_available_mutex);
> > +     /* If we haven't started yet, we are already holding lock. */
> > +     if (!server_data->started)
> > +             pthread_mutex_lock(&server_data->work_available_mutex);
> >
> >       server_data->shutdown_requested = 1;
> 
> Is this condition inverted?

Yes, good catch.

> > I had also previously checked my suggested solution. So I do think
> > either is a valid solution to the problem.
> 
> I also tested your approach on Windows with a few additions to
> ipc-win32.c, and it worked correctly.

Yeah, I never even tried building mine on Windows, and was just testing
via tmate on our macOS CI environment. :-/

I've added in the necessary Windows bits, along with smoothing a few
rough edges. Especially with the extra Windows changes (which I mostly
had to guess-and-check by pushing to CI), I'm beginning to wonder if my
solution isn't getting a bit too complicated, and maybe yours was the
right way after all.

But I've cleaned it up for presentation here, so at least we can look at
the final form of both and see which we prefer.

  [1/2]: simple-ipc: split async server initialization and running
  [2/2]: fsmonitor: initialize fs event listener before accepting clients

 builtin/fsmonitor--daemon.c          |  6 ++--
 compat/fsmonitor/fsm-listen-darwin.c |  6 ++++
 compat/fsmonitor/fsm-listen-win32.c  |  6 ++++
 compat/simple-ipc/ipc-shared.c       |  5 +--
 compat/simple-ipc/ipc-unix-socket.c  | 28 +++++++++++++---
 compat/simple-ipc/ipc-win32.c        | 48 +++++++++++++++++++++++++---
 simple-ipc.h                         | 17 +++++++---
 7 files changed, 98 insertions(+), 18 deletions(-)

-Peff

[PATCH 1/2] simple-ipc: split async server initialization and running

[Jeff King]

To start an async ipc server, you call ipc_server_run_async(). That
initializes the ipc_server_data object, and starts all of the threads
running, which may immediately start serving clients.

This can create some awkward timing problems, though. In the fsmonitor
daemon (the sole user of the simple-ipc system), we want to create the
ipc server early in the process, which means we may start serving
clients before the rest of the daemon is fully initialized.

To solve this, let's break run_async() into two parts: an initialization
which allocates all data and spawns the threads (without letting them
run), and a start function which actually lets them begin work. Since we
have two simple-ipc implementations, we have to handle this twice:

  - in ipc-unix-socket.c, we have a central listener thread which hands
    connections off to worker threads using a work_available mutex. We
    can hold that mutex after init, and release it when we're ready to
    start.

    We do need an extra "started" flag so that we know whether the main
    thread is holding the mutex or not (e.g., if we prematurely stop the
    server, we want to make sure all of the worker threads are released
    to hear about the shutdown).

  - in ipc-win32.c, we don't have a central mutex. So we'll introduce a
    new startup_barrier mutex, which we'll similarly hold until we're
    ready to let the threads proceed.

    We again need a "started" flag here to make sure that we release the
    barrier mutex when shutting down, so that the sub-threads can
    proceed to the finish.

I've renamed the run_async() function to init_async() to make sure we
catch all callers, since they'll now need to call the matching
start_async().

We could leave run_async() as a wrapper that does both, but there's not
much point. There are only two callers, one of which is fsmonitor, which
will want to actually do work between the two calls. And the other is
just a test-tool wrapper.

For now I've added the start_async() calls in fsmonitor where they would
otherwise have happened, so there should be no behavior change with this
patch.

Signed-off-by: Jeff King <peff@peff.net>
---
 builtin/fsmonitor--daemon.c         |  8 +++--
 compat/simple-ipc/ipc-shared.c      |  5 +--
 compat/simple-ipc/ipc-unix-socket.c | 28 ++++++++++++++---
 compat/simple-ipc/ipc-win32.c       | 48 ++++++++++++++++++++++++++---
 simple-ipc.h                        | 17 +++++++---
 5 files changed, 88 insertions(+), 18 deletions(-)

diff --git a/builtin/fsmonitor--daemon.c b/builtin/fsmonitor--daemon.c
index e1e6b96d09..4a077810d0 100644
--- a/builtin/fsmonitor--daemon.c
+++ b/builtin/fsmonitor--daemon.c
@@ -1208,13 +1208,15 @@ static int fsmonitor_run_daemon_1(struct fsmonitor_daemon_state *state)
 	 * 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))
+	if (ipc_server_init_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);
 
+	ipc_server_start_async(&state->ipc_server_data);
+
 	/*
 	 * Start the fsmonitor listener thread to collect filesystem
 	 * events.
diff --git a/compat/simple-ipc/ipc-shared.c b/compat/simple-ipc/ipc-shared.c
index cb176d966f..d1c21b49bd 100644
--- a/compat/simple-ipc/ipc-shared.c
+++ b/compat/simple-ipc/ipc-shared.c
@@ -16,11 +16,12 @@ int ipc_server_run(const char *path, const struct ipc_server_opts *opts,
 	struct ipc_server_data *server_data = NULL;
 	int ret;
 
-	ret = ipc_server_run_async(&server_data, path, opts,
-				   application_cb, application_data);
+	ret = ipc_server_init_async(&server_data, path, opts,
+				    application_cb, application_data);
 	if (ret)
 		return ret;
 
+	ipc_server_start_async(server_data);
 	ret = ipc_server_await(server_data);
 
 	ipc_server_free(server_data);
diff --git a/compat/simple-ipc/ipc-unix-socket.c b/compat/simple-ipc/ipc-unix-socket.c
index 9b3f2cdf8c..57d919c6b4 100644
--- a/compat/simple-ipc/ipc-unix-socket.c
+++ b/compat/simple-ipc/ipc-unix-socket.c
@@ -328,6 +328,7 @@ struct ipc_server_data {
 	int back_pos;
 	int front_pos;
 
+	int started;
 	int shutdown_requested;
 	int is_stopped;
 };
@@ -824,10 +825,10 @@ static int setup_listener_socket(
 /*
  * Start IPC server in a pool of background threads.
  */
-int ipc_server_run_async(struct ipc_server_data **returned_server_data,
-			 const char *path, const struct ipc_server_opts *opts,
-			 ipc_server_application_cb *application_cb,
-			 void *application_data)
+int ipc_server_init_async(struct ipc_server_data **returned_server_data,
+			  const char *path, const struct ipc_server_opts *opts,
+			  ipc_server_application_cb *application_cb,
+			  void *application_data)
 {
 	struct unix_ss_socket *server_socket = NULL;
 	struct ipc_server_data *server_data;
@@ -888,6 +889,12 @@ int ipc_server_run_async(struct ipc_server_data **returned_server_data,
 	server_data->accept_thread->fd_send_shutdown = sv[0];
 	server_data->accept_thread->fd_wait_shutdown = sv[1];
 
+	/*
+	 * Hold work-available mutex so that no work can start until
+	 * we unlock it.
+	 */
+	pthread_mutex_lock(&server_data->work_available_mutex);
+
 	if (pthread_create(&server_data->accept_thread->pthread_id, NULL,
 			   accept_thread_proc, server_data->accept_thread))
 		die_errno(_("could not start accept_thread '%s'"), path);
@@ -918,6 +925,15 @@ int ipc_server_run_async(struct ipc_server_data **returned_server_data,
 	return 0;
 }
 
+void ipc_server_start_async(struct ipc_server_data *server_data)
+{
+	if (!server_data || server_data->started)
+		return;
+
+	server_data->started = 1;
+	pthread_mutex_unlock(&server_data->work_available_mutex);
+}
+
 /*
  * Gently tell the IPC server treads to shutdown.
  * Can be run on any thread.
@@ -933,7 +949,9 @@ int ipc_server_stop_async(struct ipc_server_data *server_data)
 
 	trace2_region_enter("ipc-server", "server-stop-async", NULL);
 
-	pthread_mutex_lock(&server_data->work_available_mutex);
+	/* If we haven't started yet, we are already holding lock. */
+	if (server_data->started)
+		pthread_mutex_lock(&server_data->work_available_mutex);
 
 	server_data->shutdown_requested = 1;
 
diff --git a/compat/simple-ipc/ipc-win32.c b/compat/simple-ipc/ipc-win32.c
index 8bfe51248e..a8fc812adf 100644
--- a/compat/simple-ipc/ipc-win32.c
+++ b/compat/simple-ipc/ipc-win32.c
@@ -371,6 +371,9 @@ struct ipc_server_data {
 	HANDLE hEventStopRequested;
 	struct ipc_server_thread_data *thread_list;
 	int is_stopped;
+
+	pthread_mutex_t startup_barrier;
+	int started;
 };
 
 enum connect_result {
@@ -526,6 +529,16 @@ static int use_connection(struct ipc_server_thread_data *server_thread_data)
 	return ret;
 }
 
+static void wait_for_startup_barrier(struct ipc_server_data *server_data)
+{
+	/*
+	 * Temporarily hold the startup_barrier mutex before starting,
+	 * which lets us know that it's OK to start serving requests.
+	 */
+	pthread_mutex_lock(&server_data->startup_barrier);
+	pthread_mutex_unlock(&server_data->startup_barrier);
+}
+
 /*
  * Thread proc for an IPC server worker thread.  It handles a series of
  * connections from clients.  It cleans and reuses the hPipe between each
@@ -550,6 +563,8 @@ static void *server_thread_proc(void *_server_thread_data)
 	memset(&oConnect, 0, sizeof(oConnect));
 	oConnect.hEvent = hEventConnected;
 
+	wait_for_startup_barrier(server_thread_data->server_data);
+
 	for (;;) {
 		cr = wait_for_connection(server_thread_data, &oConnect);
 
@@ -752,10 +767,10 @@ static HANDLE create_new_pipe(wchar_t *wpath, int is_first)
 	return hPipe;
 }
 
-int ipc_server_run_async(struct ipc_server_data **returned_server_data,
-			 const char *path, const struct ipc_server_opts *opts,
-			 ipc_server_application_cb *application_cb,
-			 void *application_data)
+int ipc_server_init_async(struct ipc_server_data **returned_server_data,
+			  const char *path, const struct ipc_server_opts *opts,
+			  ipc_server_application_cb *application_cb,
+			  void *application_data)
 {
 	struct ipc_server_data *server_data;
 	wchar_t wpath[MAX_PATH];
@@ -787,6 +802,13 @@ int ipc_server_run_async(struct ipc_server_data **returned_server_data,
 	strbuf_addstr(&server_data->buf_path, path);
 	wcscpy(server_data->wpath, wpath);
 
+	/*
+	 * Hold the startup_barrier lock so that no threads will progress
+	 * until ipc_server_start_async() is called.
+	 */
+	pthread_mutex_init(&server_data->startup_barrier, NULL);
+	pthread_mutex_lock(&server_data->startup_barrier);
+
 	if (nr_threads < 1)
 		nr_threads = 1;
 
@@ -837,6 +859,15 @@ int ipc_server_run_async(struct ipc_server_data **returned_server_data,
 	return 0;
 }
 
+void ipc_server_start_async(struct ipc_server_data *server_data)
+{
+	if (!server_data || server_data->started)
+		return;
+
+	server_data->started = 1;
+	pthread_mutex_unlock(&server_data->startup_barrier);
+}
+
 int ipc_server_stop_async(struct ipc_server_data *server_data)
 {
 	if (!server_data)
@@ -850,6 +881,13 @@ int ipc_server_stop_async(struct ipc_server_data *server_data)
 	 * We DO NOT attempt to force them to drop an active connection.
 	 */
 	SetEvent(server_data->hEventStopRequested);
+
+	/*
+	 * If we haven't yet told the threads they are allowed to run,
+	 * do so now, so they can receive the shutdown event.
+	 */
+	ipc_server_start_async(server_data);
+
 	return 0;
 }
 
@@ -900,5 +938,7 @@ void ipc_server_free(struct ipc_server_data *server_data)
 		free(std);
 	}
 
+	pthread_mutex_destroy(&server_data->startup_barrier);
+
 	free(server_data);
 }
diff --git a/simple-ipc.h b/simple-ipc.h
index a849d9f841..3916eaf70d 100644
--- a/simple-ipc.h
+++ b/simple-ipc.h
@@ -179,11 +179,20 @@ struct ipc_server_opts
  * When a client IPC message is received, the `application_cb` will be
  * called (possibly on a random thread) to handle the message and
  * optionally compose a reply message.
+ *
+ * This initializes all threads but no actual work will be done until
+ * ipc_server_start_async() is called.
+ */
+int ipc_server_init_async(struct ipc_server_data **returned_server_data,
+			  const char *path, const struct ipc_server_opts *opts,
+			  ipc_server_application_cb *application_cb,
+			  void *application_data);
+
+/*
+ * Let an async server start running. This needs to be called only once
+ * after initialization.
  */
-int ipc_server_run_async(struct ipc_server_data **returned_server_data,
-			 const char *path, const struct ipc_server_opts *opts,
-			 ipc_server_application_cb *application_cb,
-			 void *application_data);
+void ipc_server_start_async(struct ipc_server_data *server_data);
 
 /*
  * Gently signal the IPC server pool to shutdown.  No new client
-- 
2.47.0.427.g067ae60d0d

[PATCH 2/2] fsmonitor: initialize fs event listener before accepting clients

[Jeff King]

There's a racy hang in fsmonitor on macOS that we sometimes see in CI.
When we serve a client, what's supposed to happen is:

  1. The client thread calls with_lock__wait_for_cookie() in which we
     create a cookie file and then wait for a pthread_cond event

  2. The filesystem event listener sees the cookie file creation, does
     some internal book-keeping, and then triggers the pthread_cond.

But there's a problem: we start the listener that accepts client threads
before we start the fs event thread. So it's possible for us to accept a
client which creates the cookie file and starts waiting before the fs
event thread is initialized, and we miss those filesystem events
entirely. That leaves the client thread hanging forever.

In CI, the symptom is that t9210 (which is testing scalar, which always
enables fsmonitor under the hood) may hang forever in "scalar clone". It
is waiting on "git fetch" which is waiting on the fsmonitor daemon.

The race happens more frequently under load, but you can trigger it
predictably with a sleep like this, which delays the start of the fs
event thread:

  --- 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;

One solution might be to reverse the order of initialization: start the
fs event thread before we start the thread listening for clients. But
the fsmonitor code explicitly does it in the opposite direction. The fs
event thread wants to refer to the ipc_server_data struct, so we need it
to be initialized first.

A further complication is that we need a signal from the fs event thread
that it is actually ready and listening. And those details happen within
backend-specific fsmonitor code, whereas the initialization is in the
shared code.

So instead, let's use the ipc_server init/start split added in the
previous commit. The generic fsmonitor code will init the ipc_server but
_not_ start it, leaving that to the backend specific code, which now
needs to call ipc_server_start_async() at the right time.

For macOS, that is right after we start the FSEventStream that you can
see in the diff above.

It's not clear to me if Windows suffers from the same problem (and we
simply don't trigger it in CI), or if it is immune. Regardless, the
obvious place to start accepting clients there is right after we've
established the ReadDirectoryChanges watch.

This makes the hangs go away in our macOS CI environment, even when
compiled with the sleep() above.

Helped-by: Koji Nakamaru <koji.nakamaru@gree.net>
Signed-off-by: Jeff King <peff@peff.net>
---
 builtin/fsmonitor--daemon.c          | 2 --
 compat/fsmonitor/fsm-listen-darwin.c | 6 ++++++
 compat/fsmonitor/fsm-listen-win32.c  | 6 ++++++
 3 files changed, 12 insertions(+), 2 deletions(-)

diff --git a/builtin/fsmonitor--daemon.c b/builtin/fsmonitor--daemon.c
index 4a077810d0..f3f6bd330b 100644
--- a/builtin/fsmonitor--daemon.c
+++ b/builtin/fsmonitor--daemon.c
@@ -1215,8 +1215,6 @@ static int fsmonitor_run_daemon_1(struct fsmonitor_daemon_state *state)
 			_("could not start IPC thread pool on '%s'"),
 			state->path_ipc.buf);
 
-	ipc_server_start_async(&state->ipc_server_data);
-
 	/*
 	 * Start the fsmonitor listener thread to collect filesystem
 	 * events.
diff --git a/compat/fsmonitor/fsm-listen-darwin.c b/compat/fsmonitor/fsm-listen-darwin.c
index 2fc67442eb..dfa551459d 100644
--- a/compat/fsmonitor/fsm-listen-darwin.c
+++ b/compat/fsmonitor/fsm-listen-darwin.c
@@ -516,6 +516,12 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
 	}
 	data->stream_started = 1;
 
+	/*
+	 * Our fs event listener is now running, so it's safe to start
+	 * serving client requests.
+	 */
+	ipc_server_start_async(state->ipc_server_data);
+
 	pthread_mutex_lock(&data->dq_lock);
 	pthread_cond_wait(&data->dq_finished, &data->dq_lock);
 	pthread_mutex_unlock(&data->dq_lock);
diff --git a/compat/fsmonitor/fsm-listen-win32.c b/compat/fsmonitor/fsm-listen-win32.c
index 5a21dade7b..80e092b511 100644
--- a/compat/fsmonitor/fsm-listen-win32.c
+++ b/compat/fsmonitor/fsm-listen-win32.c
@@ -741,6 +741,12 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)
 	    start_rdcw_watch(data->watch_gitdir) == -1)
 		goto force_error_stop;
 
+	/*
+	 * Now that we've established the rdcw watches, we can start
+	 * serving clients.
+	 */
+	ipc_server_start_async(state->ipc_server_data);
+
 	for (;;) {
 		dwWait = WaitForMultipleObjects(data->nr_listener_handles,
 						data->hListener,
-- 
2.47.0.427.g067ae60d0d

Re: [PATCH 0/2] alternate approach to fixing fsmonitor hangs

[Koji Nakamaru]

On Tue, Oct 8, 2024 at 5:31 PM Jeff King <peff@peff.net> wrote:
> I've added in the necessary Windows bits, along with smoothing a few
> rough edges. Especially with the extra Windows changes (which I mostly
> had to guess-and-check by pushing to CI), I'm beginning to wonder if my
> solution isn't getting a bit too complicated, and maybe yours was the
> right way after all.
>
> But I've cleaned it up for presentation here, so at least we can look at
> the final form of both and see which we prefer.

Thank you for the new patch. It prevents to start accepting requests
until starting fs event listening and simplifies the code flow. It also
has sufficient comments, so later everyone can easily understand how it
works. I also tested it both on mac and windows and it works correctly.

I think this one should be adopted :)

Koji Nakamaru

Re: [PATCH 0/2] alternate approach to fixing fsmonitor hangs

[Jeff King]

On Wed, Oct 09, 2024 at 01:03:14AM +0900, Koji Nakamaru wrote:

> > But I've cleaned it up for presentation here, so at least we can look at
> > the final form of both and see which we prefer.
> 
> Thank you for the new patch. It prevents to start accepting requests
> until starting fs event listening and simplifies the code flow. It also
> has sufficient comments, so later everyone can easily understand how it
> works. I also tested it both on mac and windows and it works correctly.
> 
> I think this one should be adopted :)

Thanks for reviewing, and for all your work identifying the problem in
the first place! Looks like Junio has picked up my patch and it's
already in 'next', so hopefully these 6-hour CI timeouts will soon be a
thing of the past. :)

-Peff

Re: [PATCH 0/2] alternate approach to fixing fsmonitor hangs

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> On Wed, Oct 09, 2024 at 01:03:14AM +0900, Koji Nakamaru wrote:
>
>> > But I've cleaned it up for presentation here, so at least we can look at
>> > the final form of both and see which we prefer.
>> 
>> Thank you for the new patch. It prevents to start accepting requests
>> until starting fs event listening and simplifies the code flow. It also
>> has sufficient comments, so later everyone can easily understand how it
>> works. I also tested it both on mac and windows and it works correctly.
>> 
>> I think this one should be adopted :)
>
> Thanks for reviewing, and for all your work identifying the problem in
> the first place! Looks like Junio has picked up my patch and it's
> already in 'next', so hopefully these 6-hour CI timeouts will soon be a
> thing of the past. :)

Yup.  Thanks, both of you.