From: Stefan Sperling Subject: Re: fix gotd notifications race To: gameoftrees@openbsd.org Date: Wed, 4 Jun 2025 11:53:23 +0200 On Wed, Jun 04, 2025 at 11:38:43AM +0200, Stefan Sperling wrote: > I used gotd's regression test http-server to receive http notifications. > Unfortunately, this server is only able to process a single request > before stopping itself. So I could only confirm that the first notification > was actually sent. > And http-server's behaviour makes it difficult to write a test case for > this issue. I will send more about this in a follow-up message. Here is a WIP diff which attempts to add a test case for the notification race fix, by rewriting http-server to accept more than one notification before stopping itself. Unfortunately, these changes break the test_file_changed notification test case, where we try to run 'git push' to trigger a notification for a simple file modification. It seems things start going wrong when Git clients close their side of the TCP connection early, presumably using shutdown(fd, SHUT_WR); For some reason, as in indirect consequence the notification request is never received by the http-server, even though got-notify-http has sent the request (unsure where this data is gong), and it still attempts to read a response which fails with: got-notify-http[54315]: unexpected EOF from upstream HTTP server I've been trying to make sense of this for a full day now, and need to start focussing on other things. Could someone else take a look? Most likely my HTTP server changes are buggy. This problem does not trigger when 'got send' is used. But it can be triggered via 'got send' by adding a shutdown call here: --- libexec/got-send-pack/got-send-pack.c +++ libexec/got-send-pack/got-send-pack.c @@ -15,6 +15,7 @@ * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. */ +#include #include #include #include @@ -555,6 +556,7 @@ send_pack(int fd, struct got_pathlist_head *refs, err = send_pack_file(fd, packfd, ibuf); if (err) goto done; + shutdown(fd, SHUT_WR); } err = got_pkt_readpkt(&n, fd, buf, sizeof(buf), chattygot, INFTIM); M regress/gotd/http-server | 70+ 78- M regress/gotd/http_notification.sh | 278+ 36- 2 files changed, 348 insertions(+), 114 deletions(-) commit - 77ebbf498677a798fd1077376cb02a3bfeb7cf88 commit + b0fa84f6f11d39f0949ee7e2a4c73c9d113ae859 blob - 2c6cd5bc09b5a166703c82c4cff9e40cd853d91c blob + da15b58e92d2d304b9ac791fbf0ecbe1d39ca22e --- regress/gotd/http-server +++ regress/gotd/http-server @@ -19,110 +19,102 @@ use IPC::Open2; use Getopt::Long qw(:config bundling); use Digest; use Digest::HMAC; +use HTTP::Daemon; +use HTTP::Status; +use HTTP::Request; my $auth; my $port = 8000; my $hmac_secret; my $hmac_signature; -my $hmac; GetOptions("a:s" => \$auth, "p:i" => \$port, "s:s" => \$hmac_secret) or die("usage: $0 [-a auth] [-p port] [-s hmac_secret]\n"); -my $pid = open2(my $out, my $in, 'nc', '-l', 'localhost', $port); +# $HTTP::Daemon::DEBUG = 1; -my $clen; -while (<$out>) { - local $/ = "\r\n"; - chomp; +my $server = HTTP::Daemon->new( + Domain => AF_INET, + Type => SOCK_STREAM, + Proto => 'tcp', + LocalHost => '127.0.0.1', + LocalPort => $port, + ReusePort => 1, + Listen => 1, +) || die "Could not open socket 127.0.0.1:$port: $IO::Socket::errstr"; - last if /^$/; +$SIG{'PIPE'} = 'IGNORE'; - if (m/^POST/) { - die "bad http request" unless m,^POST / HTTP/1.1$,; - next; - } +sub handle_post { + my ($req, $client) = @_; + my $hmac_signature = $req->header('X-Gotd-Signature'); + my $connection = $req->header('Connection'); + printf STDERR "connection: %s\n", $connection; - if (m/^Host:/) { - die "bad Host header" unless /^Host: localhost:$port$/; - next; + if (defined $hmac_signature) { + die "no Hmac secret provided" unless defined $hmac_secret; } - if (m/^Content-Type/) { - die "bad content-type header" - unless m,Content-Type: application/json$,; - next; - } + my $content = $req->content(); + die if not "$content"; + print $content; + say ""; - if (m/^Content-Length/) { - die "double content-length" if defined $clen; - die "bad content-length header" - unless m/Content-Length: (\d+)$/; - $clen = $1; - next; - } + if (defined $hmac_signature) { + my $sha256 = Digest->new("SHA-256"); + my $hmac = Digest::HMAC->new($hmac_secret, $sha256); + my $clen = length($content); - if (m/Connection/) { - die "bad connection header" - unless m/Connection: close$/; - next; + while ($clen > 0) { + my $len; + $len = 512 if $len > 512; + $hmac->add($content, $len); + $content = substr($content, $len); + $clen -= $len + } + my $digest = $hmac->hexdigest; + if ($digest ne $hmac_signature) { + printf STDERR "bad hmac signature: expected: $hmac_signature, actual: $digest"; + die + } } - if (m/Authorization/) { - die "bad authorization header" - unless m/Authorization: basic (.*)$/; - my $t = $1; - die "wrong authorization; got $t want $auth" - if not defined($auth) or $auth ne $t; - next; - } + my $headers = HTTP::Headers->new; + my ($status_code, $status) = (200, "OK"); - if (m/X-Gotd-Signature/) { - die "bad hmac signature header" - unless m/X-Gotd-Signature: sha256=(.*)$/; - $hmac_signature = $1; - next; - } -} + my $resp = HTTP::Response->new($status_code, $status, $headers); + $client->send_response($resp); -die "no Content-Length header" unless defined $clen; + printf STDERR "POST %s: 200 OK\n", $req->uri->path; -if (defined $hmac_signature) { - die "no Hmac secret provided" unless defined $hmac_secret; - my $sha256 = Digest->new("SHA-256"); - $hmac = Digest::HMAC->new($hmac_secret, $sha256); -} - -while ($clen != 0) { - my $len = $clen; - $len = 512 if $clen > 512; - - my $r = read($out, my $buf, $len); - $clen -= $r; - - if (defined $hmac) { - $hmac->add($buf); + if ($connection eq "close") { + return 1; } - print $buf; + return 0; } -say ""; -if (defined $hmac) { - my $digest = $hmac->hexdigest; - if ($digest ne $hmac_signature) { - print "bad hmac signature: expected: $hmac_signature, actual: $digest"; - die - } -} +STDOUT->autoflush(1); +STDERR->autoflush(1); +printf STDERR "$$: ready\n"; -print $in "HTTP/1.1 200 OK\r\n"; -print $in "Content-Length: 0\r\n"; -print $in "Connection: close\r\n"; -print $in "\r\n"; +while (1) { + my $client = $server->accept(); + print STDERR "accept new\n"; -close $in; -close $out; + my $req = $client->get_request; + if ($req) { + print STDERR "have request\n"; + if ($req->method eq "POST") { + handle_post($req, $client); + } else { + warn "unknown method ". $req->method . "\n"; + my $res = HTTP::Response->new(405, + "Method not Allowed"); + $client->send_response($res); + } + } -waitpid($pid, 0); -exit $? >> 8; + $client->close(); + undef $client; +} blob - a358917969feee72a0c5245f6bcfb0062556fe9d blob + 8622aef4dcf0b4f5838a9694d6f83ed5d00d3e50 --- regress/gotd/http_notification.sh +++ regress/gotd/http_notification.sh @@ -44,12 +44,28 @@ test_file_changed() { local commit_id=`git_show_head $testroot/repo-clone` local author_time=`git_show_author_time $testroot/repo-clone` - timeout 5 ./http-server -a $AUTH -p $GOTD_TEST_HTTP_PORT \ - > $testroot/stdout & + timeout 20 ./http-server -a $AUTH -p $GOTD_TEST_HTTP_PORT \ + > $testroot/stdout 2> $testroot/stderr & sleep 1 # server starts up + for i in 1 2 3 4; do + if grep -q ': ready' $testroot/stderr; then + break + fi + if [ $i -eq 4 ]; then + echo "http-server startup timeout" >&2 + test_done "$testroot" "1" + # timeout(1) will kill the server eventually + return 1 + fi + sleep 1 # server is still starting up + done - got send -b main -q -r $testroot/repo-clone + http_pid=`head -n 1 $testroot/stderr | cut -d ':' -f1` + trap "kill -9 $http_pid; wait $http_pid" HUP INT QUIT PIPE TERM + + #got send -b main -q -r $testroot/repo-clone + git -C $testroot/repo-clone push -q origin main ret=$? if [ $ret -ne 0 ]; then echo "got send failed unexpectedly" >&2 @@ -57,8 +73,6 @@ test_file_changed() { return 1 fi - wait %1 # wait for the http "server" - touch "$testroot/stdout.expected" ed -s "$testroot/stdout.expected" <<-EOF a @@ -101,6 +115,9 @@ test_file_changed() { w EOF + kill $http_pid + wait $http_pid + cmp -s $testroot/stdout.expected $testroot/stdout ret=$? if [ $ret -ne 0 ]; then @@ -109,17 +126,35 @@ test_file_changed() { return 1 fi + test_done "$testroot" "0" + return + # Try the same thing again with 'git push' instead of 'got send' echo "change alpha once more" > $testroot/wt/alpha (cd $testroot/wt && got commit -m 'make more changes' > /dev/null) local commit_id=`git_show_head $testroot/repo-clone` local author_time=`git_show_author_time $testroot/repo-clone` - timeout 5 ./http-server -a $AUTH -p $GOTD_TEST_HTTP_PORT \ - > $testroot/stdout & + timeout 20 ./http-server -a $AUTH -p $GOTD_TEST_HTTP_PORT \ + > $testroot/stdout 2> $testroot/stderr & sleep 1 # server starts up + for i in 1 2 3 4; do + if grep -q ': ready' $testroot/stderr; then + break + fi + if [ $i -eq 4 ]; then + echo "http-server startup timeout" >&2 + test_done "$testroot" "1" + # timeout(1) will kill the server eventually + return 1 + fi + sleep 1 # server is still starting up + done + http_pid=`head -n 1 $testroot/stderr | cut -d ':' -f1` + trap "kill -9 $http_pid; wait $http_pid" HUP INT QUIT PIPE TERM + git -C $testroot/repo-clone push -q origin main ret=$? if [ $ret -ne 0 ]; then @@ -128,7 +163,8 @@ test_file_changed() { return 1 fi - wait %1 # wait for the http "server" + kill $http_pid + wait $http_pid echo -n > "$testroot/stdout.expected" ed -s "$testroot/stdout.expected" <<-EOF @@ -177,6 +213,7 @@ test_file_changed() { if [ $ret -ne 0 ]; then diff -u $testroot/stdout.expected $testroot/stdout fi + test_done "$testroot" "$ret" } @@ -206,11 +243,26 @@ test_bad_utf8() { local commit_id=`git_show_head $testroot/repo-clone` local author_time=`git_show_author_time $testroot/repo-clone` - timeout 5 ./http-server -a $AUTH -p $GOTD_TEST_HTTP_PORT \ - > $testroot/stdout & + timeout 20 ./http-server -a $AUTH -p $GOTD_TEST_HTTP_PORT \ + > $testroot/stdout 2> $testroot/stderr & sleep 1 # server starts up + for i in 1 2 3 4; do + if grep -q ': ready' $testroot/stdout; then + break + fi + if [ $i -eq 4 ]; then + echo "http-server startup timeout" >&2 + test_done "$testroot" "1" + # timeout(1) will kill the server eventually + return 1 + fi + sleep 1 # server is still starting up + done + http_pid=`head -n 1 $testroot/stderr | cut -d ':' -f1` + trap "kill -9 $http_pid; wait $http_pid" HUP INT QUIT PIPE TERM + got send -b main -q -r $testroot/repo-clone ret=$? if [ $ret -ne 0 ]; then @@ -219,7 +271,8 @@ test_bad_utf8() { return 1 fi - wait %1 # wait for the http "server" + kill $http_pid + wait $http_pid touch "$testroot/stdout.expected" ed -s "$testroot/stdout.expected" <<-EOF @@ -301,11 +354,26 @@ test_many_commits_not_summarized() { set -- "$@" "$commit_id $author_time" done - timeout 5 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ - > $testroot/stdout & + timeout 20 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ + > $testroot/stdout 2> $testroot/stderr & sleep 1 # server starts up + for i in 1 2 3 4; do + if grep -q ': ready' $testroot/stdout; then + break + fi + if [ $i -eq 4 ]; then + echo "http-server startup timeout" >&2 + test_done "$testroot" "1" + # timeout(1) will kill the server eventually + return 1 + fi + sleep 1 # server is still starting up + done + http_pid=`head -n 1 $testroot/stderr | cut -d ':' -f1` + trap "kill -9 $http_pid; wait $http_pid" HUP INT QUIT PIPE TERM + got send -b main -q -r $testroot/repo-clone ret=$? if [ $ret -ne 0 ]; then @@ -314,7 +382,8 @@ test_many_commits_not_summarized() { return 1 fi - wait %1 # wait for the http "server" + kill $http_pid + wait $http_pid printf '{"notifications":[' > $testroot/stdout.expected comma="" @@ -408,11 +477,26 @@ test_many_commits_summarized() { set -- "$@" "$short_commit_id $author_time" done - timeout 5 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ - > $testroot/stdout & + timeout 20 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ + > $testroot/stdout 2> $testroot/stderr & sleep 1 # server starts up + for i in 1 2 3 4; do + if grep -q ': ready' $testroot/stdout; then + break + fi + if [ $i -eq 4 ]; then + echo "http-server startup timeout" >&2 + test_done "$testroot" "1" + # timeout(1) will kill the server eventually + return 1 + fi + sleep 1 # server is still starting up + done + http_pid=`head -n 1 $testroot/stderr | cut -d ':' -f1` + trap "kill -9 $http_pid; wait $http_pid" HUP INT QUIT PIPE TERM + got send -b main -q -r $testroot/repo-clone ret=$? if [ $ret -ne 0 ]; then @@ -421,7 +505,8 @@ test_many_commits_summarized() { return 1 fi - wait %1 # wait for the http "server" + kill $http_pid + wait $http_pid printf '{"notifications":[' > $testroot/stdout.expected comma="" @@ -491,11 +576,26 @@ test_branch_created() { local commit_id=`git_show_branch_head $testroot/repo-clone newbranch` local author_time=`git_show_author_time $testroot/repo-clone $commit_id` - timeout 5 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ - > $testroot/stdout & + timeout 20 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ + > $testroot/stdout 2> $testroot/stderr & sleep 1 # server starts up + for i in 1 2 3 4; do + if grep -q ': ready' $testroot/stdout; then + break + fi + if [ $i -eq 4 ]; then + echo "http-server startup timeout" >&2 + test_done "$testroot" "1" + # timeout(1) will kill the server eventually + return 1 + fi + sleep 1 # server is still starting up + done + http_pid=`head -n 1 $testroot/stderr | cut -d ':' -f1` + trap "kill -9 $http_pid; wait $http_pid" HUP INT QUIT PIPE TERM + got send -b newbranch -q -r $testroot/repo-clone ret=$? if [ $ret -ne 0 ]; then @@ -504,7 +604,8 @@ test_branch_created() { return 1 fi - wait %1 # wait for the http "server" + kill $http_pid + wait $http_pid # in the future it should contain something like this too # { @@ -579,11 +680,26 @@ test_branch_removed() { return 1 fi - timeout 5 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ - > $testroot/stdout & + timeout 20 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ + > $testroot/stdout 2> $testroot/stderr & sleep 1 # server starts up + for i in 1 2 3 4; do + if grep -q ': ready' $testroot/stdout; then + break + fi + if [ $i -eq 4 ]; then + echo "http-server startup timeout" >&2 + test_done "$testroot" "1" + # timeout(1) will kill the server eventually + return 1 + fi + sleep 1 # server is still starting up + done + http_pid=`head -n 1 $testroot/stderr | cut -d ':' -f1` + trap "kill -9 $http_pid; wait $http_pid" HUP INT QUIT PIPE TERM + local commit_id=`git_show_branch_head $testroot/repo-clone newbranch` got send -d newbranch -q -r $testroot/repo-clone @@ -594,7 +710,8 @@ test_branch_removed() { return 1 fi - wait %1 # wait for the http "server" + kill $http_pid + wait $http_pid touch "$testroot/stdout.expected" ed -s "$testroot/stdout.expected" <<-EOF @@ -637,11 +754,26 @@ test_tag_created() { local commit_id=`git_show_head $testroot/repo-clone` local tagger_time=`git_show_tagger_time $testroot/repo-clone 1.0` - timeout 5 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ - >$testroot/stdout & + timeout 20 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ + > $testroot/stdout 2> $testroot/stderr & sleep 1 # server starts up + for i in 1 2 3 4; do + if grep -q ': ready' $testroot/stdout; then + break + fi + if [ $i -eq 4 ]; then + echo "http-server startup timeout" >&2 + test_done "$testroot" "1" + # timeout(1) will kill the server eventually + return 1 + fi + sleep 1 # server is still starting up + done + http_pid=`head -n 1 $testroot/stderr | cut -d ':' -f1` + trap "kill -9 $http_pid; wait $http_pid" HUP INT QUIT PIPE TERM + got send -t 1.0 -q -r $testroot/repo-clone ret=$? if [ $ret -ne 0 ]; then @@ -650,7 +782,8 @@ test_tag_created() { return 1 fi - wait %1 # wait for the http "server" + kill $http_pid + wait $http_pid touch "$testroot/stdout.expected" ed -s "$testroot/stdout.expected" <<-EOF @@ -716,11 +849,26 @@ test_tag_changed() { got tag -r $testroot/repo-clone -m "new tag" 1.0 > /dev/null local tagger_time=`git_show_tagger_time $testroot/repo-clone 1.0` - timeout 5 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ - > $testroot/stdout & + timeout 20 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ + > $testroot/stdout 2> $testroot/stderr & sleep 1 # server starts up + for i in 1 2 3 4; do + if grep -q ': ready' $testroot/stdout; then + break + fi + if [ $i -eq 4 ]; then + echo "http-server startup timeout" >&2 + test_done "$testroot" "1" + # timeout(1) will kill the server eventually + return 1 + fi + sleep 1 # server is still starting up + done + http_pid=`head -n 1 $testroot/stderr | cut -d ':' -f1` + trap "kill -9 $http_pid; wait $http_pid" HUP INT QUIT PIPE TERM + got send -f -t 1.0 -q -r $testroot/repo-clone ret=$? if [ $ret -ne 0 ]; then @@ -729,7 +877,8 @@ test_tag_changed() { return 1 fi - wait %1 # wait for the http "server" + kill $http_pid + wait $http_pid # XXX: at the moment this is exactly the same as the "new tag" # notification @@ -771,12 +920,105 @@ test_tag_changed() { test_done "$testroot" "$ret" } +test_commit_and_tag_created() { + local testroot=`test_init commit_and_tag_created 1` + + got clone -a -q ${GOTD_TEST_REPO_URL} $testroot/repo-clone + ret=$? + if [ $ret -ne 0 ]; then + echo "got clone failed unexpectedly" >&2 + test_done "$testroot" 1 + return 1 + fi + + got checkout -q $testroot/repo-clone $testroot/wt >/dev/null + ret=$? + if [ $ret -ne 0 ]; then + echo "got checkout failed unexpectedly" >&2 + test_done "$testroot" 1 + return 1 + fi + + echo "change alpha again" >> $testroot/wt/alpha + (cd $testroot/wt && got commit -m 'make changes' > /dev/null) + got tag -r $testroot/repo-clone -m "new tag" 2.0 > /dev/null + local commit_id=`git_show_head $testroot/repo-clone` + local tagger_time=`git_show_tagger_time $testroot/repo-clone 2.0` + + timeout 20 ./http-server -a $AUTH -p "$GOTD_TEST_HTTP_PORT" \ + > $testroot/stdout 2> $testroot/stderr & + + sleep 1 # server starts up + for i in 1 2 3 4; do + if grep -q ': ready' $testroot/stdout; then + break + fi + if [ $i -eq 4 ]; then + echo "http-server startup timeout" >&2 + test_done "$testroot" "1" + # timeout(1) will kill the server eventually + return 1 + fi + sleep 1 # server is still starting up + done + + http_pid=`head -n 1 $testroot/stderr | cut -d ':' -f1` + trap "kill -9 $http_pid; wait $http_pid" HUP INT QUIT PIPE TERM + + got send -T -q -r $testroot/repo-clone + ret=$? + if [ $ret -ne 0 ]; then + echo "got send failed unexpectedly" >&2 + test_done "$testroot" "1" + return 1 + fi + + kill $http_pid + wait $http_pid + + touch "$testroot/stdout.expected" + ed -s "$testroot/stdout.expected" <<-EOF + a + {"notifications":[{ + "type":"tag", + "repo":"test-repo", + "authenticated_user":"${GOTD_DEVUSER}", + "tag":"refs/tags/2.0", + "tagger":{ + "full":"$GOT_AUTHOR", + "name":"$GIT_AUTHOR_NAME", + "mail":"$GIT_AUTHOR_EMAIL", + "user":"$GOT_AUTHOR_11" + }, + "date":$tagger_time, + "object":{ + "type":"commit", + "id":"$commit_id" + }, + "message":"new tag\n\n" + }]} + . + ,j + w + EOF + + cmp -s $testroot/stdout.expected $testroot/stdout + ret=$? + if [ $ret -ne 0 ]; then + diff -u $testroot/stdout.expected $testroot/stdout + test_done "$testroot" "$ret" + return 1 + fi + + test_done "$testroot" "$ret" +} test_parseargs "$@" run_test test_file_changed -run_test test_bad_utf8 -run_test test_many_commits_not_summarized -run_test test_many_commits_summarized -run_test test_branch_created -run_test test_branch_removed -run_test test_tag_created -run_test test_tag_changed +#run_test test_bad_utf8 +#run_test test_many_commits_not_summarized +#run_test test_many_commits_summarized +#run_test test_branch_created +#run_test test_branch_removed +#run_test test_tag_created +#run_test test_tag_changed +#run_test test_commit_and_tag_created