{"thread":{"id":"50070","subject":"Periodic hang during git index-pack","startedAt":"2018-12-19T23:00:00Z","lastAt":"2019-02-03T08:17:17Z","messageCount":6,"participants":["Sitsofe Wheeler","Jeff King"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"365604","messageId":"CALjAwxiB1uDfg4iPFjh2dNibEZa5mJ0RwhCzt0R2b87NTVqWfA@mail.gmail.com","threadId":"50070","inReplyTo":null,"subject":"Periodic hang during git index-pack","fromName":"Sitsofe Wheeler","fromEmail":"sitsofe@gmail.com","sentAt":"2018-12-19T22:59:30Z","receivedAt":"2018-12-19T23:00:00Z","isPatch":false,"sender":{"key":"sitsofe@gmail.com","avatar":null},"body":"Hi,\n\nWhile using trying to use git to clone a remote repository git\nindex-pack occasionally goes on to hang:\n\nexport GIT_TRACE=1\ngit clone -n remotehost:diffusion/LIBEDIT/libedit\n22:43:48.948378 git.c:418               trace: built-in: git clone -n\nremotehost:diffusion/LIBEDIT/libedit\nCloning into 'libedit'...\n22:43:48.951196 run-command.c:643       trace: run_command: unset\nGIT_DIR; ssh remotehost 'git-upload-pack\n'\\''diffusion/LIBEDIT/libedit'\\'''\n22:43:49.130517 run-command.c:643       trace: run_command: git\nindex-pack --stdin -v --fix-thin '--keep=fetch-pack 13914 on machine'\n--check-self-contained-and-connected\nremote: Enumerating objects: 178, done.\n22:43:49.132535 git.c:418               trace: built-in: git\nindex-pack --stdin -v --fix-thin '--keep=fetch-pack 13914 on machine'\n--check-self-contained-and-connected\nremote: Counting objects: 100% (178/178), done.\nremote: Compressing objects: 100% (81/81), done.\nremote: Total 178 (delta 95), reused 178 (delta 95)\nReceiving objects: 100% (178/178), 539.36 KiB | 16.85 MiB/s, done.\nResolving deltas: 100% (95/95), done.\n22:43:49.209193 run-command.c:643       trace: run_command: git\nrev-list --objects --stdin --not --all --quiet '--progress=Checking\nconnectivity'\n22:43:49.211276 git.c:418               trace: built-in: git rev-list\n--objects --stdin --not --all --quiet '--progress=Checking\nconnectivity'\nWed 19 Dec 22:43:49 GMT 2018\nWed 19 Dec 22:43:49 GMT 2018\n22:43:49.220996 git.c:418               trace: built-in: git clone -n\nremotehost:diffusion/LIBEDIT/libedit\nCloning into 'libedit'...\n22:43:49.223462 run-command.c:643       trace: run_command: unset\nGIT_DIR; ssh remotehost 'git-upload-pack\n'\\''diffusion/LIBEDIT/libedit'\\'''\n22:43:49.491004 run-command.c:643       trace: run_command: git\nindex-pack --stdin -v --fix-thin '--keep=fetch-pack 13925 on machine'\n--check-self-contained-and-connected\nremote: Enumerating objects: 178, done.\n22:43:49.492988 git.c:418               trace: built-in: git\nindex-pack --stdin -v --fix-thin '--keep=fetch-pack 13925 on machine'\n--check-self-contained-and-connected\nremote: Counting objects: 100% (178/178), done.\nremote: Compressing objects: 100% (81/81), done.\nremote: Total 178 (delta 95), reused 178 (delta 95)\nReceiving objects: 100% (178/178), 539.36 KiB | 17.40 MiB/s, done.\nResolving deltas: 100% (95/95), done.\n22:43:49.569331 run-command.c:643       trace: run_command: git\nrev-list --objects --stdin --not --all --quiet '--progress=Checking\nconnectivity'\n22:43:49.571431 git.c:418               trace: built-in: git rev-list\n--objects --stdin --not --all --quiet '--progress=Checking\nconnectivity'\nWed 19 Dec 22:43:49 GMT 2018\nWed 19 Dec 22:43:49 GMT 2018\n22:43:49.581282 git.c:418               trace: built-in: git clone -n\nremotehost:diffusion/LIBEDIT/libedit\nCloning into 'libedit'...\n22:43:49.584019 run-command.c:643       trace: run_command: unset\nGIT_DIR; ssh remotehost 'git-upload-pack\n'\\''diffusion/LIBEDIT/libedit'\\'''\n22:43:49.818490 run-command.c:643       trace: run_command: git\nindex-pack --stdin -v --fix-thin '--keep=fetch-pack 13936 on machine'\n--check-self-contained-and-connected\nremote: Enumerating objects: 178, done.\n22:43:49.820477 git.c:418               trace: built-in: git\nindex-pack --stdin -v --fix-thin '--keep=fetch-pack 13936 on machine'\n--check-self-contained-and-connected\nremote: Counting objects: 100% (178/178), done.\nremote: Compressing objects: 100% (81/81), done.\nReceiving objects:  64% (114/178)\n\nMost of the time cloning complets fine but every now and then it will\nhang indefinitely in the receiving objects stage. This happens with\ngit version 2.17.1 from Ubuntu 18.04 and a hand compiled git version\n2.20.1. The remote end is running through Phabricator sshd scripts\n(both 2.17.1 and 2.20.1 have been tried on the remote end). ssh\nmultiplexing is on:\n\nControlMaster auto\nControlPersist 120\nControlPath /tmp/ssh-%r@%h:%p\nServerAliveInterval 60\n\nLooking at where it is stuck, git is doing read of a pipe:\n\n#0  0x00007fd1b845034e in __libc_read (fd=fd@entry=0,\nbuf=buf@entry=0x55ab81e19d40 <input_buffer>, nbytes=nbytes@entry=4096)\n    at ../sysdeps/unix/sysv/linux/read.c:27\n#1  0x000055ab81b51b23 in read (__nbytes=4096, __buf=0x55ab81e19d40\n<input_buffer>, __fd=0)\n    at /usr/include/x86_64-linux-gnu/bits/unistd.h:44\n#2  xread (fd=0, buf=0x55ab81e19d40 <input_buffer>, len=4096) at wrapper.c:260\n#3  0x000055ab819d1069 in fill (min=min@entry=1) at builtin/index-pack.c:255\n#4  0x000055ab819d123a in unpack_entry_data (offset=268408,\nsize=size@entry=14675, type=<optimised out>,\noid=oid@entry=0x55ab837cff40)\n    at builtin/index-pack.c:445\n#5  0x000055ab819d1bc7 in unpack_raw_entry (oid=0x55ab837cff40,\nref_oid=0x7fffee137440, ofs_offset=0x55ab837ce350, obj=0x55ab837cff40)\n    at builtin/index-pack.c:526\n#6  parse_pack_objects (hash=0x7fffee1374f0 \"\\001\") at builtin/index-pack.c:1113\n#7  cmd_index_pack (argc=<optimised out>, argv=<optimised out>,\nprefix=<optimised out>) at builtin/index-pack.c:1775\n#8  0x000055ab819934e1 in run_builtin (argv=<optimised out>,\nargc=<optimised out>, p=<optimised out>) at git.c:421\n#9  handle_builtin (argc=<optimised out>, argv=<optimised out>) at git.c:647\n#10 0x000055ab81994515 in run_argv (argv=0x7fffee137690,\nargcp=0x7fffee13769c) at git.c:701\n#11 cmd_main (argc=<optimised out>, argv=<optimised out>) at git.c:798\n#12 0x000055ab8199318f in main (argc=7, argv=0x7fffee137908) at common-main.c:45\n\nDoes anyone know what might be wrong and/or how to debug this?\n\n-- \nSitsofe | http://sucs.org/~sits/\n"},{"id":"365608","messageId":"20181219232200.GB21283@sigill.intra.peff.net","threadId":"50070","inReplyTo":"CALjAwxiB1uDfg4iPFjh2dNibEZa5mJ0RwhCzt0R2b87NTVqWfA@mail.gmail.com","subject":"Re: Periodic hang during git index-pack","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-12-19T23:22:00Z","receivedAt":"2018-12-19T23:22:03Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Dec 19, 2018 at 10:59:30PM +0000, Sitsofe Wheeler wrote:\n\n> While using trying to use git to clone a remote repository git\n> index-pack occasionally goes on to hang:\n> [...]\n> Looking at where it is stuck, git is doing read of a pipe:\n> \n> #0  0x00007fd1b845034e in __libc_read (fd=fd@entry=0,\n> buf=buf@entry=0x55ab81e19d40 <input_buffer>, nbytes=nbytes@entry=4096)\n>     at ../sysdeps/unix/sysv/linux/read.c:27\n> #1  0x000055ab81b51b23 in read (__nbytes=4096, __buf=0x55ab81e19d40\n> <input_buffer>, __fd=0)\n>     at /usr/include/x86_64-linux-gnu/bits/unistd.h:44\n\nIndex-pack is reading the pack on stdin, so it's expecting more bytes.\nThose bytes should be coming from the git-clone process, which is\nrelaying the bytes from the other side.\n\nCheck the backtrace of git-clone to see why it isn't feeding more data\n(but note that it will generally have two threads -- one processing the\ndata from the remote, and one wait()ing for index-pack to finish).\n\nMy guess, though, is that you'll find that git-clone is simply waiting\non another pipe: the one from ssh.\n\n-Peff\n"},{"id":"365621","messageId":"CALjAwxg2E_48kQYt1GHkcXvVmaFyPY3PGG9rHZNMp+++UqKfow@mail.gmail.com","threadId":"50070","inReplyTo":"20181219232200.GB21283@sigill.intra.peff.net","subject":"Re: Periodic hang during git index-pack","fromName":"Sitsofe Wheeler","fromEmail":"sitsofe@gmail.com","sentAt":"2018-12-20T10:03:45Z","receivedAt":"2018-12-20T10:04:14Z","isPatch":false,"sender":{"key":"sitsofe@gmail.com","avatar":null},"body":"On Wed, 19 Dec 2018 at 23:22, Jeff King <peff@peff.net> wrote:\n>\n> On Wed, Dec 19, 2018 at 10:59:30PM +0000, Sitsofe Wheeler wrote:\n>\n> > While using trying to use git to clone a remote repository git\n> > index-pack occasionally goes on to hang:\n> > [...]\n> > Looking at where it is stuck, git is doing read of a pipe:\n> >\n> > #0  0x00007fd1b845034e in __libc_read (fd=fd@entry=0,\n> > buf=buf@entry=0x55ab81e19d40 <input_buffer>, nbytes=nbytes@entry=4096)\n> >     at ../sysdeps/unix/sysv/linux/read.c:27\n> > #1  0x000055ab81b51b23 in read (__nbytes=4096, __buf=0x55ab81e19d40\n> > <input_buffer>, __fd=0)\n> >     at /usr/include/x86_64-linux-gnu/bits/unistd.h:44\n>\n> Index-pack is reading the pack on stdin, so it's expecting more bytes.\n> Those bytes should be coming from the git-clone process, which is\n> relaying the bytes from the other side.\n>\n> Check the backtrace of git-clone to see why it isn't feeding more data\n> (but note that it will generally have two threads -- one processing the\n> data from the remote, and one wait()ing for index-pack to finish).\n>\n> My guess, though, is that you'll find that git-clone is simply waiting\n> on another pipe: the one from ssh.\n\nOk here are backtraces from another run (with SSH multiplexing disabled):\n\n(gdb) thread apply all bt\n\nThread 2 (Thread 0x7faafbf1c700 (LWP 36586)):\n#0  0x00007faafc805384 in __libc_read (fd=fd@entry=5,\n    buf=buf@entry=0x7faafbf0ddec, nbytes=nbytes@entry=5)\n    at ../sysdeps/unix/sysv/linux/read.c:27\n#1  0x000055c8ca2f5b23 in read (__nbytes=5, __buf=0x7faafbf0ddec, __fd=5)\n    at /usr/include/x86_64-linux-gnu/bits/unistd.h:44\n#2  xread (fd=fd@entry=5, buf=buf@entry=0x7faafbf0ddec, len=len@entry=5)\n    at wrapper.c:260\n#3  0x000055c8ca2f5cdb in read_in_full (fd=5, buf=buf@entry=0x7faafbf0bdf0,\n    count=5, count@entry=8193) at wrapper.c:318\n#4  0x000055c8ca27222b in get_packet_data (fd=fd@entry=5,\n    src_buf=src_buf@entry=0x0, src_size=src_size@entry=0x0,\n    dst=dst@entry=0x7faafbf0bdf0, size=size@entry=8193,\n    options=options@entry=0) at pkt-line.c:289\n#5  0x000055c8ca272ed8 in packet_read_with_status (fd=fd@entry=5,\n    src_buffer=src_buffer@entry=0x0, src_len=src_len@entry=0x0,\n    buffer=buffer@entry=0x7faafbf0bdf0\n\"\\001\\344\\305\\066JJj\\341q@\\243\\225ժ\\350\\026M\\fkM9:-ƀ\\253\\206\\336\\001\\275\\070\\325\\372\\250\\204\\232aM\\221\\213(\\320B%\\a\\275\\233\\261g\\321A\\245\\n\n\\247\\374\\326\\b'\\v\\252\\277rA\\211\\312l\\212j\\352\\177\\260\\317j\\aT\\252&t2\\256\\254\\360\\002\\217V\\024\\061k\\201ڲ;;\\017`\\361\\020:*b\\n5\\222\\036i\\272\\067}\\360,\\323\\345Y\\314ir\\311\\034b\\232F\\267\\364\\016]\",\nsize=size@entry=65520,\n    pktlen=pktlen@entry=0x7faafbf0bd94, options=0) at pkt-line.c:344\n#6  0x000055c8ca273078 in packet_read (fd=fd@entry=5,\n    src_buffer=src_buffer@entry=0x0, src_len=src_len@entry=0x0,\n    buffer=buffer@entry=0x7faafbf0bdf0\n\"\\001\\344\\305\\066JJj\\341q@\\243\\225ժ\\350\\026M\\fkM9:-ƀ\\253\\206\\336\\001\\275\\070\\325\\372\\250\\204\\232aM\\221\\213(\\320B%\\a\\275\\233\\261g\\321A\\245\\n\n\\247\\374\\326\\b'\\v\\252\\277rA\\211\\312l\\212j\\352\\177\\260\\317j\\aT\\252&t2\\256\\254\\360\\002\\217V\\024\\061k\\201ڲ;;\\017`\\361\\020:*b\\n5\\222\\036i\\272\\067}\\360,\\323\\345Y\\314ir\\311\\034b\\232F\\267\\364\\016]\",\nsize=size@entry=65520,\n    options=options@entry=0) at pkt-line.c:364\n#7  0x000055c8ca2cbf73 in recv_sideband (\n    me=me@entry=0x55c8ca3466ed \"fetch-pack\", in_stream=5, out=out@entry=6)\n    at sideband.c:143\n#8  0x000055c8ca22d6cb in sideband_demux (in=<optimised out>, out=6,\n    data=<optimised out>) at fetch-pack.c:776\n#9  0x000055c8ca2a8458 in run_thread (data=0x7ffda489ef90)\n    at run-command.c:1032\n#10 0x00007faafc7fb6db in start_thread (arg=0x7faafbf1c700)\n    at pthread_create.c:463\n#11 0x00007faafc31c88f in clone ()\n    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95\n\nThread 1 (Thread 0x7faafce3bb80 (LWP 36584)):\n#0  0x00007faafc805384 in __libc_read (fd=fd@entry=7,\n    buf=buf@entry=0x7ffda489ef10, nbytes=nbytes@entry=46)\n    at ../sysdeps/unix/sysv/linux/read.c:27\n#1  0x000055c8ca2f5b23 in read (__nbytes=46, __buf=0x7ffda489ef10, __fd=7)\n    at /usr/include/x86_64-linux-gnu/bits/unistd.h:44\n#2  xread (fd=fd@entry=7, buf=buf@entry=0x7ffda489ef10, len=len@entry=46)\n    at wrapper.c:260\n#3  0x000055c8ca2f5cdb in read_in_full (fd=7, buf=buf@entry=0x7ffda489ef10,\n    count=count@entry=46) at wrapper.c:318\n#4  0x000055c8ca26a54f in index_pack_lockfile (ip_out=<optimised out>)\n    at pack-write.c:297\n#5  0x000055c8ca22e18c in get_pack (args=args@entry=0x7ffda489f2e0,\n    xd=xd@entry=0x55c8cb4966f8,\n    pack_lockfile=pack_lockfile@entry=0x55c8cb496660) at fetch-pack.c:881\n#6  0x000055c8ca22fbfb in do_fetch_pack (pack_lockfile=<optimised out>,\n    si=0x7ffda489f1f0, nr_sought=<optimised out>, sought=<optimised out>,\n    orig_ref=<optimised out>, fd=<optimised out>, args=0x7ffda489f2e0)\n    at fetch-pack.c:1019\n#7  fetch_pack (args=args@entry=0x7ffda489f2e0, fd=<optimised out>,\n    conn=<optimised out>, ref=<optimised out>,\n    dest=dest@entry=0x55c8cb498820\n\"remotehost:diffusion/LIBEDIT/libedit\",\nsought=sought@entry=0x55c8cb498580,\n    nr_sought=<optimised out>, shallow=<optimised out>,\n    pack_lockfile=<optimised out>, version=<optimised out>)\n    at fetch-pack.c:1649\n#8  0x000055c8ca2dddf8 in fetch_refs_via_pack (transport=0x55c8cb496620,\n    nr_heads=2, to_fetch=0x55c8cb498580) at transport.c:365\n#9  0x000055c8ca2df246 in transport_fetch_refs (\n    transport=transport@entry=0x55c8cb496620, refs=refs@entry=0x55c8cb4959e0)\n    at transport.c:1295\n#10 0x000055c8ca1529ab in cmd_clone (argc=<optimised out>,\n    argv=<optimised out>, prefix=<optimised out>) at builtin/clone.c:1212\n#11 0x000055c8ca1374e1 in run_builtin (argv=<optimised out>,\n    argc=<optimised out>, p=<optimised out>) at git.c:421\n#12 handle_builtin (argc=<optimised out>, argv=<optimised out>) at git.c:647\n#13 0x000055c8ca138515 in run_argv (argv=0x7ffda489fa00, argcp=0x7ffda489fa0c)\n    at git.c:701\n#14 cmd_main (argc=<optimised out>, argv=<optimised out>) at git.c:798\n#15 0x000055c8ca13718f in main (argc=4, argv=0x7ffda489fc78)\n    at common-main.c:45\n\n(gdb) thread apply all bt\n\nThread 1 (Thread 0x7ff8a03dab80 (LWP 36587)):\n#0  0x00007ff89fda434e in __libc_read (fd=fd@entry=0,\n    buf=buf@entry=0x5604bea43d40 <input_buffer>, nbytes=nbytes@entry=4096)\n    at ../sysdeps/unix/sysv/linux/read.c:27\n#1  0x00005604be77bb23 in read (__nbytes=4096,\n    __buf=0x5604bea43d40 <input_buffer>, __fd=0)\n    at /usr/include/x86_64-linux-gnu/bits/unistd.h:44\n#2  xread (fd=0, buf=0x5604bea43d40 <input_buffer>, len=4096) at wrapper.c:260\n#3  0x00005604be5fb069 in fill (min=min@entry=1) at builtin/index-pack.c:255\n#4  0x00005604be5fb23a in unpack_entry_data (offset=528312,\n    size=size@entry=19448, type=<optimised out>, oid=oid@entry=0x5604c0605ea0)\n    at builtin/index-pack.c:445\n#5  0x00005604be5fbbc7 in unpack_raw_entry (oid=0x5604c0605ea0,\n    ref_oid=0x7ffc74cd73f0, ofs_offset=0x5604c0603580, obj=0x5604c0605ea0)\n    at builtin/index-pack.c:526\n#6  parse_pack_objects (hash=0x7ffc74cd74a0 \"\\001\")\n    at builtin/index-pack.c:1113\n#7  cmd_index_pack (argc=<optimised out>, argv=<optimised out>,\n    prefix=<optimised out>) at builtin/index-pack.c:1775\n#8  0x00005604be5bd4e1 in run_builtin (argv=<optimised out>,\n    argc=<optimised out>, p=<optimised out>) at git.c:421\n#9  handle_builtin (argc=<optimised out>, argv=<optimised out>) at git.c:647\n#10 0x00005604be5be515 in run_argv (argv=0x7ffc74cd7640, argcp=0x7ffc74cd764c)\n    at git.c:701\n#11 cmd_main (argc=<optimised out>, argv=<optimised out>) at git.c:798\n#12 0x00005604be5bd18f in main (argc=7, argv=0x7ffc74cd78b8)\n    at common-main.c:45\n\nAs before, any hints on how to debug this gratefully accepted!\n\n-- \nSitsofe | http://sucs.org/~sits/\n"},{"id":"365644","messageId":"20181220151037.GC27361@sigill.intra.peff.net","threadId":"50070","inReplyTo":"CALjAwxg2E_48kQYt1GHkcXvVmaFyPY3PGG9rHZNMp+++UqKfow@mail.gmail.com","subject":"Re: Periodic hang during git index-pack","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-12-20T15:10:38Z","receivedAt":"2018-12-20T15:11:03Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Dec 20, 2018 at 10:03:45AM +0000, Sitsofe Wheeler wrote:\n\n> > Check the backtrace of git-clone to see why it isn't feeding more data\n> > (but note that it will generally have two threads -- one processing the\n> > data from the remote, and one wait()ing for index-pack to finish).\n> >\n> > My guess, though, is that you'll find that git-clone is simply waiting\n> > on another pipe: the one from ssh.\n> \n> Ok here are backtraces from another run (with SSH multiplexing disabled):\n\nOK, that's about what I expected. Here we have clone's sideband-demux\nthread waiting to pull more packfile data from the remote:\n\n> (gdb) thread apply all bt\n> \n> Thread 2 (Thread 0x7faafbf1c700 (LWP 36586)):\n> #0  0x00007faafc805384 in __libc_read (fd=fd@entry=5,\n>     buf=buf@entry=0x7faafbf0ddec, nbytes=nbytes@entry=5)\n>     at ../sysdeps/unix/sysv/linux/read.c:27\n> #1  0x000055c8ca2f5b23 in read (__nbytes=5, __buf=0x7faafbf0ddec, __fd=5)\n>     at /usr/include/x86_64-linux-gnu/bits/unistd.h:44\n> [...coming from packet_read / recv_sideband / sideband_demux...]\n\nI assume fd=5 there is a pipe connected to ssh. You could double check\nwith \"lsof\" or similar, but I don't think it would ever be reading from\nanywhere else.\n\nAnd then this thread:\n\n> Thread 1 (Thread 0x7faafce3bb80 (LWP 36584)):\n> #0  0x00007faafc805384 in __libc_read (fd=fd@entry=7,\n>     buf=buf@entry=0x7ffda489ef10, nbytes=nbytes@entry=46)\n>     at ../sysdeps/unix/sysv/linux/read.c:27\n> #1  0x000055c8ca2f5b23 in read (__nbytes=46, __buf=0x7ffda489ef10, __fd=7)\n>     at /usr/include/x86_64-linux-gnu/bits/unistd.h:44\n> #2  xread (fd=fd@entry=7, buf=buf@entry=0x7ffda489ef10, len=len@entry=46)\n>     at wrapper.c:260\n> #3  0x000055c8ca2f5cdb in read_in_full (fd=7, buf=buf@entry=0x7ffda489ef10,\n>     count=count@entry=46) at wrapper.c:318\n> #4  0x000055c8ca26a54f in index_pack_lockfile (ip_out=<optimised out>)\n>     at pack-write.c:297\n\n...is us waiting on index-pack to single completion by printing out the\nname of the pack's .keep file.\n\nAnd then this is just index-pack:\n\n> (gdb) thread apply all bt\n> \n> Thread 1 (Thread 0x7ff8a03dab80 (LWP 36587)):\n> #0  0x00007ff89fda434e in __libc_read (fd=fd@entry=0,\n>     buf=buf@entry=0x5604bea43d40 <input_buffer>, nbytes=nbytes@entry=4096)\n>     at ../sysdeps/unix/sysv/linux/read.c:27\n> #1  0x00005604be77bb23 in read (__nbytes=4096,\n>     __buf=0x5604bea43d40 <input_buffer>, __fd=0)\n>     at /usr/include/x86_64-linux-gnu/bits/unistd.h:44\n> #2  xread (fd=0, buf=0x5604bea43d40 <input_buffer>, len=4096) at wrapper.c:260\n> #3  0x00005604be5fb069 in fill (min=min@entry=1) at builtin/index-pack.c:255\n\n...waiting for more data.\n\nSo though it goes back and forth between two processes, the sequence of\nblocking data is linear due to the threads:\n\n  ssh -> git-clone        -> index-pack -> git-clone\n         (sideband_demux)                  (index_pack_lockfile)\n\nwith each blocking on read() from its predecessor. So you need to find\nout why \"ssh\" is blocking. Unfortunately, short of a bug in ssh, the\nlikely cause is either:\n\n  1. The git-upload-pack on the remote side stopped generating data for\n     some reason. You may or may not have access on the remotehost to\n     dig into that.\n\n     It's certainly possible there's a deadlock bug between the server\n     and client side of a Git conversation. But I'd find it extremely\n     unlikely to find such a deadlock bug at this point in the\n     conversation, because at this point the client side has nothing\n     left to say to the server. The server should just be streaming out\n     the packfile bytes and then closing the descriptor.\n\n     You mentioned \"Phabricator sshd scripts\" running on the server.\n     I don't know what Phabricator might be sticking in the middle of\n     the connection, but that could be the source of the stall.\n\n  2. It's possible the network connection dropped but ssh did not\n     notice. Maybe try turning on ssh keepalives and seeing if it\n     eventually times out?\n\n-Peff\n"},{"id":"365656","messageId":"CALjAwxjyS5raGbib5KyUPZzS+9UyB1fpCN2fybYoYOctXe7iyA@mail.gmail.com","threadId":"50070","inReplyTo":"20181220151037.GC27361@sigill.intra.peff.net","subject":"Re: Periodic hang during git index-pack","fromName":"Sitsofe Wheeler","fromEmail":"sitsofe@gmail.com","sentAt":"2018-12-20T16:48:13Z","receivedAt":"2018-12-20T16:48:42Z","isPatch":false,"sender":{"key":"sitsofe@gmail.com","avatar":null},"body":"On Thu, 20 Dec 2018 at 15:11, Jeff King <peff@peff.net> wrote:\n>\n> OK, that's about what I expected. Here we have clone's sideband-demux\n> thread waiting to pull more packfile data from the remote:\n>\n> > (gdb) thread apply all bt\n> >\n> > Thread 2 (Thread 0x7faafbf1c700 (LWP 36586)):\n> > #0  0x00007faafc805384 in __libc_read (fd=fd@entry=5,\n> >     buf=buf@entry=0x7faafbf0ddec, nbytes=nbytes@entry=5)\n> >     at ../sysdeps/unix/sysv/linux/read.c:27\n> > #1  0x000055c8ca2f5b23 in read (__nbytes=5, __buf=0x7faafbf0ddec, __fd=5)\n> >     at /usr/include/x86_64-linux-gnu/bits/unistd.h:44\n> > [...coming from packet_read / recv_sideband / sideband_demux...]\n>\n> I assume fd=5 there is a pipe connected to ssh. You could double check\n> with \"lsof\" or similar, but I don't think it would ever be reading from\n> anywhere else.\n\nI checked and in all cases git was reading from a pipe.\n\n[snip]\n\n> with each blocking on read() from its predecessor. So you need to find\n> out why \"ssh\" is blocking. Unfortunately, short of a bug in ssh, the\n> likely cause is either:\n>\n>   1. The git-upload-pack on the remote side stopped generating data for\n>      some reason. You may or may not have access on the remotehost to\n>      dig into that.\n>\n>      It's certainly possible there's a deadlock bug between the server\n>      and client side of a Git conversation. But I'd find it extremely\n>      unlikely to find such a deadlock bug at this point in the\n>      conversation, because at this point the client side has nothing\n>      left to say to the server. The server should just be streaming out\n>      the packfile bytes and then closing the descriptor.\n\nI think it's highly unlikely too given how many good runs we generally have.\n\n>      You mentioned \"Phabricator sshd scripts\" running on the server.\n>      I don't know what Phabricator might be sticking in the middle of\n>      the connection, but that could be the source of the stall.\n\nI think you're right. I set up a seperate sshd on a different port on\nthe same machine where there were no Phabricator callouts and the\nproblem never manifested...\n\n>   2. It's possible the network connection dropped but ssh did not\n>      notice. Maybe try turning on ssh keepalives and seeing if it\n>      eventually times out?\n\nI had already done this but the problem still manifested. I went so\nfar as checking if the problem would happen over the loopback device\non the same machine (via localhost) and the problem continued\nhappening so I'm fairly sure that rules out networking issues.\n\n-- \nSitsofe | http://sucs.org/~sits/\n"},{"id":"368429","messageId":"CALjAwxj2oDH8NGoLgoPV_=FZ5yRcS=bCKtsuZ1Vin7o8Y+OuOQ@mail.gmail.com","threadId":"50070","inReplyTo":"CALjAwxjyS5raGbib5KyUPZzS+9UyB1fpCN2fybYoYOctXe7iyA@mail.gmail.com","subject":"Re: Periodic hang during git index-pack","fromName":"Sitsofe Wheeler","fromEmail":"sitsofe@gmail.com","sentAt":"2019-02-03T08:16:48Z","receivedAt":"2019-02-03T08:17:17Z","isPatch":false,"sender":{"key":"sitsofe@gmail.com","avatar":null},"body":"On Wed, 19 Dec 2018 at 22:59, Sitsofe Wheeler <sitsofe@gmail.com> wrote:\n>\n> While using trying to use git to clone a remote repository git\n> index-pack occasionally goes on to hang:\n\nOn Thu, 20 Dec 2018 at 16:48, Sitsofe Wheeler <sitsofe@gmail.com> wrote:\n>\n> On Thu, 20 Dec 2018 at 15:11, Jeff King <peff@peff.net> wrote:\n> >\n[snip]\n> >\n> > with each blocking on read() from its predecessor. So you need to find\n> > out why \"ssh\" is blocking. Unfortunately, short of a bug in ssh, the\n> > likely cause is either:\n> >\n> >   1. The git-upload-pack on the remote side stopped generating data for\n> >      some reason. You may or may not have access on the remotehost to\n> >      dig into that.\n> >\n> >      It's certainly possible there's a deadlock bug between the server\n> >      and client side of a Git conversation. But I'd find it extremely\n> >      unlikely to find such a deadlock bug at this point in the\n> >      conversation, because at this point the client side has nothing\n> >      left to say to the server. The server should just be streaming out\n> >      the packfile bytes and then closing the descriptor.\n>\n> I think it's highly unlikely too given how many good runs we generally have.\n>\n> >      You mentioned \"Phabricator sshd scripts\" running on the server.\n> >      I don't know what Phabricator might be sticking in the middle of\n> >      the connection, but that could be the source of the stall.\n>\n> I think you're right. I set up a seperate sshd on a different port on\n> the same machine where there were no Phabricator callouts and the\n> problem never manifested...\n\nJust to finally follow up - this was confirmed to be a bug in the\nPhabricator server side git+ssh wrapper and the issue exists in at\nleast Phabricator versions between\n2016 Week 28 - 2019 Week 3. The Phabricator ssh-exec PHP script was\ndoing a select() that would very occasionally fail with errno set to\nEINTR and then going on to cause subsequent git data to not be sent to\nthe git client. It's unclear why this started happening more\nfrequently for us but we had recently changed to a faster/more\ncores/larger AWS instance type and we also switched to a later Ubuntu\n14.04 kernel...\n\nSee https://discourse.phabricator-community.org/t/sporadic-git-cloning-hang-over-ssh/2233\nfor a longer description of the issue that was reported to the\nPhabricator developers. That link contains a patch by myself that\nresolves the issue, a link to an upstream Phabricator task made by the\nPhabricator devs and a link to an upstream Phabricator diff that works\naround the issue in a looser manner than my final patch.\n\nThanks for your rapid reply and guidance Jeff!\n\n--\nSitsofe | http://sucs.org/~sits/\n"}]}