{"thread":{"id":"42679","subject":"http-backend fatal error message on shallow clone","startedAt":"2016-06-21T11:23:20Z","lastAt":"2016-06-21T16:41:41Z","messageCount":3,"participants":["Eric Wong","Jeff King","Duy Nguyen"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"289748","messageId":"20160621112303.GA21973@dcvr.yhbt.net","threadId":"42679","inReplyTo":null,"subject":"http-backend fatal error message on shallow clone","fromName":"Eric Wong","fromEmail":"e@80x24.org","sentAt":"2016-06-21T11:23:03Z","receivedAt":"2016-06-21T11:23:20Z","isPatch":false,"sender":{"key":"e@80x24.org","avatar":null},"body":"I noticed \"fatal: The remote end hung up unexpectedly\" in server\nlogs from shallow clones.  Totally reproducible in the test\ncases, too.  The following change shows it:\n\ndiff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh\nindex 90e0d6f..cfa55ce 100755\n--- a/t/t5561-http-backend.sh\n+++ b/t/t5561-http-backend.sh\n@@ -132,5 +132,11 @@ test_expect_success 'server request log matches test results' '\n \ttest_cmp exp act\n '\n \n+test_expect_success 'shallow clone' '\n+\tconfig http.uploadpack true &&\n+\tgit clone --depth=1 \"$HTTPD_URL/smart/repo.git\" shallow &&\n+\ttail \"$HTTPD_ROOT_PATH\"/error.log | grep fatal\n+'\n+\n stop_httpd\n test_done\n\n\nAnd the last test ends like this:\n\nexpecting success: \n\tconfig http.uploadpack true &&\n\tgit clone --depth=1 \"$HTTPD_URL/smart/repo.git\" shallow &&\n\ttail \"$HTTPD_ROOT_PATH\"/error.log | grep fatal\n\nCloning into 'shallow'...\n[Tue Jun 21 11:07:41.391269 2016] [cgi:error] [pid 21589] [client 127.0.0.1:37518] AH01215: fatal: The remote end hung up unexpectedly\nok 15 - shallow clone\n\nIt doesn't show above, but I think http-backend exits\nwith a non-zero status, too, which might cause some CGI\nimplementations to complain or break.\n\nNot sure if it's just a corner case that wasn't tested\nor something else, but the clone itself seems successful...\n"},{"id":"289764","messageId":"20160621121041.GA29156@sigill.intra.peff.net","threadId":"42679","inReplyTo":"20160621112303.GA21973@dcvr.yhbt.net","subject":"Re: http-backend fatal error message on shallow clone","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-06-21T12:10:42Z","receivedAt":"2016-06-21T12:17:36Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Jun 21, 2016 at 11:23:03AM +0000, Eric Wong wrote:\n\n> I noticed \"fatal: The remote end hung up unexpectedly\" in server\n> logs from shallow clones.  Totally reproducible in the test\n> cases, too.  The following change shows it:\n> [...]\n> [Tue Jun 21 11:07:41.391269 2016] [cgi:error] [pid 21589] [client 127.0.0.1:37518] AH01215: fatal: The remote end hung up unexpectedly\n> \n> It doesn't show above, but I think http-backend exits\n> with a non-zero status, too, which might cause some CGI\n> implementations to complain or break.\n> \n> Not sure if it's just a corner case that wasn't tested\n> or something else, but the clone itself seems successful...\n\nThe dying process is actually upload-pack. If we instrument it like\nthis:\n\ndiff --git a/upload-pack.c b/upload-pack.c\nindex 9e03c27..a1da676 100644\n--- a/upload-pack.c\n+++ b/upload-pack.c\n@@ -820,6 +820,14 @@ static int upload_pack_config(const char *var, const char *value, void *unused)\n \treturn parse_hide_refs_config(var, value, \"uploadpack\");\n }\n \n+NORETURN\n+static void custom_die(const char *err, va_list params)\n+{\n+\tvreportf(\"fatal: \", err, params);\n+\twarning(\"aborting\");\n+\tabort();\n+}\n+\n int main(int argc, const char **argv)\n {\n \tconst char *dir;\n@@ -836,6 +844,9 @@ int main(int argc, const char **argv)\n \t\tOPT_END()\n \t};\n \n+\twarning(\"running upload-pack\");\n+\tset_die_routine(custom_die);\n+\n \tgit_setup_gettext();\n \n \tpacket_trace_identity(\"upload-pack\");\n\nwe can see two things. One is we can get a backtrace from the core file:\n\n#0  0x00007f04aef51458 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55\n#1  0x00007f04aef528da in __GI_abort () at abort.c:89\n#2  0x0000000000406009 in custom_die (err=0x4ede60 \"The remote end hung up unexpectedly\", \n    params=0x7ffe15858758) at upload-pack.c:828\n#3  0x000000000045ec63 in die (err=0x4ede60 \"The remote end hung up unexpectedly\") at usage.c:108\n#4  0x000000000041e016 in get_packet_data (fd=0, src_buf=0x0, src_size=0x0, dst=0x7ffe158588b0, \n    size=4, options=2) at pkt-line.c:167\n#5  0x000000000041e0ea in packet_read (fd=0, src_buf=0x0, src_len=0x0, \n    buffer=0x73cc40 <packet_buffer> \"deepen 1\", size=65520, options=2) at pkt-line.c:204\n#6  0x000000000041e22b in packet_read_line_generic (fd=0, src=0x0, src_len=0x0, dst_len=0x0)\n    at pkt-line.c:234\n#7  0x000000000041e27c in packet_read_line (fd=0, len_p=0x0) at pkt-line.c:244\n#8  0x0000000000404dc9 in get_common_commits () at upload-pack.c:384\n#9  0x0000000000405eb4 in upload_pack () at upload-pack.c:798\n#10 0x0000000000406229 in main (argc=1, argv=0x7ffe15858c28) at upload-pack.c:872\n\nSo we expected to read a packet but didn't get one. Not surprising. The\ninteresting thing is that we are in get_common_commits(), and if we were\nto get a flush packet in stateless-rpc mode, we would simply exit(0).\nBut we get EOF instead, which provokes packet_read_line() to die.\n\nThe other interesting thing is that we can see in httpd's error.log that\nit is the penultimate upload-pack that dies (I trimmed the log lines for\nreadability):\n\nAH01215: warning: running upload-pack\nAH01215: fatal: The remote end hung up unexpectedly\nAH01215: warning: aborting\nAH01215: error: git-upload-pack died of signal 6\nAH01215: warning: running upload-pack\n\nSo this request actually takes _two_ upload-pack instances to serve\n(which is not uncommon when we need multiple rounds of\nget_common_commits(), though I am a little surprised that would be the\ncase for a clone). And the first one seems to be missing a closing\n\"0000\" flush packet from the client to end it.\n\nIf that analysis is correct, this isn't affecting operation in any way;\nit's just giving a useless message from upload-pack (and as you note,\nthat could trigger http-backend to exit(1), which may make the webserver\nunhappy).\n\nIf we further instrument upload-pack to set GIT_TRACE_PACKET on the\nserver side, we can see the two requests:\n\npacket:  upload-pack< want 379518c0c94e3b1a0710129d03d5560814a0ba6f multi_ack_detailed no-done side-band-64k thin-pack include-tag ofs-delta agent=git/2.9.0.37.gb3ad8ab.dirty\npacket:  upload-pack< deepen 1\npacket:  upload-pack< 0000\npacket:  upload-pack> shallow 379518c0c94e3b1a0710129d03d5560814a0ba6f\npacket:  upload-pack> 0000\n\npacket:  upload-pack< want 379518c0c94e3b1a0710129d03d5560814a0ba6f multi_ack_detailed no-done side-band-64k thin-pack include-tag ofs-delta agent=git/2.9.0.37.gb3ad8ab.dirty\npacket:  upload-pack< deepen 1\npacket:  upload-pack< 0000\npacket:  upload-pack> shallow 379518c0c94e3b1a0710129d03d5560814a0ba6f\npacket:  upload-pack> 0000\npacket:  upload-pack< done\npacket:  upload-pack> NAK\npacket:  upload-pack> 0000\n\nI think in the first one we would get \"deepen 1\" from the client in\nreceive_needs(), and similarly write out our \"shallow\" line. But then we\ngo into get_common_commits() and the client has hung up, which causes\nthe message. Whereas in the second line it gives us a \"done\", which\ncompletes the negotiation.\n\nSo my not-very-educated thoughts are:\n\n  1. The client should probably be sending an extra flush in the first\n     request. Alternatively, in the stateless-rpc case we should just\n     accept the lack of flush as an acceptable end to the request.\n\n  2. Presumably the shallowness is what causes the double-request, as\n     fetch-pack wants to see the shallow list before proceeding. But\n     since it has no actual commits to negotiate, the negotiation is a\n     noop. So probably this case could actually happen in a single\n     request.\n\n     I suspect that other fetches could not, though, so I'm not sure how\n     much effort is worth putting into optimizing.\n\n-Peff\n"},{"id":"289781","messageId":"CACsJy8DQGE2fAgzDdJjL82-UrS00zVwy+u1Jd06xDdYmfC94-w@mail.gmail.com","threadId":"42679","inReplyTo":"20160621121041.GA29156@sigill.intra.peff.net","subject":"Re: http-backend fatal error message on shallow clone","fromName":"Duy Nguyen","fromEmail":"pclouds@gmail.com","sentAt":"2016-06-21T16:41:08Z","receivedAt":"2016-06-21T16:41:41Z","isPatch":false,"sender":{"key":"pclouds@gmail.com","avatar":"https://avatars.githubusercontent.com/u/720?v=4"},"body":"On Tue, Jun 21, 2016 at 2:10 PM, Jeff King <peff@peff.net> wrote:\n> ...\n> So this request actually takes _two_ upload-pack instances to serve\n> (which is not uncommon when we need multiple rounds of\n> get_common_commits(), though I am a little surprised that would be the\n> case for a clone). And the first one seems to be missing a closing\n> \"0000\" flush packet from the client to end it.\n>\n> If that analysis is correct, this isn't affecting operation in any way;\n> it's just giving a useless message from upload-pack (and as you note,\n> that could trigger http-backend to exit(1), which may make the webserver\n> unhappy).\n>\n> If we further instrument upload-pack to set GIT_TRACE_PACKET on the\n> server side, we can see the two requests:\n>\n> packet:  upload-pack< want 379518c0c94e3b1a0710129d03d5560814a0ba6f multi_ack_detailed no-done side-band-64k thin-pack include-tag ofs-delta agent=git/2.9.0.37.gb3ad8ab.dirty\n> packet:  upload-pack< deepen 1\n> packet:  upload-pack< 0000\n> packet:  upload-pack> shallow 379518c0c94e3b1a0710129d03d5560814a0ba6f\n> packet:  upload-pack> 0000\n>\n> packet:  upload-pack< want 379518c0c94e3b1a0710129d03d5560814a0ba6f multi_ack_detailed no-done side-band-64k thin-pack include-tag ofs-delta agent=git/2.9.0.37.gb3ad8ab.dirty\n> packet:  upload-pack< deepen 1\n> packet:  upload-pack< 0000\n> packet:  upload-pack> shallow 379518c0c94e3b1a0710129d03d5560814a0ba6f\n> packet:  upload-pack> 0000\n> packet:  upload-pack< done\n> packet:  upload-pack> NAK\n> packet:  upload-pack> 0000\n>\n> I think in the first one we would get \"deepen 1\" from the client in\n> receive_needs(), and similarly write out our \"shallow\" line. But then we\n> go into get_common_commits() and the client has hung up, which causes\n> the message. Whereas in the second line it gives us a \"done\", which\n> completes the negotiation.\n>\n> So my not-very-educated thoughts are:\n>\n>   1. The client should probably be sending an extra flush in the first\n>      request. Alternatively, in the stateless-rpc case we should just\n>      accept the lack of flush as an acceptable end to the request.\n\nOur pkt-line.c can't deal with eof if I remember correctly (I tried to\nuse pkt-line for the parallel checkout stuff, where workers can also\nexit early...) so sending extra flush may be easier. Old upload-pack\nwill not have a problem with this extra flush right? I haven't checked\nupload-pack.c yet...\n\n>   2. Presumably the shallowness is what causes the double-request, as\n>      fetch-pack wants to see the shallow list before proceeding. But\n>      since it has no actual commits to negotiate, the negotiation is a\n>      noop. So probably this case could actually happen in a single\n>      request.\n\nI seem to recall our discussion a few months(?) ago about quickfetch()\nwhere shallow clone would force another fetch initiated from\nbackfill_tags(). I guess that's why you see two fetches.\n\n>\n>      I suspect that other fetches could not, though, so I'm not sure how\n>      much effort is worth putting into optimizing.\n>\n> -Peff\n> --\n> To unsubscribe from this list: send the line \"unsubscribe git\" in\n> the body of a message to majordomo@vger.kernel.org\n> More majordomo info at  http://vger.kernel.org/majordomo-info.html\n\n\n\n-- \nDuy\n"}]}