1 file changed, 84 insertions, 26 deletions

diff --git a/tests/t0003-cache.sh b/tests/t0003-cache.shindex a07950b..ad6017c 100755--- a/tests/t0003-cache.sh+++ b/tests/t0003-cache.sh@@ -271,35 +271,54 @@ test_expect_success 'a failed final write still delivers the page' ' 	! grep "called many times" flush.err ' -# The second request lands while the first is inside its filter, which says-# so through a marker file, since a fresh binary can take a moment to start.+# The first request's filter says through a marker that it is running, and+# then holds the first request there until the test writes a marker of its+# own, so the second request is sure to land while the first holds the slot.+# A fresh binary can take a moment to start, so both waits are bounded loops. start_first_request() {-	n=0-	rm -f filter-running+	rm -f filter-running release 	cgit_rc lockrc "url=bigpage/about/" >first.out 2>first.err &-	while ! test -f filter-running && test $n -lt 10+	first_pid=$!+	n=0+	while ! test -f filter-running && test $n -lt 30 	do 		sleep 1 		n=$((n + 1)) 	done+	test -f filter-running+}++# Lets the first request go and returns its status.+finish_first_request() {+	touch release+	wait "$first_pid" }  overlap_requests() {-	start_first_request-	cgit_rc lockrc "url=bigpage/log/" >/dev/null 2>second.err-	wait+	start_first_request &&+	cgit_rc lockrc "url=bigpage/log/" >second.out 2>second.err+	overlap_status=$?+	finish_first_request &&+	return $overlap_status }  # The fill writes the page into the lock file through stdout, and an exec # filter puts its own pipe on stdout while it runs. The slot lock has to # outlast that, or a second request on the slot rebuilds it under the first # and the first visitor gets the two pages spliced together. The second one-# finding the lock held is ordinary contention, which logs nothing.+# finding the lock held is ordinary contention, which logs nothing and gets+# the page uncached. A network filesystem that fakes flock with record locks+# breaks this the same way, so the trash directory has to be local. test_expect_success 'a slot stays locked while an exec filter runs' ' 	rm -rf cache3 && mkdir cache3 && 	write_script slow-filter.sh <<-EOF && 	touch "$PWD/filter-running"-	sleep 3+	n=0+	while ! test -f "$PWD/release" && test \$n -lt 60+	do+		sleep 1+		n=\$((n + 1))+	done 	cat 	EOF 	{@@ -310,33 +329,72 @@ test_expect_success 'a slot stays locked while an exec filter runs' ' 	} >lockrc && 	overlap_requests && 	test $(grep -c "^Status:" first.out) = 1 &&-	grep "id=.about." first.out &&-	! grep "Unable to publish" first.err &&-	! grep "Unable to lock" second.err+	test_grep "<div id=.about.>1$" first.out &&+	test_grep "</html>" first.out &&+	test_must_be_empty first.err &&+	test_grep "data-page=.log." second.out &&+	test_grep "</html>" second.out &&+	test_must_be_empty second.err &&+	tr "\000" "\n" <cache3/00000000 | head -n 1 >slot.key &&+	test_grep "about" slot.key &&+	test_grep ! "log" slot.key '  # A request that opens the lock file just before its holder renames it into # place as the live slot goes on to lock the slot itself. strace holds the # second request's flock back until the first has finished, and the check # that the path still names the locked file turns that lock down, so the-# slot keeps the first request's key. strace needs ptrace and a version that-# can delay a call, which some systems do not give.+# slot keeps the first request's key. This is the only test of that check.+# The test needs an strace that can trace the process and delay a call, and+# skips where there is none. test_lazy_prereq STRACE_DELAY '-	strace -o /dev/null -e inject=flock:delay_enter=1 true+	strace -o /dev/null -e trace=%file,flock -e inject=flock:delay_enter=1 true ' +# Returns once the trace shows the second request has opened the lock file,+# which the first request still holds.+start_traced_request() {+	rm -f second.trace+	strace -o second.trace -e trace=%file,flock \+		-e inject=flock:delay_enter=4000000 \+		-E CGIT_CONFIG="$PWD/lockrc" -E QUERY_STRING="url=bigpage/log/" \+		cgit >second.out 2>second.err &+	second_pid=$!+	n=0+	while ! grep "00000000\.lock" second.trace >/dev/null 2>&1 && test $n -lt 30+	do+		sleep 1+		n=$((n + 1))+	done+	grep "00000000\.lock" second.trace >/dev/null 2>&1+}++overlap_traced_requests() {+	second_pid=+	start_first_request &&+	start_traced_request+	overlap_status=$?+	finish_first_request || overlap_status=1+	if test -n "$second_pid"+	then+		wait "$second_pid" || overlap_status=1+	fi+	return $overlap_status+}++# The first request is let go as soon as the second has the lock file open,+# well inside the delay, so the flock that follows succeeds on a file that+# has become the slot. A trace showing it refused would mean the race was+# never reached. strace pads a short call out to a column before its result. test_expect_success STRACE_DELAY 'a lock taken after the rename leaves the slot alone' ' 	rm -rf cache3 && mkdir cache3 &&-	start_first_request &&-	strace -o /dev/null -e inject=flock:delay_enter=4000000 \-		-E CGIT_CONFIG="$PWD/lockrc" -E QUERY_STRING="url=bigpage/log/" \-		cgit >second.out 2>second.err &&-	wait &&-	grep "id=.about." first.out &&-	grep "</html>" second.out &&-	tr "\000" "\n" <"cache3/$(ls cache3)" | head -n 1 >slot.key &&-	grep "about" slot.key &&-	! grep "log" slot.key+	overlap_traced_requests &&+	test_grep -E "^flock\(.*\) += 0" second.trace &&+	test_grep "<div id=.about.>1$" first.out &&+	test_grep "</html>" second.out &&+	tr "\000" "\n" <cache3/00000000 | head -n 1 >slot.key &&+	test_grep "about" slot.key &&+	test_grep ! "log" slot.key '  # An flock lasts until the last copy of its descriptor closes, so a filter
diff --git a/tests/t0003-cache.sh b/tests/t0003-cache.sh
index a07950b..ad6017c 100755
--- a/tests/t0003-cache.sh
+++ b/tests/t0003-cache.sh
@@ -271,35 +271,54 @@ test_expect_success 'a failed final write still delivers the page' '
 	! grep "called many times" flush.err
 '
 
-# The second request lands while the first is inside its filter, which says
-# so through a marker file, since a fresh binary can take a moment to start.
+# The first request's filter says through a marker that it is running, and
+# then holds the first request there until the test writes a marker of its
+# own, so the second request is sure to land while the first holds the slot.
+# A fresh binary can take a moment to start, so both waits are bounded loops.
 start_first_request() {
-	n=0
-	rm -f filter-running
+	rm -f filter-running release
 	cgit_rc lockrc "url=bigpage/about/" >first.out 2>first.err &
-	while ! test -f filter-running && test $n -lt 10
+	first_pid=$!
+	n=0
+	while ! test -f filter-running && test $n -lt 30
 	do
 		sleep 1
 		n=$((n + 1))
 	done
+	test -f filter-running
+}
+
+# Lets the first request go and returns its status.
+finish_first_request() {
+	touch release
+	wait "$first_pid"
 }
 
 overlap_requests() {
-	start_first_request
-	cgit_rc lockrc "url=bigpage/log/" >/dev/null 2>second.err
-	wait
+	start_first_request &&
+	cgit_rc lockrc "url=bigpage/log/" >second.out 2>second.err
+	overlap_status=$?
+	finish_first_request &&
+	return $overlap_status
 }
 
 # The fill writes the page into the lock file through stdout, and an exec
 # filter puts its own pipe on stdout while it runs. The slot lock has to
 # outlast that, or a second request on the slot rebuilds it under the first
 # and the first visitor gets the two pages spliced together. The second one
-# finding the lock held is ordinary contention, which logs nothing.
+# finding the lock held is ordinary contention, which logs nothing and gets
+# the page uncached. A network filesystem that fakes flock with record locks
+# breaks this the same way, so the trash directory has to be local.
 test_expect_success 'a slot stays locked while an exec filter runs' '
 	rm -rf cache3 && mkdir cache3 &&
 	write_script slow-filter.sh <<-EOF &&
 	touch "$PWD/filter-running"
-	sleep 3
+	n=0
+	while ! test -f "$PWD/release" && test \$n -lt 60
+	do
+		sleep 1
+		n=\$((n + 1))
+	done
 	cat
 	EOF
 	{
@@ -310,33 +329,72 @@ test_expect_success 'a slot stays locked while an exec filter runs' '
 	} >lockrc &&
 	overlap_requests &&
 	test $(grep -c "^Status:" first.out) = 1 &&
-	grep "id=.about." first.out &&
-	! grep "Unable to publish" first.err &&
-	! grep "Unable to lock" second.err
+	test_grep "<div id=.about.>1$" first.out &&
+	test_grep "</html>" first.out &&
+	test_must_be_empty first.err &&
+	test_grep "data-page=.log." second.out &&
+	test_grep "</html>" second.out &&
+	test_must_be_empty second.err &&
+	tr "\000" "\n" <cache3/00000000 | head -n 1 >slot.key &&
+	test_grep "about" slot.key &&
+	test_grep ! "log" slot.key
 '
 
 # A request that opens the lock file just before its holder renames it into
 # place as the live slot goes on to lock the slot itself. strace holds the
 # second request's flock back until the first has finished, and the check
 # that the path still names the locked file turns that lock down, so the
-# slot keeps the first request's key. strace needs ptrace and a version that
-# can delay a call, which some systems do not give.
+# slot keeps the first request's key. This is the only test of that check.
+# The test needs an strace that can trace the process and delay a call, and
+# skips where there is none.
 test_lazy_prereq STRACE_DELAY '
-	strace -o /dev/null -e inject=flock:delay_enter=1 true
+	strace -o /dev/null -e trace=%file,flock -e inject=flock:delay_enter=1 true
 '
 
+# Returns once the trace shows the second request has opened the lock file,
+# which the first request still holds.
+start_traced_request() {
+	rm -f second.trace
+	strace -o second.trace -e trace=%file,flock \
+		-e inject=flock:delay_enter=4000000 \
+		-E CGIT_CONFIG="$PWD/lockrc" -E QUERY_STRING="url=bigpage/log/" \
+		cgit >second.out 2>second.err &
+	second_pid=$!
+	n=0
+	while ! grep "00000000\.lock" second.trace >/dev/null 2>&1 && test $n -lt 30
+	do
+		sleep 1
+		n=$((n + 1))
+	done
+	grep "00000000\.lock" second.trace >/dev/null 2>&1
+}
+
+overlap_traced_requests() {
+	second_pid=
+	start_first_request &&
+	start_traced_request
+	overlap_status=$?
+	finish_first_request || overlap_status=1
+	if test -n "$second_pid"
+	then
+		wait "$second_pid" || overlap_status=1
+	fi
+	return $overlap_status
+}
+
+# The first request is let go as soon as the second has the lock file open,
+# well inside the delay, so the flock that follows succeeds on a file that
+# has become the slot. A trace showing it refused would mean the race was
+# never reached. strace pads a short call out to a column before its result.
 test_expect_success STRACE_DELAY 'a lock taken after the rename leaves the slot alone' '
 	rm -rf cache3 && mkdir cache3 &&
-	start_first_request &&
-	strace -o /dev/null -e inject=flock:delay_enter=4000000 \
-		-E CGIT_CONFIG="$PWD/lockrc" -E QUERY_STRING="url=bigpage/log/" \
-		cgit >second.out 2>second.err &&
-	wait &&
-	grep "id=.about." first.out &&
-	grep "</html>" second.out &&
-	tr "\000" "\n" <"cache3/$(ls cache3)" | head -n 1 >slot.key &&
-	grep "about" slot.key &&
-	! grep "log" slot.key
+	overlap_traced_requests &&
+	test_grep -E "^flock\(.*\) += 0" second.trace &&
+	test_grep "<div id=.about.>1$" first.out &&
+	test_grep "</html>" second.out &&
+	tr "\000" "\n" <cache3/00000000 | head -n 1 >slot.key &&
+	test_grep "about" slot.key &&
+	test_grep ! "log" slot.key
 '
 
 # An flock lasts until the last copy of its descriptor closes, so a filter