{"thread":{"id":"50201","subject":"t0021-conversion: flaky filter process test","startedAt":"2019-01-11T14:04:15Z","lastAt":"2019-01-15T13:45:11Z","messageCount":2,"participants":["SZEDER Gábor","Johannes Schindelin"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"366556","messageId":"20190111140408.GC840@szeder.dev","threadId":"50201","inReplyTo":null,"subject":"t0021-conversion: flaky filter process test","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-01-11T14:04:08Z","receivedAt":"2019-01-11T14:04:15Z","isPatch":false,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"Hi Lars,\n\nI see occasional failures in the test 'required process filter should\nfilter data' in 't0021-conversion.sh', added in edcc85814c (convert:\nadd filter.<driver>.process option, 2016-10-16); most often in the\nmacOS Travis CI build jobs, but it's an OS-independent timing issue.\n\nThat's an enormous test, and the part failing every once in a while is\nthis:\n\n    filter_git checkout --quiet --no-progress empty-branch &&\n    cat >expected.log <<-EOF &&\n            START\n            init handshake complete\n            IN: clean test.r $S [OK] -- OUT: $S . [OK]\n            STOP\n    EOF\n    test_cmp_exclude_clean expected.log debug.log &&\n\nHere's the relevant trace output:\n\n  ++filter_git checkout --quiet --no-progress empty-branch\n  ++rm -f debug.log expected.log\n  ++git checkout --quiet --no-progress empty-branch\n  ++cat\n  ++test_cmp_exclude_clean expected.log debug.log\n  ++expect=expected.log\n  ++actual=debug.log\n  ++for FILE in '\"$expect\"' '\"$actual\"'\n  ++grep -v 'IN: clean' expected.log\n  ++for FILE in '\"$expect\"' '\"$actual\"'\n  ++grep -v 'IN: clean' debug.log\n  grep: debug.log: No such file or directory\n  error: last command exited with $?=2\n\nSo when checking out the 'empty-branch' four tracked files from the\ncurrently checked out 'master' branch must be removed, and this part\nof the test assumes that the filter process is always invoked to clean\nthose files.  Alas, this is not necessarily the case: if 'git\ncheckout' knows for sure that all files are clean, then it won't waste\nresources running the clean filter process at all, and just deletes\nthose files.\n\nNow, in our tests commands are executed in rapid succession, so it's\nhighly probable that those files are racily clean, and, consequently,\n'git checkout' has to look at the contents of the files, meaning that\nit has to run the clean filter process, and then all is well: that's\nwhy the test succeeds most of the time.  Occasionally, however, the\ncommands are executed slow enough or just at the right moment that the\nfiles are really clean, and 'git checkout' won't bother starting the\nclean filter process, which then won't write a 'debug.log' file,\nresulting in the above failure.\n\nYou might find the 'sg/stress-test' topic (already in 'next', tip at\nfb7d1e3ac8; just run './t0021-conversion.sh -r 1,15 --stress' and\nwait) and the patch below helpful in reproducing and debugging the\nissue.\n\n\n\ndiff --git a/convert.c b/convert.c\nindex e0848226d2..f87184cae2 100644\n--- a/convert.c\n+++ b/convert.c\n@@ -812,6 +812,8 @@ static int apply_multi_file_filter(const char *path, const char *src, size_t len\n \tstruct strbuf filter_status = STRBUF_INIT;\n \tconst char *filter_type;\n \n+\ttrace_printf(\"apply_multi_file_filter()\\n\");\n+\n \tif (!subprocess_map_initialized) {\n \t\tsubprocess_map_initialized = 1;\n \t\thashmap_init(&subprocess_map, cmd2process_cmp, NULL, 0);\ndiff --git a/read-cache.c b/read-cache.c\nindex bd45dc3e24..ce39ace43f 100644\n--- a/read-cache.c\n+++ b/read-cache.c\n@@ -412,11 +412,13 @@ int ie_match_stat(struct index_state *istate,\n \t * carefully than others.\n \t */\n \tif (!changed && is_racy_timestamp(istate, ce)) {\n+\t\ttrace_printf(\"'%s' is RACILY clean!\\n\", ce->name);\n \t\tif (assume_racy_is_modified)\n \t\t\tchanged |= DATA_CHANGED;\n \t\telse\n \t\t\tchanged |= ce_modified_check_fs(istate, ce, st);\n-\t}\n+\t} else\n+\t\ttrace_printf(\"'%s' is clean\\n\", ce->name);\n \n \treturn changed;\n }\ndiff --git a/t/t0021-conversion.sh b/t/t0021-conversion.sh\nindex fd5f1ac649..6b3d3b12e5 100755\n--- a/t/t0021-conversion.sh\n+++ b/t/t0021-conversion.sh\n@@ -390,7 +390,11 @@ test_expect_success PERL 'required process filter should filter data' '\n \t\tEOF\n \t\ttest_cmp_exclude_clean expected.log debug.log &&\n \n-\t\tfilter_git checkout --quiet --no-progress empty-branch &&\n+\t\tGIT_TRACE=2 &&\n+\t\texport GIT_TRACE &&\n+\t\tfilter_git checkout --quiet --no-progress empty-branch 2>trace &&\n+\t\tcat trace &&\n+\t\tunset GIT_TRACE &&\n \t\tcat >expected.log <<-EOF &&\n \t\t\tSTART\n \t\t\tinit handshake complete\n@@ -398,6 +402,7 @@ test_expect_success PERL 'required process filter should filter data' '\n \t\t\tSTOP\n \t\tEOF\n \t\ttest_cmp_exclude_clean expected.log debug.log &&\n+\t\tgrep RACILY trace &&\n \n \t\tfilter_git checkout --quiet --no-progress master &&\n \t\tcat >expected.log <<-EOF &&\n@@ -416,6 +421,7 @@ test_expect_success PERL 'required process filter should filter data' '\n \t\ttest_cmp_committed_rot13 \"$TEST_ROOT/test3 '\\''sq'\\'',\\$x=.o\" \"testsubdir/test3 '\\''sq'\\'',\\$x=.r\"\n \t)\n '\n+test_done\n \n test_expect_success PERL 'required process filter takes precedence' '\n \ttest_config_global filter.protocol.clean false &&\n\n"},{"id":"366708","messageId":"nycvar.QRO.7.76.6.1901151442420.41@tvgsbejvaqbjf.bet","threadId":"50201","inReplyTo":"20190111140408.GC840@szeder.dev","subject":"Re: t0021-conversion: flaky filter process test","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2019-01-15T13:44:51Z","receivedAt":"2019-01-15T13:45:11Z","isPatch":false,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi,\n\nOn Fri, 11 Jan 2019, SZEDER Gábor wrote:\n\n> [...]\n> \n> Now, in our tests commands are executed in rapid succession, so it's\n> highly probable that those files are racily clean, and, consequently,\n> 'git checkout' has to look at the contents of the files, meaning that\n> it has to run the clean filter process, and then all is well: that's\n> why the test succeeds most of the time.  Occasionally, however, the\n> commands are executed slow enough or just at the right moment that the\n> files are really clean, and 'git checkout' won't bother starting the\n> clean filter process, which then won't write a 'debug.log' file,\n> resulting in the above failure.\n\nWe had a similar problem in some of the VFS4Git tests, and solved it by\nusing `test-tool chmtime -60 .git/index`. Maybe the same strategy works\nhere?\n\nCiao,\nDscho"}]}