{"thread":{"id":"55729","subject":"[BUG] clone of large repo fails when server closes idle SSH session during \"Resolving deltas\"","startedAt":"2021-05-19T04:01:03Z","lastAt":"2021-05-19T16:11:09Z","messageCount":4,"participants":["Greg Pflaum","Jeff King"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"424916","messageId":"OF9ECB0D17.7C6A7258-ON852586DA.0014125E-852586DA.0014B7AB@pnp-hcl.com","threadId":"55729","inReplyTo":null,"subject":"[BUG] clone of large repo fails when server closes idle SSH session during \"Resolving deltas\"","fromName":"Greg Pflaum","fromEmail":"greg.pflaum@pnp-hcl.com","sentAt":"2021-05-19T03:46:17Z","receivedAt":"2021-05-19T04:01:03Z","isPatch":false,"sender":{"key":"greg.pflaum@pnp-hcl.com","avatar":null},"body":"Git's handling of the SSH session during \"git clone\" changed between Git\n2.17.0 and 2.31.1, causing cloning of a large repo to fail when the server\ncloses the idle session during the \"Resolving deltas\" phase.\n\nIn the older version, git closes the SSH session after \"Receiving objects\"\nand before \"Resolving deltas\". In the newer version, git doesn't close the\nSSH session until after \"Resolving deltas\" finishes. In the newer version,\nif \"Resolving deltas\" takes a long time (over 2 minutes for our large \nrepo)\nand the server closes the idle SSH session (60 seconds for our GitHub\nEnterprise server), git displays the error message \"Connection to\ngit.example.com closed by remote host\", finishes resolving deltas, then \nexits\nwithout checking out files.\n\nSuccessful with Git 2.17.0:\n\n> git clone git@git.example.com:org/bigrepo.git\nCloning into 'bigrepo'...\nremote: Enumerating objects: 260, done.\nremote: Counting objects: 100% (260/260), done.\nremote: Compressing objects: 100% (170/170), done.\nremote: Total 361839 (delta 74), reused 174 (delta 37), pack-reused 361579\nReceiving objects: 100% (361839/361839), 4.47 GiB | 36.71 MiB/s, done.\nResolving deltas: 100% (252249/252249), done.\nChecking out files: 100% (59466/59466), done.\n\nFails with Git 2.31.1:\n\ngit clone git@git.example.com:org/bigrepo.git\nCloning into 'bigrepo'...\nremote: Enumerating objects: 363, done.\nremote: Counting objects: 100% (363/363), done.\nremote: Compressing objects: 100% (221/221), done.\nReceiving objects: 100% (361930/361930), 4.47 GiB | 36.37 MiB/s, done.\nRConnection to git.example.com closed by remote host.esolving deltas:  39% \n(98729/252244)\nResolving deltas: 100% (252244/252244), done.\n\nWhat did you do before the bug happened? (Steps to reproduce your issue)\n\nRan \"git clone git@git.example.com:org/bigrepo.git\"\n\nWhat did you expect to happen? (Expected behavior)\n\nExpected successful creation of a cloned repo.\n\nWhat happened instead? (Actual behavior)\n\nRepo was partially created, but files were not checked out. Branches and \ntags\nalso seem to be missing from the repo.\n\nWhat's different between what you expected and what actually happened?\n\nWith the old Git version, cloning the repo is successful. With the newer\nversion it fails.\n\nAnything else you want to add:\n\nA workaround is to configure the SSH client to prevent the server from\nseeing an idle session, by adding these lines to .ssh/config:\n\nHost git.example.com\n    # Send keep-alive message to server every 30 seconds\n    # so the server won't close an idle session.\n    ServerAliveInterval 30\n\n\n[System Info]\ngit version:\ngit version 2.31.1.windows.1\ncpu: x86_64\nbuilt from commit: c5f0be26a7e3846e3b6268d1c6c4800d838c6bbb\nsizeof-long: 4\nsizeof-size_t: 8\nshell-path: /bin/sh\nfeature: fsmonitor--daemon\nuname: Windows 10.0 14393\ncompiler info: gnuc: 10.2\nlibc info: no libc information available\n$SHELL (typically, interactive shell): <unset>\n\n\n[Enabled Hooks]\nnot run from a git repository - no hooks to show\n\n"},{"id":"424928","messageId":"YKTbsByUaPEuDNtR@coredump.intra.peff.net","threadId":"55729","inReplyTo":"OF9ECB0D17.7C6A7258-ON852586DA.0014125E-852586DA.0014B7AB@pnp-hcl.com","subject":"Re: [BUG] clone of large repo fails when server closes idle SSH session during \"Resolving deltas\"","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-05-19T09:34:40Z","receivedAt":"2021-05-19T09:34:43Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, May 18, 2021 at 11:46:17PM -0400, Greg Pflaum wrote:\n\n> Git's handling of the SSH session during \"git clone\" changed between Git\n> 2.17.0 and 2.31.1, causing cloning of a large repo to fail when the server\n> closes the idle session during the \"Resolving deltas\" phase.\n\nInteresting find.\n\nDuring that phase, all communication with the server is finished. We're\nnot expecting it to say anything else, and I'd have actually expected us\nto have hung up the connection.\n\nBut I can definitely reproduce the issue by fetching even a moderate\nsized repository like git.git, and observing that ssh is still running\nwhen we hit the \"Resolving deltas\" phase. And indeed, killing it at that\nstep shows the problem:\n\n  $ git clone --bare git@github.com:git/git foo.git\n  Cloning into bare repository 'foo.git'...\n  remote: Enumerating objects: 307777, done.\n  remote: Counting objects: 100% (114/114), done.\n  remote: Compressing objects: 100% (48/48), done.\n  remote: Total 307777 (delta 72), reused 94 (delta 66), pack-reused 307663\n  Receiving objects: 100% (307777/307777), 159.14 MiB | 30.71 MiB/s, done.\n  Resolving deltas: 100% (229729/229729), done.\n  error: ssh died of signal 9\n\nIn another terminal I waited for it to hit \"resolving\" and ran:\n\n  kill -9 $(ps ax | grep ssh | grep github | awk '{print $1}')\n\nYou can see that we did completely successfully receive the incoming\npack. It's just that we then do an over-eager check of ssh's exit code\nand complain when disconnecting the transport.\n\nI had a hunch that this was related to the v2 protocol (which became the\ndefault between the two versions you mentioned). And indeed, running\n\"git clone -c protocol.version=0 clone ...\" makes it go away.\n\nSo I'd guess that in the v0 protocol, we close the pipe going to ssh's\nstdin (which does a half-duplex shutdown, and then when the server side\ncloses its pipe, ssh exits completely).\n\nBut in v2, we presumably don't. Which is not too surprising; v2's view\nof ssh is much more as a transport over which it will make several\nrequest/response pairs. So the caller would have to explicitly indicate\nthat this is the final request, and the transport can be terminated\nafter that. That doesn't seem too complex conceptually, but I worry\nimplementing it will run into conflicts with how the v2 code works.\n\nAnother side issue is that once the protocol conversation has finished,\nI'm not sure if it's really useful for us to detect and complain about\nssh's exit code. We know the other side completed the conversation\nsuccessfully, and we have nothing left to ask it. So a fix for your\nimmediate pain would be to stop noticing that. I think the root issue is\nstill worth addressing, though; we are tying up network and local\nresources with a useless to-be-closed ssh connection.\n\n-Peff\n"},{"id":"424931","messageId":"YKTg8nYjSGpKbq8W@coredump.intra.peff.net","threadId":"55729","inReplyTo":"YKTbsByUaPEuDNtR@coredump.intra.peff.net","subject":"Re: [BUG] clone of large repo fails when server closes idle SSH session during \"Resolving deltas\"","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-05-19T09:57:06Z","receivedAt":"2021-05-19T09:57:08Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, May 19, 2021 at 05:34:40AM -0400, Jeff King wrote:\n\n> Another side issue is that once the protocol conversation has finished,\n> I'm not sure if it's really useful for us to detect and complain about\n> ssh's exit code. We know the other side completed the conversation\n> successfully, and we have nothing left to ask it. So a fix for your\n> immediate pain would be to stop noticing that. I think the root issue is\n> still worth addressing, though; we are tying up network and local\n> resources with a useless to-be-closed ssh connection.\n\nBy the way, there's an interesting subtlety / bug related to this. While\n\"git clone\" does return a failed exit code in this case, it leaves the\nrepository directory in place! And because no real error occurred with\nthe clone, you can use it as usual (though I think if it's a non-bare\nclone, you'd need to run \"git checkout\" fill in the working tree).\n\nPropagating the error code comes from aab179d937 (builtin/clone.c: don't\nignore transport_fetch_refs() errors, 2020-12-03). So prior to Git\nv2.30.0, your case would kind-of work.\n\nBut:\n\n  - I think that is just \"clone\"; a \"git fetch\" would always have\n    propagated the error from transport_fetch_refs()\n\n  - that commit was right to start propagating the error code from\n    transport_fetch_refs(). While in this specific case, we happened to\n    produce a useful repository directory, most other errors would not.\n\n  - there _is_ a bug in aab179d937, though. When it sees the error it\n    should clean up the repo directory. And that even happens\n    automatically via an atexit() handler. But because rather than\n    calling die() it jumps to cleanup code, it mistakenly sets the flag\n    for \"leave the directory in place\".\n\n  - any logic to ignore errors would have to be inside the transport\n    code (i.e., it realizes that ssh exiting non-zero isn't a big deal\n    anymore, and then transport_fetch_refs() still returns success).\n\n-Peff\n"},{"id":"424970","messageId":"YKU4mbq/am/liAN4@coredump.intra.peff.net","threadId":"55729","inReplyTo":"YKTbsByUaPEuDNtR@coredump.intra.peff.net","subject":"[PATCH] fetch-pack: signal v2 server that we are done making requests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-05-19T16:11:05Z","receivedAt":"2021-05-19T16:11:09Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, May 19, 2021 at 05:34:40AM -0400, Jeff King wrote:\n\n> On Tue, May 18, 2021 at 11:46:17PM -0400, Greg Pflaum wrote:\n> \n> > Git's handling of the SSH session during \"git clone\" changed between Git\n> > 2.17.0 and 2.31.1, causing cloning of a large repo to fail when the server\n> > closes the idle session during the \"Resolving deltas\" phase.\n> \n> Interesting find.\n> \n> During that phase, all communication with the server is finished. We're\n> not expecting it to say anything else, and I'd have actually expected us\n> to have hung up the connection.\n\nOK, here's the fix I came up with. It's a two-line code change, of\ncourse, but I tried to lay out all of my thinking about why this is the\nright thing to do. Apologies in advance for the length. :)\n\n-- >8 --\nSubject: [PATCH] fetch-pack: signal v2 server that we are done making requests\n\nWhen fetching with the v0 protocol over ssh (or a local upload-pack with\npipes), the server closes the connection as soon as it is finished\nsending the pack. So even though the client may still be operating on\nthe data via index-pack (e.g., resolving deltas, checking connectivity,\netc), the server has released all resources.\n\nWith the v2 protocol, however, the server considers the ssh session only\nas a transport, with individual requests coming over it. After sending\nthe pack, it goes back to its main loop, waiting for another request to\ncome from the client. As a result, the ssh session hangs around until\nthe client process ends, which may be much later (because resolving\ndeltas, etc, may consume a lot of CPU).\n\nThis is bad for two reasons:\n\n  - it's consuming resources on the server to leave open a connection\n    that won't see any more use\n\n  - if something bad happens to the ssh connection in the meantime (say,\n    it gets killed by the network because it's idle, as happened in a\n    real-world report), then ssh will exit non-zero, and we'll propagate\n    the error up the stack.\n\nThe server is correct here not to hang up after serving the pack. The v2\nprotocol's design is meant to allow multiple requests like this, and\nhanging up would be the wrong thing for a hypothetical client which was\nplanning to make more requests (though in practice, the git.git client\nnever would, and I doubt any other implementations would either).\n\nThe right thing is instead for the client to signal to the server that\nit's not interested in making more requests. We can do that by closing\nthe pipe descriptor we use to write to ssh. This will propagate to the\nserver upload-pack as an EOF when it tries to read the next request (and\nthen it will close its half, and the whole connection will go away).\n\nIt's important to do this \"half duplex\" shutdown, because we have to do\nit _before_ we actually receive the pack. This is an artifact of the way\nfetch-pack and index-pack (or unpack-objects) interact. We hand the\nconnection off to index-pack (really, a sideband demuxer which feeds\nit), and then wait until it returns. And it doesn't do that until it has\nresolved all of the deltas in the pack, even though it was done reading\nfrom the server long before.\n\nSo just closing the connection fully after index-pack returns would be\ntoo late; we'd have held it open much longer than was necessary. And\nteaching index-pack to close the connection is awkward. It's not even\nseeing the whole conversation (the sideband demuxer is, but it doesn't\nactually know what's in the packets, or when the end comes).\n\nNote that this close() is happening deep within the transport code. It's\npossible that a caller would want to perform other operations over the\nsame ssh transport after receiving the pack. But as of the current code,\nnone of the callers do, and there haven't been discussions of any plans\nto change this. If we need to support that later, we can probably do so\nby passing down a flag for \"you're the last request on the transport;\nit's OK to close\" instead of the code just assuming that's true.\n\nThe description above all discusses v2 ssh, so it's worth thinking about\nhow this interacts with other protocols:\n\n  - in v0 protocols, we could do the same half-duplex shutdown (it just\n    goes into the v0 do_fetch_pack() instead). This does work, but since\n    it doesn't have the same persistence problem in the first place,\n    there's little reason to change it at this point.\n\n  - local fetches against git-upload-pack on the same machine will\n    behave the same as ssh (they are talking over two pipes, and see EOF\n    on their input pipe)\n\n  - fetches against git-daemon will run this same code, and close one of\n    the descriptors. In practice, this won't do anything, since there\n    our two descriptors are dups of each other, and not part of a\n    half-duplex pair. The right thing would probably be to call\n    shutdown(SHUT_WR) on it. I didn't bother with that here. It doesn't\n    face the same error-code problem (since it's just a TCP connection),\n    so it's really only an optimization problem. And git:// is not that\n    widely used these days, and has less impact on server resources than\n    an ssh termination.\n\n  - v2 http doesn't suffer from this problem in the first place, as our\n    pipes terminate at a local git-remote-https, which is passing data\n    along as individual requests via curl. Probably curl is keeping the\n    TCP/TLS connection open for more requests, and we might be able to\n    tell it manually \"hey, we are done making requests now\". But I think\n    that's much less important. It again doesn't suffer from the\n    error-code problem, and HTTP keepalive is pretty well understood\n    (importantly, the timeouts can be set low, because clients like curl\n    know how to reconnect for subsequent requests if necessary). So it's\n    probably not worth figuring out how to tell curl that we're done\n    (though if we do, this patch is probably the first step anyway;\n    fetch-pack closes the pipe back to remote-https, which would be the\n    signal that it should tell curl we're done).\n\nThe code is pretty straightforward. We close the pipe at the right\nmoment, and set it to -1 to mark it as invalid. I modified the later\ncleanup code to avoid calling close(-1). That's not strictly necessary,\nsince close(-1) is a noop, but hopefully makes things a bit more obvious\nto a reader.\n\nI suspect that trying to call more transport functions after the close()\n(e.g., calling transport_fetch_refs() again) would fail, as it's not\nsmart enough to realize we need to re-open the ssh connection. But\nthat's already true when v0 is in use. And no current callers want to do\nthat (and again, the solution is probably a flag in the transport code\nto keep things open, which can be added later).\n\nThere's no test here, as the situation it covers is inherently racy (the\nquestion is when upload-pack exits, compared to when index-pack finishes\nresolving deltas and exits). The rather gross shell snippet below does\nrecreate the problematic situation; when run on a sufficiently-large\nrepository (git.git works fine), it kills an \"idle\" upload-pack while\nthe client is resolving deltas, leading to a failed clone.\n\n-- >8 --\n(\n\tgit clone --no-local --progress . foo.git 2>&1\n\techo >&2 \"clone exit code=$?\"\n) |\ntr '\\r' '\\n' |\nwhile read line\ndo\n\tcase \"$done,$line\" in\n\t,Resolving*)\n\t\techo \"hit resolving deltas; killing upload-pack\"\n\t\tkillall -9 git-upload-pack\n\t\tdone=t\n\t\t;;\n\tesac\ndone\n-- >8 --\n\nReported-by: Greg Pflaum <greg.pflaum@pnp-hcl.com>\nSigned-off-by: Jeff King <peff@peff.net>\n---\n fetch-pack.c | 9 +++++++++\n transport.c  | 6 ++++--\n 2 files changed, 13 insertions(+), 2 deletions(-)\n\ndiff --git a/fetch-pack.c b/fetch-pack.c\nindex c135635e34..b0c7be717c 100644\n--- a/fetch-pack.c\n+++ b/fetch-pack.c\n@@ -1645,6 +1645,15 @@ static struct ref *do_fetch_pack_v2(struct fetch_pack_args *args,\n \t\t\tif (process_section_header(&reader, \"packfile-uris\", 1))\n \t\t\t\treceive_packfile_uris(&reader, &packfile_uris);\n \t\t\tprocess_section_header(&reader, \"packfile\", 0);\n+\n+\t\t\t/*\n+\t\t\t * this is the final request we'll make of the server;\n+\t\t\t * do a half-duplex shutdown to indicate that they can\n+\t\t\t * hang up as soon as the pack is sent.\n+\t\t\t */\n+\t\t\tclose(fd[1]);\n+\t\t\tfd[1] = -1;\n+\n \t\t\tif (get_pack(args, fd, pack_lockfiles,\n \t\t\t\t     packfile_uris.nr ? &index_pack_args : NULL,\n \t\t\t\t     sought, nr_sought, &fsck_options.gitmodules_found))\ndiff --git a/transport.c b/transport.c\nindex 6cf3da19eb..50f5830eb6 100644\n--- a/transport.c\n+++ b/transport.c\n@@ -427,7 +427,8 @@ static int fetch_refs_via_pack(struct transport *transport,\n \n cleanup:\n \tclose(data->fd[0]);\n-\tclose(data->fd[1]);\n+\tif (data->fd[1] >= 0)\n+\t\tclose(data->fd[1]);\n \tif (finish_connect(data->conn))\n \t\tret = -1;\n \tdata->conn = NULL;\n@@ -869,7 +870,8 @@ static int disconnect_git(struct transport *transport)\n \t\tif (data->got_remote_heads && !transport->stateless_rpc)\n \t\t\tpacket_flush(data->fd[1]);\n \t\tclose(data->fd[0]);\n-\t\tclose(data->fd[1]);\n+\t\tif (data->fd[1] >= 0)\n+\t\t\tclose(data->fd[1]);\n \t\tfinish_connect(data->conn);\n \t}\n \n-- \n2.32.0.rc0.424.g95d3bde94f\n\n"}]}