t0021-conversion: flaky filter process test

["SZEDER Gábor" <szeder.dev@gmail.com>]

Hi Lars,

I see occasional failures in the test 'required process filter should
filter data' in 't0021-conversion.sh', added in edcc85814c (convert:
add filter.<driver>.process option, 2016-10-16); most often in the
macOS Travis CI build jobs, but it's an OS-independent timing issue.

That's an enormous test, and the part failing every once in a while is
this:

    filter_git checkout --quiet --no-progress empty-branch &&
    cat >expected.log <<-EOF &&
            START
            init handshake complete
            IN: clean test.r $S [OK] -- OUT: $S . [OK]
            STOP
    EOF
    test_cmp_exclude_clean expected.log debug.log &&

Here's the relevant trace output:

  ++filter_git checkout --quiet --no-progress empty-branch
  ++rm -f debug.log expected.log
  ++git checkout --quiet --no-progress empty-branch
  ++cat
  ++test_cmp_exclude_clean expected.log debug.log
  ++expect=expected.log
  ++actual=debug.log
  ++for FILE in '"$expect"' '"$actual"'
  ++grep -v 'IN: clean' expected.log
  ++for FILE in '"$expect"' '"$actual"'
  ++grep -v 'IN: clean' debug.log
  grep: debug.log: No such file or directory
  error: last command exited with $?=2

So when checking out the 'empty-branch' four tracked files from the
currently checked out 'master' branch must be removed, and this part
of the test assumes that the filter process is always invoked to clean
those files.  Alas, this is not necessarily the case: if 'git
checkout' knows for sure that all files are clean, then it won't waste
resources running the clean filter process at all, and just deletes
those files.

Now, in our tests commands are executed in rapid succession, so it's
highly probable that those files are racily clean, and, consequently,
'git checkout' has to look at the contents of the files, meaning that
it has to run the clean filter process, and then all is well: that's
why the test succeeds most of the time.  Occasionally, however, the
commands are executed slow enough or just at the right moment that the
files are really clean, and 'git checkout' won't bother starting the
clean filter process, which then won't write a 'debug.log' file,
resulting in the above failure.

You might find the 'sg/stress-test' topic (already in 'next', tip at
fb7d1e3ac8; just run './t0021-conversion.sh -r 1,15 --stress' and
wait) and the patch below helpful in reproducing and debugging the
issue.



diff --git a/convert.c b/convert.c
index e0848226d2..f87184cae2 100644
--- a/convert.c
+++ b/convert.c
@@ -812,6 +812,8 @@ static int apply_multi_file_filter(const char *path, const char *src, size_t len
 	struct strbuf filter_status = STRBUF_INIT;
 	const char *filter_type;
 
+	trace_printf("apply_multi_file_filter()\n");
+
 	if (!subprocess_map_initialized) {
 		subprocess_map_initialized = 1;
 		hashmap_init(&subprocess_map, cmd2process_cmp, NULL, 0);
diff --git a/read-cache.c b/read-cache.c
index bd45dc3e24..ce39ace43f 100644
--- a/read-cache.c
+++ b/read-cache.c
@@ -412,11 +412,13 @@ int ie_match_stat(struct index_state *istate,
 	 * carefully than others.
 	 */
 	if (!changed && is_racy_timestamp(istate, ce)) {
+		trace_printf("'%s' is RACILY clean!\n", ce->name);
 		if (assume_racy_is_modified)
 			changed |= DATA_CHANGED;
 		else
 			changed |= ce_modified_check_fs(istate, ce, st);
-	}
+	} else
+		trace_printf("'%s' is clean\n", ce->name);
 
 	return changed;
 }
diff --git a/t/t0021-conversion.sh b/t/t0021-conversion.sh
index fd5f1ac649..6b3d3b12e5 100755
--- a/t/t0021-conversion.sh
+++ b/t/t0021-conversion.sh
@@ -390,7 +390,11 @@ test_expect_success PERL 'required process filter should filter data' '
 		EOF
 		test_cmp_exclude_clean expected.log debug.log &&
 
-		filter_git checkout --quiet --no-progress empty-branch &&
+		GIT_TRACE=2 &&
+		export GIT_TRACE &&
+		filter_git checkout --quiet --no-progress empty-branch 2>trace &&
+		cat trace &&
+		unset GIT_TRACE &&
 		cat >expected.log <<-EOF &&
 			START
 			init handshake complete
@@ -398,6 +402,7 @@ test_expect_success PERL 'required process filter should filter data' '
 			STOP
 		EOF
 		test_cmp_exclude_clean expected.log debug.log &&
+		grep RACILY trace &&
 
 		filter_git checkout --quiet --no-progress master &&
 		cat >expected.log <<-EOF &&
@@ -416,6 +421,7 @@ test_expect_success PERL 'required process filter should filter data' '
 		test_cmp_committed_rot13 "$TEST_ROOT/test3 '\''sq'\'',\$x=.o" "testsubdir/test3 '\''sq'\'',\$x=.r"
 	)
 '
+test_done
 
 test_expect_success PERL 'required process filter takes precedence' '
 	test_config_global filter.protocol.clean false &&