t5562: skip if NO_CURL is enabled

6c213e863a ("http-backend: respect CONTENT_LENGTH for receive-pack", 2018-07-27) introduced all tests but without a check for CURL support from git.

---
 t/t5562-http-backend-content-length.sh | 6 ++++++
 1 file changed, 6 insertions(+)

index b24d8b05a4..7594899471 100755
@@ -3,6 +3,12 @@
 test_description='test git-http-backend respects CONTENT_LENGTH'
 . ./test-lib.sh
 
+if test -n "$NO_CURL"
+then
+	skip_all='skipping test, git built without http support'
+	test_done
+fi
+
 test_lazy_prereq GZIP 'gzip --version'
 
 verify_http_result() {

2.20.0.rc0

The tests should not be using curl, they just pipe data to http-backend's standard input.

Max

NO_CURL reflects the build setting (for http support); CURL checks for the curl binary, but as Ævar points out the requirements must be from somewhere else since a NO_CURL=1 build (tested in macOS) still passes the test, but not in NetBSD.

tests 3-8 seem to fail because perl is hardcoded to /urs/bin/perl in t5562/invoke-with-content-length.pl, while I seem to be getting some sporadic errors in 9 with the following output :

++ env CONTENT_TYPE=application/x-git-receive-pack-request QUERY_STRING=/repo.git/git-receive-pack 'PATH_TRANSLATED=/home/carenas/src/git/t/trash directory.t5562-http-backend-content-length/.git/git-receive-pack' GIT_HTTP_EXPORT_ALL=TRUE REQUEST_METHOD=POST /home/carenas/src/git/t/t5562/invoke-with-content-length.pl push_body git http-backend
++ verify_http_result '200 OK'
++ grep fatal: act.err
Binary file act.err matches
++ return 1
error: last command exited with $?=1
not ok 9 - push plain

and the following output in act.err (with a 200 in act)

fatal: the remote end hung up unexpectedly

Carlo

I see.

In other perl files I can see either '#!/usr/bin/perl' or '#!/ust/bin/env perl'. The second one should be more portable. Does the latter work on the NetBSD?

To all: what is supposed to be done about it?

This is more complicated.

Does it happen often?

Does test 12 ("push gzipped") ever fail?

So far I can imagine either a buffering issue or some mistake in length calculation.

You should swap this out for $PERL_PATH. You can use write_script() to help if you're copying the script around anyway. Though it looks like you just run it from the one function. So maybe just:

index b24d8b05a4..90d890d02f 100755
@@ -31,6 +31,7 @@ test_http_env() {
 		PATH_TRANSLATED="$PWD/.git/git-$handler_type-pack" \
 		GIT_HTTP_EXPORT_ALL=TRUE \
 		REQUEST_METHOD=POST \
+		"$PERL_PATH" \
 		"$TEST_DIRECTORY"/t5562/invoke-with-content-length.pl \
 		    "$request_body" git http-backend >act.out 2>act.err
 }

(note that it's normally OK to just run "perl", because we use a shell-function wrapper that respects $PERL_PATH, but here we're actually passing it to "env").

You could also lose the executable bit on the script at that point. It doesn't matter much, but it would catch an erroneous call relying on the shebang line.

-Peff

From: Jeff King <[email protected]>

Some systems do not have perl installed to /usr/bin. Use the variable from the build settiings, and call perl directly than via shebang.

---
Submitting. Could you sign-off? Also removed shebang from the script as it is not needed

 t/t5562-http-backend-content-length.sh | 1 +
 t/t5562/invoke-with-content-length.pl  | 1 -
 2 files changed, 1 insertion(+), 1 deletion(-)
 mode change 100755 => 100644 t/t5562/invoke-with-content-length.pl

index b24d8b05a4..90d890d02f 100755
@@ -31,6 +31,7 @@ test_http_env() {
 		PATH_TRANSLATED="$PWD/.git/git-$handler_type-pack" \
 		GIT_HTTP_EXPORT_ALL=TRUE \
 		REQUEST_METHOD=POST \
+		"$PERL_PATH" \
 		"$TEST_DIRECTORY"/t5562/invoke-with-content-length.pl \
 		    "$request_body" git http-backend >act.out 2>act.err
 }

old mode 100755
new mode 100644
index 6c2aae7692..0943474af2
@@ -1,4 +1,3 @@
-#!/usr/bin/perl
 use 5.008;
 use strict;
 use warnings;

2.19.0.1202.g68e1e8f04e

IMHO leaving the shebang might be better if only for consistency but could go eitherway

Carlo

Yep:

As Carlos mentioned, I think you could leave the shebang as documentation, but I'm OK either way.

-Peff

This bit me today, too, and I can reproduce it by running under my stress-testing script.

Curiously, the act.err file also has 54 NUL bytes before the "fatal:" message. I tried adding an "strace" to see who was producing that output, but I can't seem to get it to fail when running under strace (presumably because the timing is quite different, and this likely some kind of pipe race).

-Peff

FWIW the issue goes away when more than 1 CPU is used in NetBSD 8,0 (32-bit) and for some tracing, it would seem that it gets 0 when trying to read 4 bytes from what I think is a pipe that connects to a child that has been gone already for a while.

Carlo

Could you clarify it? I'm afraid I don't understand.

Meanwhile, I've been staring at code and so far don't have any assumption where it could fail. Except basic things like something is wrong with forking or reading/writing pipes, but then it would have bigger consequences.

Also, I tried to look at it with NetBSD but cannot get past error, while running tests:

There is the following code there:

-----

                if test -z "$test_untraceable" || {
                     test -n "$BASH_VERSION" && {
                       test ${BASH_VERSINFO[0]} -gt 4 || { # line 327
                         test ${BASH_VERSINFO[0]} -eq 4 &&
                         test ${BASH_VERSINFO[1]} -ge 1

-----

Should I install bash for it to work? I cannot say I understand what the message is about.

yes, you need to install bash and use SHELL_PATH=/usr/pkg/bin/bash; PERL_PATH=/usr/pkg/bin/perl for the perl script

Carlo

the error that gets eventually to stderr in the caller comes from get_packet_data, who is trying to read 4 bytes and gets 0. when looking at the trace (obtained with ktrace) I see there is no longer any other process running,

the last child of it is long gone with an error as shown by :

  9255      1 git-http-backend CALL  close(1)
  9255      1 git-http-backend RET   close 0
  9255      1 git-http-backend CALL  read(0,0xbfb2bb14,0)
  9255      1 git-http-backend GIO   fd 0 read 0 bytes
       ""
  9255      1 git-http-backend RET   read 0
  9255      1 git-http-backend CALL  write(2,0xbfb2a604,0x36)
  9255      1 git-http-backend GIO   fd 2 wrote 54 bytes
       "fatal: request ended in the middle of the gzip stream\n"
  9255      1 git-http-backend RET   write 54/0x36
  9255      1 git-http-backend CALL  write(1,0xb781f0e0,0x94)
  9255      1 git-http-backend RET   write -1 errno 9 Bad file descriptor

not sure how it got into that state, though

Carlo

Yes too early close of the input data is the thing which triggers the "remote end hung up unexpectedly" message.

do you mean git receive-pack? This is strange, all its parents should be waiting for it to exit.

...

This should be some other test than push_plain, some of the gzip related ones. Are there other tests failing?

This is interesting. http-backend for some reason closes its stdout. Here it then tries to write there something. I have not seen it in my push_plain run. Maybe it worth redirecting instead to stderr, to avoid losing some diagnostics?

it should, but I should note that for test 9 to fail, then either (or both) tests 7 and 8 should first succeed; not that I'd seen any other test fail (after I locally patched the perl path, of course) even when reordering them and while making sure tests 1 and 2 run first to create the dependencies for the rest

Peff, could you elaborate on your "load testing" setup? which could give us any hints
on what to look for?, FWIW I hadn't been able to reproduce the problem anywhere else (and not for a lack of trying)

that should help with the garbled output from stderr, AFAIK the process API allows creating
a pipe specifically for that with would be better than redirecting stderr into stdout.

the fact we got EBADF means that there is a problem somewhere though in the way the
previous failure that closed stdout got handled (which should had been most likely in
the call to die)

Carlo

PS. upstreaming the PERL_PATH fix is likely to be good to do soonish as I presume at least all BSD might be affected, let me know if you would rather me do that instead as I suspect we might be deadlocked otherwise ;)

The script I use is at:

https://github.com/peff/git/blob/meta/stress

which you invoke like "/path/to/stress t5562" from the top-level of a git.git checkout. It basically just runs a loop of twice as many simultaneous invocations of the test script as you have CPUs, and waits for one to fail. The load created by all of the runs tends to flush out timing effects after a while.

It fails for me on t5562 within 30 seconds or so (but note that in this particular case it sometimes takes a while to produce the final output because invoke-with-content-length misses the expected SIGCLD and sleeps the full 60 seconds).

You'll probably need to tweak the variables at the top of the script for your system.

Yeah, the $PERL_PATH thing is totally orthogonal, and should graduate separately.

-Peff

I have observed it caught failure at the very first run. However I could not fail t again. I tried running up to 20 instances, with 1 or 2 active cores (that's all I have here), also edited the test to include only push_plain case, and repeat it several times, to avoid running irrelevant cases, the failure never happened again.

The first failure was a bit unusual, in the ouput actually all tests were marked as passed, but it still failed somehow. Unfortunately, I did not save the output.

I submitted the perl patch

Max

as I explained previously[1] and as odd as it might seem the push_plain case ONLY
fails if your run them together with the other tests that return errors with compressed input

frankly I don't understand how one could affect the other as they should be running in independent processes but it happens fairly consistently in NetBSD (tested 7.1, 7.2, 8) with only one CPU (tested i386 and amd64)

Carlo

[1] https://public-inbox.org/git/[email protected]/T/#m041e9703432c39dcb04fe10e86fc53d5254474b4

Some expected failures of git-http-backend leave running its children (receive-pack or upload-pack) which still hold opened descriptors to act.err and with some probability they live long enough to write their failure messages after next test has already truncated the files. This causes occasional failures of the test script.

Avoid the issue by unlinking the older files before writing to them.

---
Thanks for the analysis. I seem to have guessed the reason. This patch should prevent it.

I think the tests should somehow make sure there are no such late processes. I can see 2 options:
* somehow find out in the tests all children and wait for them. I have no idea how.
* make http-backend close handle to its child and wait for it to exit before dying. This would not prevent childrenc in general, because http-backend may be killed, but not in our expected failure cases

Actually, don't the children receive some SIGHUP? Maybe thy should. However, it would still take some time for them to handle it, so it does not fully solve the issue

 t/t5562-http-backend-content-length.sh | 4 ++++
 1 file changed, 4 insertions(+)

index 90d890d02f..bb53f82c0c 100755
@@ -25,6 +25,8 @@ test_http_env() {
 	handler_type="$1"
 	request_body="$2"
 	shift
+	(rm -f act.out || true) &&
+	(rm -f act.err || true) &&
 	env \
 		CONTENT_TYPE="application/x-git-$handler_type-pack-request" \
 		QUERY_STRING="/repo.git/git-$handler_type-pack" \

@@ -155,6 +157,8 @@ test_expect_success 'CONTENT_LENGTH overflow ssite_t' '
 '
 
 test_expect_success 'empty CONTENT_LENGTH' '
+	(rm -f act.out || true) &&
+	(rm -f act.err || true) &&
 	env \
 		QUERY_STRING="service=git-receive-pack" \
 		PATH_TRANSLATED="$PWD"/.git/info/refs \

2.19.0.1202.g68e1e8f04e

Another thing. The analysis in your log message talks about a stray process holding open filehandles to these files. An attempt to remove them in such a stat would fail on some systems, so "||true" would not help, would it? It just hides the failure to remove, and when ||true is useful in hiding th failure _is_ when such a stray process is still there, waiting to corrupt the output of the next request and breaking the test, no?

I do agree that forcing the parent to wait, like you described in the comment, would be far more preferrable, but until that happens, a better workaround might be to write into unique output filenames (act1.out, act2.out, etc.); that way, you do not have to worry about the output file for the next request getting clobbered by a stale process handling the previous request. But at the same time, wouldn't this suggest that the test or the previous request may see an incomplete output, as the analysed problem is that such a process is writing to the output file very late, while we are preparing to test the enxt request, which meas we have already checked the output file for the previous request, right? So even without ||true, I am not sure how true a "solution" this change is to the issue.

Yes I agree

Yes it may miss the child's message. But in this case of failed http-backend process, there should be already one "fatal:" message in the act.err from the parent, and missing another one does not change the outcome.

Some expected failures of git-http-backend leaves running its children (receive-pack or upload-pack) which still hold opened descriptors to act.err and with some probability they live long enough to write there their failure messages after next test has already truncated the files. This causes occasional failures of the test script.

Avoid the issue by using separated output and error file for each test, apprending the test number to their name.

---
Use another output and error files for each test

 t/t5562-http-backend-content-length.sh | 8 ++++----
 1 file changed, 4 insertions(+), 4 deletions(-)

index 90d890d02f..9ebbd77bbb 100755
@@ -8,12 +8,12 @@ test_lazy_prereq GZIP 'gzip --version'
 verify_http_result() {
 	# some fatal errors still produce status 200
 	# so check if there is the error message
-	if grep 'fatal:' act.err
+	if grep 'fatal:' act.err.$test_count
 	then
 		return 1
 	fi
 
-	if ! grep "Status" act.out >act
+	if ! grep "Status" act.out.$test_count >act
 	then
 		printf "Status: 200 OK\r\n" >act
 	fi

@@ -33,7 +33,7 @@ test_http_env() {
 		REQUEST_METHOD=POST \
 		"$PERL_PATH" \
 		"$TEST_DIRECTORY"/t5562/invoke-with-content-length.pl \
-		    "$request_body" git http-backend >act.out 2>act.err
+		    "$request_body" git http-backend >act.out.$test_count 2>act.err.$test_count
 }
 
 ssize_b100dots() {

@@ -161,7 +161,7 @@ test_expect_success 'empty CONTENT_LENGTH' '
 		GIT_HTTP_EXPORT_ALL=TRUE \
 		REQUEST_METHOD=GET \
 		CONTENT_LENGTH="" \
-		git http-backend <empty_body >act.out 2>act.err &&
+		git http-backend <empty_body >act.out.$test_count 2>act.err.$test_count &&
 	verify_http_result "200 OK"
 '
 

2.19.0.1202.g68e1e8f04e

Stray processes can sometimes have funny effects on an outer test harness, too. E.g., I think I've seen hangs running t5562 under prove, because some process is holding open a pipe descriptor. This would probably fix that, too.

But if we can't do that immediately for some reason, I do agree with everything else you said here. ;)

-Peff

It looks like it can be done as simple as:

@@ -486,6 +486,8 @@ static void run_service(const char **argv, int buffer_input)
        if (buffer_input || gzipped_request || req_len >= 0)
                cld.in = -1;
        cld.git_cmd = 1;
+       cld.clean_on_exit = 1;
+       cld.wait_after_clean = 1;
        if (start_command(&cld))
                exit(1);
 

at least according to strate it does what it should.

If http-backend dies because of errors, started upload-pack or receive-pack are not killed and waited, but rather stay running for somtime until they exits because of closed stdin. It may be undesirable in working environment, and it also causes occasional failure of t5562, because the processes keep opened act.err, and sometimes write there errors after next test started using the file.

Fix by enabling cleaning of the command at http-backed exit.

---
This seems to fix the issue at NetBSD. I verified it manually with strace but could not catch the visible timing effect in tests at Linux. So no tests for it.

the "t5562: do not reuse output files" patches are not needed then

 http-backend.c | 2 ++
 1 file changed, 2 insertions(+)

index 9e894f197f..29e68e38b5 100644
@@ -486,6 +486,8 @@ static void run_service(const char **argv, int buffer_input)
 	if (buffer_input || gzipped_request || req_len >= 0)
 		cld.in = -1;
 	cld.git_cmd = 1;
+	cld.clean_on_exit = 1;
+	cld.wait_after_clean = 1;
 	if (start_command(&cld))
 		exit(1);
 

2.19.0.1202.g68e1e8f04e

"sometime" (will fix locally, no reason for a resend).

"they exit" (ditto)

Thanks for a clear explanation.

Will queue.

Sounds sane.

I am offhand not sure what the right value of wait_after_clean for this codepath be, though. 46df6906 ("execv_dashed_external: wait for child on signal death", 2017-01-06) made this non-default but turned it on for dashed externals (especially to help the case where they spawn a pager), as the parent has nothing other than to wait for the child to exit in that codepath. Does the same reasoning apply here, too?

This is a meta point, but I wonder if there is an easy way to "grep" for uses of run-command interface that do *not* set clean_on_exit. The pager that can outlive us long after we exit, kept alive while the user views our output, is an example cited by afe19ff7 ("run-command: optionally kill children on exit", 2012-01-07), and while I am wondering if the default should hae been to kill the children instead, such a "grep" would have been very useful to know what codepaths would be affected if we flipped the default.

As far as I understand, the reason to _not_ wait was that the child might still be expecting closed stdin even after receiving SIGTERM, so parent would wait forever. But this is not clearly the case here. And otherwise there should be no reason to not wait, as long as we are interested in synchronous exiting of the child.

In my Linux experiments the child was exiting because of signal earlier than because of closed stdin, but who knows, maybe with some bad luck the signal would be delivered after the closed stdin, and we would still have the issue. After all, at Linux it was mostly working even without fix.

Some expected failures of git-http-backend leaves running its children (receive-pack or upload-pack) which still hold opened descriptors to act.err and with some probability they live long enough to write there their failure messages after next test has already truncated the files. This causes occasional failures of the test script.

Avoid the issue by unlinking the older files before writing to them.

---
Thanks. Updated

 t/t5562-http-backend-content-length.sh | 2 ++
 1 file changed, 2 insertions(+)

index 90d890d02f..3a9f7a14e2 100755
@@ -25,6 +25,7 @@ test_http_env() {
 	handler_type="$1"
 	request_body="$2"
 	shift
+	rm -f act.out act.err &&
 	env \
 		CONTENT_TYPE="application/x-git-$handler_type-pack-request" \
 		QUERY_STRING="/repo.git/git-$handler_type-pack" \

@@ -155,6 +156,7 @@ test_expect_success 'CONTENT_LENGTH overflow ssite_t' '
 '
 
 test_expect_success 'empty CONTENT_LENGTH' '
+	rm -f act.out act.err &&
 	env \
 		QUERY_STRING="service=git-receive-pack" \
 		PATH_TRANSLATED="$PWD"/.git/info/refs \

2.19.0.1202.g68e1e8f04e

On the subject of orthagonal things: This test fails on AIX with /bin/sh (but not /bin/bash) due to some interaction of ssize_b100dots and the build_option function. On that system:

    $ ./git version --build-options
    git version 2.20.0-rc1
    cpu: 00FA74164C00
    no commit associated with this build
    sizeof-long: 4
    sizeof-size_t: 4

But it somehow ends up in the 'die' condition in that case statement. I dug around briefly but couldn't find the cause, probably some limitation in the shell constructs it supports. Just leaving a note about this...

That's weird. The functions involved are pretty vanilla. I'd suspect something funny with the sed invocation:

  build_option () {
        git version --build-options |
        sed -ne "s/^$1: //p"
  }

but that's the one thing that shouldn't be dependent on the shell in use.

Can you manually replicate the shell commands to see where it goes wrong?

-Peff

I saw this a few times on Travis CI as well.

I think those NUL bytes come from the file system.

The contents of 'act.err' from the previous test ('fetch gzipped empty') is usually:

fatal: request ended in the middle of the gzip stream
fatal: the remote end hung up unexpectedly

Notice that the length of the first line is 54 bytes (including the trailing newline). So I suspect that the following is happening:

- http-backend in the previous test writes the first line,
- that test finishes and this one starts,
- this test truncates 'act.err',
- and then the still-running http-backend from the previous test finally writes the second line.

So at this point 'act.err' is empty, but the offset of the fd of the redirection still open from the previous test is at 54, so the file system fills those bytes with NULs.

Right, good thinking. Thanks for the explanation!

-Peff