{"thread":{"id":"58296","subject":"t7527 intermittent failure on macOS APFS and possible fix","startedAt":"2022-08-12T13:52:37Z","lastAt":"2022-08-17T20:24:09Z","messageCount":6,"participants":["Đoàn Trần Công Danh","Junio C Hamano","Jeff King","Jeff Hostetler"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"461115","messageId":"YvZbGAf+82WtNXcJ@danh.dev","threadId":"58296","inReplyTo":null,"subject":"t7527 intermittent failure on macOS APFS and possible fix","fromName":"Đoàn Trần Công Danh","fromEmail":"congdanhqx@gmail.com","sentAt":"2022-08-12T13:52:24Z","receivedAt":"2022-08-12T13:52:37Z","isPatch":false,"sender":{"key":"congdanhqx@gmail.com","avatar":"https://avatars.githubusercontent.com/u/42673067?v=4"},"body":"Hello,\n\nRunning t7527 on macOS with encrypted APFS filesystem.\nI observes intermittent failure, however, when I manually check the\ntest cases, they're all passed.\n\nI suspected fileystem caching issue.\nI added those sync-s into test steps and the test pass.\nI'm not sure if this is the intending \"fix\" for the tests\nsince we're testing the fsmonitor with t7527.\n\nPlease advise!\n\nP/S: When debugging, I also found out that:\n\"test-tool fsmonitor-client query\" doesn't write the final newline\ncharacter, thus making the output harder to read. The diff also have\nthe final newline added.\n\n----- 8< -------\ndiff --git a/t/helper/test-fsmonitor-client.c b/t/helper/test-fsmonitor-client.c\nindex 54a4856c48..98d6cf1440 100644\n--- a/t/helper/test-fsmonitor-client.c\n+++ b/t/helper/test-fsmonitor-client.c\n@@ -55,6 +55,7 @@ static int do_send_query(const char *token)\n \n \twrite_in_full(1, answer.buf, answer.len);\n \tstrbuf_release(&answer);\n+\twrite_in_full(1, \"\\n\", 1);\n \n \treturn 0;\n }\n@@ -77,6 +78,7 @@ static int do_send_flush(void)\n \n \twrite_in_full(1, answer.buf, answer.len);\n \tstrbuf_release(&answer);\n+\twrite_in_full(1, \"\\n\", 1);\n \n \treturn 0;\n }\ndiff --git a/t/t7527-builtin-fsmonitor.sh b/t/t7527-builtin-fsmonitor.sh\nindex 56c0dfffea..3f2cef251d 100755\n--- a/t/t7527-builtin-fsmonitor.sh\n+++ b/t/t7527-builtin-fsmonitor.sh\n@@ -430,6 +430,7 @@ test_expect_success 'edit some files' '\n \tedit_files &&\n \n \ttest-tool fsmonitor-client query --token 0 &&\n+\tsync &&\n \n \tgrep \"^event: dir1/modified$\"  .git/trace &&\n \tgrep \"^event: dir2/modified$\"  .git/trace &&\n@@ -445,6 +446,7 @@ test_expect_success 'create some files' '\n \tcreate_files &&\n \n \ttest-tool fsmonitor-client query --token 0 &&\n+\tsync &&\n \n \tgrep \"^event: dir1/new$\" .git/trace &&\n \tgrep \"^event: dir2/new$\" .git/trace &&\n@@ -459,6 +461,7 @@ test_expect_success 'delete some files' '\n \tdelete_files &&\n \n \ttest-tool fsmonitor-client query --token 0 &&\n+\tsync &&\n \n \tgrep \"^event: dir1/delete$\" .git/trace &&\n \tgrep \"^event: dir2/delete$\" .git/trace &&\n@@ -473,6 +476,7 @@ test_expect_success 'rename some files' '\n \trename_files &&\n \n \ttest-tool fsmonitor-client query --token 0 &&\n+\tsync &&\n \n \tgrep \"^event: dir1/rename$\"  .git/trace &&\n \tgrep \"^event: dir2/rename$\"  .git/trace &&\n@@ -490,6 +494,7 @@ test_expect_success 'rename directory' '\n \tmv dirtorename dirrenamed &&\n \n \ttest-tool fsmonitor-client query --token 0 &&\n+\tsync &&\n \n \tgrep \"^event: dirtorename/*$\" .git/trace &&\n \tgrep \"^event: dirrenamed/*$\"  .git/trace\n@@ -503,6 +508,7 @@ test_expect_success 'file changes to directory' '\n \tfile_to_directory &&\n \n \ttest-tool fsmonitor-client query --token 0 &&\n+\tsync &&\n \n \tgrep \"^event: delete$\"     .git/trace &&\n \tgrep \"^event: delete/new$\" .git/trace\n@@ -516,6 +522,7 @@ test_expect_success 'directory changes to a file' '\n \tdirectory_to_file &&\n \n \ttest-tool fsmonitor-client query --token 0 &&\n+\tsync &&\n \n \tgrep \"^event: dir1$\" .git/trace\n '\n---- >8 --------------\n\n-- \nDanh\n"},{"id":"461129","messageId":"xmqqmtc9baht.fsf@gitster.g","threadId":"58296","inReplyTo":"YvZbGAf+82WtNXcJ@danh.dev","subject":"Re: t7527 intermittent failure on macOS APFS and possible fix","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2022-08-12T18:08:30Z","receivedAt":"2022-08-12T18:08:37Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Đoàn Trần Công Danh  <congdanhqx@gmail.com> writes:\n\n> Running t7527 on macOS with encrypted APFS filesystem.\n> I observes intermittent failure, however, when I manually check the\n> test cases, they're all passed.\n>\n> I suspected fileystem caching issue.\n> I added those sync-s into test steps and the test pass.\n> I'm not sure if this is the intending \"fix\" for the tests\n> since we're testing the fsmonitor with t7527.\n>\n> Please advise!\n\nfsmonitor experts, please do.\n\nMy gut feeling is that, unless the production code internally calls\nthe equivalent of \"sync\" done here and the failure in tests are\ncoming from the fact that the \"sync\" is missing in \"test-tool\nfsmonitor-client\" (i.e. test-tool does not emulate the real world\nclosely enough and fails in cases where the machinery does not fail\nin the real world), these \"sync\" calls only sweep the problem under\nthe rug.\n\n> P/S: When debugging, I also found out that:\n> \"test-tool fsmonitor-client query\" doesn't write the final newline\n> character, thus making the output harder to read. The diff also have\n> the final newline added.\n>\n> ----- 8< -------\n> diff --git a/t/helper/test-fsmonitor-client.c b/t/helper/test-fsmonitor-client.c\n> index 54a4856c48..98d6cf1440 100644\n> --- a/t/helper/test-fsmonitor-client.c\n> +++ b/t/helper/test-fsmonitor-client.c\n> @@ -55,6 +55,7 @@ static int do_send_query(const char *token)\n>  \n>  \twrite_in_full(1, answer.buf, answer.len);\n>  \tstrbuf_release(&answer);\n> +\twrite_in_full(1, \"\\n\", 1);\n>  \n>  \treturn 0;\n>  }\n> @@ -77,6 +78,7 @@ static int do_send_flush(void)\n>  \n>  \twrite_in_full(1, answer.buf, answer.len);\n>  \tstrbuf_release(&answer);\n> +\twrite_in_full(1, \"\\n\", 1);\n>  \n>  \treturn 0;\n>  }\n\nAren't these protocol drivers?  If the protocol is defined without\nthe trailing LF, would it make sense to update only the sending end\nto do this?  Or does the protocol makes it clear that a trailing LF,\nor lack of it, should be tolerated by all the implementations?\n\nIf we are absolutely sure that no implementation of the other side\nwill get upset by seeing an extra LF, It would be fine, but as the\noriginal code wants to call write_in_full(), it would be more\npreferrable to do it this way instead, I suspect.\n\n+\tstrbuf_complete(&answer, '\\n');\n\twrite_in_full(1, answer.buf, answer.len);\n\tstrbuf_release(&answer);\n"},{"id":"461156","messageId":"YvbtVoP01fHF2ka3@danh.dev","threadId":"58296","inReplyTo":"xmqqmtc9baht.fsf@gitster.g","subject":"Re: t7527 intermittent failure on macOS APFS and possible fix","fromName":"Đoàn Trần Công Danh","fromEmail":"congdanhqx@gmail.com","sentAt":"2022-08-13T00:16:22Z","receivedAt":"2022-08-13T00:16:33Z","isPatch":false,"sender":{"key":"congdanhqx@gmail.com","avatar":"https://avatars.githubusercontent.com/u/42673067?v=4"},"body":"On 2022-08-12 11:08:30-0700, Junio C Hamano <gitster@pobox.com> wrote:\n> Đoàn Trần Công Danh  <congdanhqx@gmail.com> writes:\n> \n> > Running t7527 on macOS with encrypted APFS filesystem.\n> > I observes intermittent failure, however, when I manually check the\n> > test cases, they're all passed.\n> >\n> > I suspected fileystem caching issue.\n> > I added those sync-s into test steps and the test pass.\n> > I'm not sure if this is the intending \"fix\" for the tests\n> > since we're testing the fsmonitor with t7527.\n> >\n> > Please advise!\n> \n> fsmonitor experts, please do.\n> \n> My gut feeling is that, unless the production code internally calls\n> the equivalent of \"sync\" done here and the failure in tests are\n> coming from the fact that the \"sync\" is missing in \"test-tool\n> fsmonitor-client\" (i.e. test-tool does not emulate the real world\n> closely enough and fails in cases where the machinery does not fail\n> in the real world), these \"sync\" calls only sweep the problem under\n> the rug.\n\nIt's my gut feeling, too.\nAnyway, I'm running the test again, too confirm your suggestion on\nt/helper/test-fsmonitor-client.c\n\nt7527.63 (Unicode nfc/nfd) also failed intermittently, too.\nHere is the content of unicode.trace:\n---- 8< ----\n$ cat unicode.trace\nstatfs('/path/to/src/git/t/trash directory.t7527-builtin-fsmonitor/test_unicode') [type 0x0000001a][flags 0x04909080] 'apfs'\nstatfs('/path/to/src/git/t/trash directory.t7527-builtin-fsmonitor/test_unicode') [type 0x0000001a][flags 0x04909080] 'apfs'\nWatching: worktree '/path/to/src/git/t/trash directory.t7527-builtin-fsmonitor/test_unicode'\nstatfs('/path/to/src/git/t/trash directory.t7527-builtin-fsmonitor/test_unicode') [type 0x0000001a][flags 0x04909080] 'apfs'\nrequested token: quit\n---------- >8 ------------------\n\n> \n> > P/S: When debugging, I also found out that:\n> > \"test-tool fsmonitor-client query\" doesn't write the final newline\n> > character, thus making the output harder to read. The diff also have\n> > the final newline added.\n> >\n> > ----- 8< -------\n> > diff --git a/t/helper/test-fsmonitor-client.c b/t/helper/test-fsmonitor-client.c\n> > index 54a4856c48..98d6cf1440 100644\n> > --- a/t/helper/test-fsmonitor-client.c\n> > +++ b/t/helper/test-fsmonitor-client.c\n> > @@ -55,6 +55,7 @@ static int do_send_query(const char *token)\n> >  \n> >  \twrite_in_full(1, answer.buf, answer.len);\n> >  \tstrbuf_release(&answer);\n> > +\twrite_in_full(1, \"\\n\", 1);\n> >  \n> >  \treturn 0;\n> >  }\n> > @@ -77,6 +78,7 @@ static int do_send_flush(void)\n> >  \n> >  \twrite_in_full(1, answer.buf, answer.len);\n> >  \tstrbuf_release(&answer);\n> > +\twrite_in_full(1, \"\\n\", 1);\n> >  \n> >  \treturn 0;\n> >  }\n> \n> Aren't these protocol drivers?\n\nThe \"answer\" strbuf is the response from fsmonitor daemon, I think.\nThe write_in_full to fd 1 is test-tool writes down the answer to\nstdout.\n\n> If the protocol is defined without\n> the trailing LF, would it make sense to update only the sending end\n> to do this?  Or does the protocol makes it clear that a trailing LF,\n> or lack of it, should be tolerated by all the implementations?\n> \n> If we are absolutely sure that no implementation of the other side\n> will get upset by seeing an extra LF, It would be fine, but as the\n> original code wants to call write_in_full(), it would be more\n> preferrable to do it this way instead, I suspect.\n> \n> +\tstrbuf_complete(&answer, '\\n');\n> \twrite_in_full(1, answer.buf, answer.len);\n> \tstrbuf_release(&answer);\n\nThis could work, since we don't send \"answer\" back to\nfsmonitor-daemon.\n\n-- \nDanh\n"},{"id":"461157","messageId":"xmqq1qtlas3k.fsf@gitster.g","threadId":"58296","inReplyTo":"YvbtVoP01fHF2ka3@danh.dev","subject":"Re: t7527 intermittent failure on macOS APFS and possible fix","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2022-08-13T00:45:51Z","receivedAt":"2022-08-13T00:46:00Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Đoàn Trần Công Danh  <congdanhqx@gmail.com> writes:\n\n>> Aren't these protocol drivers?\n>\n> The \"answer\" strbuf is the response from fsmonitor daemon, I think.\n> The write_in_full to fd 1 is test-tool writes down the answer to\n> stdout.\n\nAhh, then please scratch everything I said about this part.  Your\noriginal implementation makes it more clear that we are \"dumping\"\nwhat we got from the daemon, and then adding LF for our own\nreadability.  I somehow mistook the code to be preparing and sending\nprotocol message to the other end (iow, fd #1 was connected to\n\"them\").\n\nSorry about the gotcha, and thanks for straightening me out.\n\n"},{"id":"461185","messageId":"YvibyWKZD1+QVkXI@coredump.intra.peff.net","threadId":"58296","inReplyTo":"YvZbGAf+82WtNXcJ@danh.dev","subject":"Re: t7527 intermittent failure on macOS APFS and possible fix","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2022-08-14T06:52:57Z","receivedAt":"2022-08-14T06:53:01Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Aug 12, 2022 at 08:52:24PM +0700, Đoàn Trần Công Danh wrote:\n\n> Running t7527 on macOS with encrypted APFS filesystem.\n> I observes intermittent failure, however, when I manually check the\n> test cases, they're all passed.\n> \n> I suspected fileystem caching issue.\n> I added those sync-s into test steps and the test pass.\n> I'm not sure if this is the intending \"fix\" for the tests\n> since we're testing the fsmonitor with t7527.\n\nI don't know anything about your problem area, but some tools in our\ntest suite that might help you get better results with an intermittent\nproblem (if you didn't already know about them):\n\n  - add:\n\n      GIT_TEST_OPTS = -x --verbose-log\n\n    into config.mak. Then when a \"make test\" run fails, you can see the\n    log in t/test-results/t7527-*.out.\n\n  - try running:\n\n      ./t7527-* --stress\n\n    which will run a bunch of instances simultaneously, with the idea\n    that the load will introduce timing issues that will trigger the\n    bug. The failed instance will produce a detailed log on stdout.\n\nThat might help you get more output from the failing cases.\n\n-Peff\n"},{"id":"461387","messageId":"a68f842a-4c96-3639-ca0c-48b79f146182@jeffhostetler.com","threadId":"58296","inReplyTo":"YvZbGAf+82WtNXcJ@danh.dev","subject":"Re: t7527 intermittent failure on macOS APFS and possible fix","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2022-08-17T20:23:57Z","receivedAt":"2022-08-17T20:24:09Z","isPatch":false,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 8/12/22 9:52 AM, Đoàn Trần Công Danh wrote:\n> Hello,\n> \n> Running t7527 on macOS with encrypted APFS filesystem.\n> I observes intermittent failure, however, when I manually check the\n> test cases, they're all passed.\n> \n> I suspected fileystem caching issue.\n> I added those sync-s into test steps and the test pass.\n> I'm not sure if this is the intending \"fix\" for the tests\n> since we're testing the fsmonitor with t7527.\n> \n> Please advise!\n> \n> P/S: When debugging, I also found out that:\n> \"test-tool fsmonitor-client query\" doesn't write the final newline\n> character, thus making the output harder to read. The diff also have\n> the final newline added.\n\nThanks for the report.  Sorry for the delay, I'm still digging thru\nmy email backlog after a long vacation.  I'll take a look at this\nand get back to you shortly.\n\nThanks,\nJeff\n\n"}]}