git/list[1] front-page[2] threads[3] people[4] search[5] about
 

t0021-conversion: flaky filter process test

From
SZEDER Gábor <szeder.dev@gmail.com>
Date
Jan 11, 2019, 14:04 UTC
Message-ID
<20190111140408.GC840@szeder.dev>
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 &&
Next: Johannes Schindelin
Message 1 of 2 in “t0021-conversion: flaky filter process test”
  1. SZEDER GáborJan 11, 2019
  2. Johannes SchindelinJan 15, 2019

Read the whole thread, see it on lore, or plain text.

$ cat FOOTERMessages come from the public archive at lore.kernel.org/git, fetched every hour. The front page is chosen and written each morning by an AI editor and can be wrong; the threads themselves are the record. About and API. For agents: an MCP server at https://gitlist.dev/mcp, and any thread, story or person page as Markdown by adding .md to its URL (or sending Accept: text/markdown). Details in /llms.txt.