{"thread":{"id":"62219","subject":"fsmonitor deadlock / macOS CI hangs","startedAt":"2024-09-30T19:46:02Z","lastAt":"2024-10-02T09:51:13Z","messageCount":4,"participants":["Jeff King","Koji Nakamaru"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"503765","messageId":"20240930194600.GA1805534@coredump.intra.peff.net","threadId":"62219","inReplyTo":null,"subject":"fsmonitor deadlock / macOS CI hangs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-09-30T19:46:00Z","receivedAt":"2024-09-30T19:46:02Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"I did some more digging on the hangs we sometimes see when running the\ntest suite on macOS. I'm cc-ing Patrick as somebody who dug into this\nbefore, and Johannes as the only still-active person mentioned in the\nrelevant code.\n\nFor those just joining, you can reproduce the issue by running t9211\nwith --stress on macOS. Some earlier notes are here:\n\n  https://lore.kernel.org/git/20240517081132.GA1517321@coredump.intra.peff.net/\n\nbut the gist of it is that we end up with Git processes waiting to read\nfrom fsmonitor, but fsmonitor hanging.\n\nSince then, I swapped out gdb for lldb, which let me see a bit more of\nwho is doing what.\n\nThe test is waiting on a \"scalar\" process to exit. But that's just in\nwait_or_whine() waiting for git-fetch to exit. That git-fetch is in turn\nwaiting to read() from fsmonitor after sending a command. Here's the\nbacktrace:\n\n    * frame #0: 0x00007ff81afdbf7e libsystem_kernel.dylib`read + 10\n      frame #1: 0x000000010a4fa6ae git`xread(fd=8, buf=0x00007ff7b5d82188, len=4) at wrapper.c:231:8\n      frame #2: 0x000000010a4fa8de git`read_in_full(fd=8, buf=0x00007ff7b5d82188, count=4) at wrapper.c:289:20\n      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\n      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\n      frame #5: 0x000000010a4178bb git`packet_read(fd=8, buffer=\"\", size=65517, options=9) at pkt-line.c:519:2\n      frame #6: 0x000000010a417a07 git`read_packetized_to_strbuf(fd_in=8, sb_out=0x00007ff7b5d82380, options=9) at pkt-line.c:554:16\n      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\n      frame #8: 0x000000010a377553 git`fsmonitor_ipc__send_query(since_token=\"1727469801286015000\", answer=0x00007ff7b5d82380) at fsmonitor-ipc.c:94:9\n      frame #9: 0x000000010a376149 git`refresh_fsmonitor(istate=0x0000600002910300) at fsmonitor.c:536:20\n      frame #10: 0x000000010a376be7 git`add_fsmonitor(istate=0x0000600002910300) at fsmonitor.c:778:3\n      frame #11: 0x000000010a376e19 git`tweak_fsmonitor(istate=0x0000600002910300) at fsmonitor.c:818:3\n      frame #12: 0x000000010a430840 git`post_read_index_from(istate=0x0000600002910300) at read-cache.c:1968:2\n\nIn fsmonitor we have a bunch of threads. The main thread is waiting on\nworker threads, which I think is expected:\n\n  * thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP\n      frame #0: 0x00007ff81afdccce libsystem_kernel.dylib`__ulock_wait + 10\n      frame #1: 0x00007ff81b01b9b9 libsystem_pthread.dylib`_pthread_join + 348\n    * frame #2: 0x000000010e5ec2b1 git`ipc_server_await(server_data=0x0000600002790000) at ipc-unix-socket.c:971:2\n      frame #3: 0x000000010e2d3a3f git`fsmonitor_run_daemon_1(state=0x00007ff7b1ca0420) at fsmonitor--daemon.c:1251:2\n      frame #4: 0x000000010e2d35c5 git`fsmonitor_run_daemon at fsmonitor--daemon.c:1399:8\n\nMost of the other threads are just waiting for clients:\n\n  * thread #2\n    * frame #0: 0x00007ff81afe2242 libsystem_kernel.dylib`poll + 10\n      frame #1: 0x000000010e5ec664 git`accept_thread__wait_for_connection(accept_thread_data=0x000060000129c000) at ipc-unix-socket.c:653:12\n      frame #2: 0x000000010e5ebf2a git`accept_thread_proc(_accept_thread_data=0x000060000129c000) at ipc-unix-socket.c:728:19\n      frame #3: 0x00007ff81b01a1d3 libsystem_pthread.dylib`_pthread_start + 125\n      frame #4: 0x00007ff81b015bd3 libsystem_pthread.dylib`thread_start + 15\n\nwhich I think is again expected. But not this one, which should be\nserving our command:\n\n  * thread #3\n    * frame #0: 0x00007ff81afde08e libsystem_kernel.dylib`__psynch_cvwait + 10\n      frame #1: 0x00007ff81b01a758 libsystem_pthread.dylib`_pthread_cond_wait + 1242\n      frame #2: 0x000000010e2d4a90 git`with_lock__wait_for_cookie(state=0x00007ff7b1ca0420) at fsmonitor--daemon.c:209:3\n      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\n      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\n      frame #5: 0x000000010e5ecaa7 git`worker_thread__do_io(worker_thread_data=0x0000600001c9c000, fd=23) at ipc-unix-socket.c:531:9\n      frame #6: 0x000000010e5ec056 git`worker_thread_proc(_worker_thread_data=0x0000600001c9c000) at ipc-unix-socket.c:605:9\n      frame #7: 0x00007ff81b01a1d3 libsystem_pthread.dylib`_pthread_start + 125\n\nWe got that same command from git-fetch, but we're hanging on a pthread\noperation. It's this one, and note the suspicious comment:\n\n          /*\n           * Technically, this is an infinite wait (well, unless another\n           * thread sends us an abort).  I'd like to change this to\n           * use `pthread_cond_timedwait()` and return an error/timeout\n           * and let the caller do the trivial response thing, but we\n           * don't have that routine in our thread-utils.\n           *\n           * After extensive beta testing I'm not really worried about\n           * this.  Also note that the above open() and unlink() calls\n           * will cause at least two FS events on that path, so the odds\n           * of getting stuck are pretty slim.\n           */\n          while (cookie->result == FCIR_INIT)\n                  pthread_cond_wait(&state->cookies_cond,\n                                    &state->main_lock);\n\nSo we're waiting for somebody to trigger the cookies_cond. Who's\nsupposed to do that? It's done in fsmonitor_publish(), which is\ntriggered when we actually see filesystem events. The main listening\nloop is also waiting on a pthread cond:\n\n  * thread #11\n    * frame #0: 0x00007ff81afde08e libsystem_kernel.dylib`__psynch_cvwait + 10\n      frame #1: 0x00007ff81b01a758 libsystem_pthread.dylib`_pthread_cond_wait + 1242\n      frame #2: 0x000000010e5fab6c git`fsm_listen__loop(state=0x00007ff7b1ca0420) at fsm-listen-darwin.c:520:2\n      frame #3: 0x000000010e2d3d76 git`fsm_listen__thread_proc(_state=0x00007ff7b1ca0420) at fsmonitor--daemon.c:1176:2\n      frame #4: 0x00007ff81b01a1d3 libsystem_pthread.dylib`_pthread_start + 125\n      frame #5: 0x00007ff81b015bd3 libsystem_pthread.dylib`thread_start + 15\n\nwhich is in this code:\n\n        FSEventStreamSetDispatchQueue(data->stream, data->dq);\n        data->stream_scheduled = 1;\n\n        if (!FSEventStreamStart(data->stream)) {\n                error(_(\"Failed to start the FSEventStream\"));\n                goto force_error_stop_without_loop;\n        }\n        data->stream_started = 1;\n\n        pthread_mutex_lock(&data->dq_lock);\n        pthread_cond_wait(&data->dq_finished, &data->dq_lock);\n\tpthread_mutex_unlock(&data->dq_lock);\n\nSo if I understand fsmonitor correctly, this is expected: we're waiting\nfor anybody to single dq_finished to tell us it's time to shut down. And\nthe real work is happening via that FSEventStreamStart(), which will\nasynchronously trigger our callback when something happens in the\nworking tree.\n\nIn which case I don't see any particular deadlock. It's just that\nsomehow establishing our cookie-wait in the thread servicing the client\nraced with there being an actual event to report.\n\nI _think_ I un-stuck things at one point by just touching files in the\nworking tree, but I'm not 100% sure (I was doing a lot of things, and\nit's hard to see when things got unstuck). But that would give evidence\nto that line of thinking.\n\nI notice there's a similar hang and fix here:\n\n  https://lore.kernel.org/git/pull.1802.git.1727577690390.gitgitgadget@gmail.com/\n\nbut I don't think it's quite the same thing. In our repo there are no\nsubmodules (in fact there are no working tree files at all!).\n\nSo I'm not sure where to go from here. It seems like a race, but if so\nit happened before I attached the debugger. And I'm not at all familiar\nwith this code, let alone its timing assumptions. I tried turning on\ntrace2 logging and re-running (since there are some trace2 event calls\nin the code that might help us see it more in action), but doing so\nseems to make the race go away. :(\n\nThe hanging wait comes from b05880d357 (fsmonitor--daemon: use a cookie\nfile to sync with file system, 2022-03-25). My understanding is that the\nauthor has retired, but Johannes is listed as a co-author. So any\ninsight is appreciated. :)\n\n-Peff\n"},{"id":"503881","messageId":"CAOTNsDykrEBGBnQJqmCghWBTgzirxHZQM25ohsCBysp8ZO1qLg@mail.gmail.com","threadId":"62219","inReplyTo":"20240930194600.GA1805534@coredump.intra.peff.net","subject":"Re: fsmonitor deadlock / macOS CI hangs","fromName":"Koji Nakamaru","fromEmail":"koji.nakamaru@gree.net","sentAt":"2024-10-02T01:46:03Z","receivedAt":"2024-10-02T01:46:16Z","isPatch":false,"sender":{"key":"koji.nakamaru@gree.net","avatar":"https://avatars.githubusercontent.com/u/2645978?v=4"},"body":"On Tue, Oct 1, 2024 at 4:46 AM Jeff King <peff@peff.net> wrote:\n>\n> I did some more digging on the hangs we sometimes see when running the\n> test suite on macOS. I'm cc-ing Patrick as somebody who dug into this\n> before, and Johannes as the only still-active person mentioned in the\n> relevant code.\n>\n> For those just joining, you can reproduce the issue by running t9211\n> with --stress on macOS. Some earlier notes are here:\n>\n>   https://lore.kernel.org/git/20240517081132.GA1517321@coredump.intra.peff.net/\n>\n> but the gist of it is that we end up with Git processes waiting to read\n> from fsmonitor, but fsmonitor hanging.\n\nPerhaps I found the cause. fsmonitor_run_daemon_1() starts the fsevent\nlistener thread before with_lock__wait_for_cookie() is called.\n\n      /*\n       * Start the fsmonitor listener thread to collect filesystem\n       * events.\n       */\n      if (pthread_create(&state->listener_thread, NULL,\n                         fsm_listen__thread_proc, state)) {\n              ipc_server_stop_async(state->ipc_server_data);\n              err = error(_(\"could not start fsmonitor listener thread\"));\n              goto cleanup;\n      }\n      listener_started = 1;\n\nfsm_listen__thread_proc() starts the following:\n\n      fsm_listen__loop(state);\n\nwhich is defined as below for darwin:\n\n  void fsm_listen__loop(struct fsmonitor_daemon_state *state)\n  {\n          struct fsm_listen_data *data;\n\n          data = state->listen_data;\n\n          pthread_mutex_init(&data->dq_lock, NULL);\n          pthread_cond_init(&data->dq_finished, NULL);\n          data->dq = dispatch_queue_create(\"FSMonitor\", NULL);\n\n          FSEventStreamSetDispatchQueue(data->stream, data->dq);\n          data->stream_scheduled = 1;\n\n          if (!FSEventStreamStart(data->stream)) {\n                  error(_(\"Failed to start the FSEventStream\"));\n                  goto force_error_stop_without_loop;\n          }\n          data->stream_started = 1;\n\n          ...\n\nNormally FSEventStreamStart() is called before\nwith_lock__wait_for_cookie() creates a cookie file, but this is not\nguaranteed. We can reproduce the issue easily if we modify\nfsm_listen__loop() as below:\n\n  --- a/compat/fsmonitor/fsm-listen-darwin.c\n  +++ b/compat/fsmonitor/fsm-listen-darwin.c\n  @@ -510,6 +510,7 @@ void fsm_listen__loop(struct\nfsmonitor_daemon_state *state)\n          FSEventStreamSetDispatchQueue(data->stream, data->dq);\n          data->stream_scheduled = 1;\n\n  +       sleep(1);\n          if (!FSEventStreamStart(data->stream)) {\n                  error(_(\"Failed to start the FSEventStream\"));\n                  goto force_error_stop_without_loop;\n\n\nKoji Nakamaru\n"},{"id":"503889","messageId":"20241002062539.GA2863841@coredump.intra.peff.net","threadId":"62219","inReplyTo":"CAOTNsDykrEBGBnQJqmCghWBTgzirxHZQM25ohsCBysp8ZO1qLg@mail.gmail.com","subject":"Re: fsmonitor deadlock / macOS CI hangs","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2024-10-02T06:25:39Z","receivedAt":"2024-10-02T06:25:40Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Oct 02, 2024 at 10:46:03AM +0900, Koji Nakamaru wrote:\n\n> Perhaps I found the cause. fsmonitor_run_daemon_1() starts the fsevent\n> Normally FSEventStreamStart() is called before\n> with_lock__wait_for_cookie() creates a cookie file, but this is not\n> guaranteed. We can reproduce the issue easily if we modify\n> fsm_listen__loop() as below:\n> \n>   --- a/compat/fsmonitor/fsm-listen-darwin.c\n>   +++ b/compat/fsmonitor/fsm-listen-darwin.c\n>   @@ -510,6 +510,7 @@ void fsm_listen__loop(struct\n> fsmonitor_daemon_state *state)\n>           FSEventStreamSetDispatchQueue(data->stream, data->dq);\n>           data->stream_scheduled = 1;\n> \n>   +       sleep(1);\n>           if (!FSEventStreamStart(data->stream)) {\n>                   error(_(\"Failed to start the FSEventStream\"));\n>                   goto force_error_stop_without_loop;\n\nAh, good catch. Yes, with that sleep it is much easier to create the\nsituation in the debugger.\n\nSo if I understand (and bear with me if you already know this, but I am\njust figuring out how fsmonitor is supposed to work), the expected\norder of events is:\n\n  - the thread serving the client creates a cookie file (something like\n    \".git/fsmonitor--daemon/cookies/1234-0\", based on the pid) and then\n    waits for the pthread_cond to be triggered\n\n  - the thread listening for fs events should see that cookie file\n    creation, which gets us to with_lock__mark_cookies_seen(), which\n    then triggers the cond\n\nBut with the sleep, the file creation event happens before the fs event\nis actually listening, so we never hear it. We can \"unstick\" it by\ndoing:\n\n  # where \"1234-0\" is the unique cookie file, which you can get by\n  # looking at the output from GIT_TRACE_FSMONITOR=1\n  echo foo >trash directory.t9211-scalar-clone/cloned/src/.git/fsmonitor--daemon/cookies/1234-0\n\nwhich then triggers us to mark the cookies seen. I have no clue why\nthere is this elaborate communication for two threads which are already\nsharing a memory space, but let's assume for a moment that it's\nrequired.\n\nThe solution then is to avoid letting any client threads run (or at\nleast create cookies) until we know we're listening for fs events.\nNaively I would say we should just have the fs event thread signal us\nthat it's ready before we spawn any of the client threads. But it looks\nlike we explicitly start those threads first in fsmonitor_run_daemon_1():\n\n       /*\n         * Start the IPC thread pool before the we've started the file\n         * system event listener thread so that we have the IPC handle\n         * before we need it.\n         */\n        if (ipc_server_run_async(&state->ipc_server_data,\n                                 state->path_ipc.buf, &ipc_opts,\n                                 handle_client, state))\n                return error_errno(\n                        _(\"could not start IPC thread pool on '%s'\"),\n                        state->path_ipc.buf);\n\nSo I guess we need to let the ipc server initialize itself and then wait\nto be told to start serving requests. And then the fs event thread can\ntrigger that \"go ahead\" once the fs event stream is started. Which is a\nlittle tricky, but possible with an extra mutex.\n\nBut hmm. I wonder if we can hack around it like this:\n\ndiff --git a/compat/fsmonitor/fsm-listen-darwin.c b/compat/fsmonitor/fsm-listen-darwin.c\nindex 2fc6744..6b06faf 100644\n--- a/compat/fsmonitor/fsm-listen-darwin.c\n+++ b/compat/fsmonitor/fsm-listen-darwin.c\n@@ -510,11 +510,17 @@ void fsm_listen__loop(struct fsmonitor_daemon_state *state)\n\tFSEventStreamSetDispatchQueue(data->stream, data->dq);\n\tdata->stream_scheduled = 1;\n\n+\tsleep(1);\n\tif (!FSEventStreamStart(data->stream)) {\n\t\terror(_(\"Failed to start the FSEventStream\"));\n\t\tgoto force_error_stop_without_loop;\n\t}\n\tdata->stream_started = 1;\n+\t/*\n+\t * In case any clients showed up before we initialized the event stream,\n+\t * abort all in-progress ops and start fresh.\n+\t */\n+\tfsmonitor_force_resync(state);\n\n\tpthread_mutex_lock(&data->dq_lock);\n\tpthread_cond_wait(&data->dq_finished, &data->dq_lock);\n\n\nThe forced resync aborts the cookies, which triggers the waiting\nclients. I'm not sure how \"bad\" it is to do a resync like this. It's\nsomething that can happen in the normal course of events, so in theory\nit's just non-optimal and nobody will do the wrong thing. And this would\nonly happen once at the start of fsmonitor, so in most cases nobody\nwould have connected yet, and we wouldn't have processed any events.\n\nSo I dunno. It does make the hang go away in this case.\n\n-Peff\n"},{"id":"503898","messageId":"CAOTNsDy-0TMQMP-7kdLkvdCmXLhHbPJYewSrRZu9m3B=TgdFSA@mail.gmail.com","threadId":"62219","inReplyTo":"20241002062539.GA2863841@coredump.intra.peff.net","subject":"Re: fsmonitor deadlock / macOS CI hangs","fromName":"Koji Nakamaru","fromEmail":"koji.nakamaru@gree.net","sentAt":"2024-10-02T09:51:01Z","receivedAt":"2024-10-02T09:51:13Z","isPatch":false,"sender":{"key":"koji.nakamaru@gree.net","avatar":"https://avatars.githubusercontent.com/u/2645978?v=4"},"body":"On Wed, Oct 2, 2024 at 3:25 PM Jeff King <peff@peff.net> wrote:\n> The solution then is to avoid letting any client threads run (or at\n> least create cookies) until we know we're listening for fs events.\n> Naively I would say we should just have the fs event thread signal us\n> that it's ready before we spawn any of the client threads. But it looks\n> like we explicitly start those threads first in fsmonitor_run_daemon_1():\n\nI submitted a fix that followed this approach as it is easy to\nunderstand and should not have any unexpected behaviour. Could you\nplease check it?\n\nhttps://lore.kernel.org/git/pull.1804.git.1727862424713.gitgitgadget@gmail.com/\n\nKoji Nakamaru\n"}]}