Hold the first request until the second is done

The lock tests leaned on a three second sleep in the filter and gave up
the wait for its marker in silence, so on a slow run the requests need
not overlap at all and every check held trivially. A bare wait also
hid any crash of the first request, and the second request's page was
never looked at. The filter now holds the first request until the test
lets it go.

The strace test gets the same hold, released once the trace shows the
second request has opened the lock file. It checks that the delayed
flock then succeeded, since a refusal would mean the inode check was
never reached.

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