{"thread":{"id":"57770","subject":"git push locks up forever, file protocol","startedAt":"2022-04-21T08:31:00Z","lastAt":"2022-04-22T16:12:00Z","messageCount":5,"participants":["Jason Morgan","brian m. carlson","Jeff Hostetler","rsbecker@nexbridge.com"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"454051","messageId":"BN0PR02MB79195847F60CA239AE9F5CE3F2F49@BN0PR02MB7919.namprd02.prod.outlook.com","threadId":"57770","inReplyTo":"BN0PR02MB79194599872BD3693CD72CF4F2F49@BN0PR02MB7919.namprd02.prod.outlook.com","subject":"git push locks up forever, file protocol","fromName":"Jason Morgan","fromEmail":"jasomorg@qti.qualcomm.com","sentAt":"2022-04-21T08:30:50Z","receivedAt":"2022-04-21T08:31:00Z","isPatch":false,"sender":{"key":"jasomorg@qti.qualcomm.com","avatar":null},"body":"Hi,\n\nWe have a remote repo accessed using the 'file:' protocol, mounted over Samba using drvfs into a WSL2 instance of Ubuntu 20.04.\n\nWe find a 'git push' waits forever. git version 2.25.1\n\nOver a local LAN this works fine, but over a VPN this fails, hinting at some sort of race condition.\n\nOutput from strace hints that git is trying (and failing) to read from a closed file handle.\n\nFinal output from strace:\n\n-----------\nopenat(AT_FDCWD, \".git/objects/ad/065dad4384ae8c81c120c562985078d1f7b34b\", O_RDONLY|O_CLOEXEC) = 3\nfstat(3, {st_mode=S_IFREG|0444, st_size=152, ...}) = 0\nmmap(NULL, 152, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\nclose(3)                                = 0\nmunmap(0x7f3e0e4af000, 152)             = 0\nopenat(AT_FDCWD, \".git/objects/30/2508dfe5201db6c000ebf17b0c69e3afb31218\", O_RDONLY|O_CLOEXEC) = 3\nfstat(3, {st_mode=S_IFREG|0555, st_size=214, ...}) = 0\nmmap(NULL, 214, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\nclose(3)                                = 0\nmunmap(0x7f3e0e4af000, 214)             = 0\nopenat(AT_FDCWD, \".git/objects/d2/2323ec2ec40a74fbd519509662254c3cfda206\", O_RDONLY|O_CLOEXEC) = 3\nfstat(3, {st_mode=S_IFREG|0444, st_size=161, ...}) = 0\nmmap(NULL, 161, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\nclose(3)                                = 0\nmunmap(0x7f3e0e4af000, 161)             = 0\naccess(\".git/hooks/pre-push\", X_OK)     = -1 ENOENT (No such file or directory)\nwrite(4, \"00953ea50e3c1f49c33f7dbbb5e3a310\"..., 149) = 149\nwrite(4, \"0000\", 4)                     = 4\npipe([3, 6])                            = 0\nfcntl(6, F_GETFD)                       = 0\nfcntl(6, F_SETFD, FD_CLOEXEC)           = 0\nmmap(NULL, 8392704, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f3e0d641000\nmprotect(0x7f3e0d642000, 8388608, PROT_READ|PROT_WRITE) = 0\nclone(child_stack=0x7f3e0de40fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tid=[12802], tls=0x7f3e0de41700, child_tidptr=0x7f3e0de419d0) = 12802\npipe([7, 8])                            = 0\nstat(\"/usr/lib/git-core/git\", {st_mode=S_IFREG|0755, st_size=3093072, ...}) = 0\npipe([9, 10])                           = 0\nrt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0\nclone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f3e0e1dae50) = 12803\nrt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0\nclose(10)                               = 0\nread(9, \"\", 8)                          = 0\nclose(9)                                = 0\nclose(7)                                = 0\nclose(4)                                = 0\nfcntl(8, F_GETFL)                       = 0x1 (flags O_WRONLY)\nopenat(AT_FDCWD, \".git/objects/3e\", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4\nfstat(4, {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0\ngetdents64(4, /* 22 entries */, 32768)  = 1328\ngetdents64(4, /* 0 entries */, 32768)   = 0\nclose(4)                                = 0\nfstat(8, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0\nwrite(8, \"^3ea50e3c1f49c33f7dbbb5e3a31017f\"..., 83) = 83\nclose(8)                                = 0\nEnumerating objects: 31, done.ts: 1\nCounting objects: 100% (31/31), done.\nDelta compression using up to 8 threads\nCompressing objects: 100% (23/23), done.\nWriting objects: 100% (23/23), 5.60 KiB | 212.00 KiB/s, done.\nTotal 23 (delta 14), reused 0 (delta 0)\n[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 12803\n--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=12803, si_uid=1000, si_status=0, si_utime=2, si_stime=6} ---\nread(3,\n------------------\nThat last read from handle 3 (which is closed) lasts forever until you ctrl-c.\n\nThe abbreviated strace output, simply halting at the comma, is very odd.\n\nNote the behaviour is the same with the file: protocol prefix and without.\n\nj.\n"},{"id":"454201","messageId":"YmIFeIrTBx6yghwn@camp.crustytoothpaste.net","threadId":"57770","inReplyTo":"BN0PR02MB79195847F60CA239AE9F5CE3F2F49@BN0PR02MB7919.namprd02.prod.outlook.com","subject":"Re: git push locks up forever, file protocol","fromName":"brian m. carlson","fromEmail":"sandals@crustytoothpaste.net","sentAt":"2022-04-22T01:31:36Z","receivedAt":"2022-04-22T01:31:43Z","isPatch":false,"sender":{"key":"sandals@crustytoothpaste.net","avatar":"https://avatars.githubusercontent.com/u/497054?v=4"},"body":"On 2022-04-21 at 08:30:50, Jason Morgan wrote:\n> Hi,\n> \n> We have a remote repo accessed using the 'file:' protocol, mounted over Samba using drvfs into a WSL2 instance of Ubuntu 20.04.\n> \n> We find a 'git push' waits forever. git version 2.25.1\n\nI seem to recall that we've fixed some various issues with protocol\nhandling in the 2.29 timeframe.  Is it possible you could try 2.36.0 to\nsee if you can reproduce it there?\n\nAlso, it would be interesting to see if there's a difference in\nbehaviour between setting protocol.version to 0 and setting it to 2.\nThat might tell us something that would help tracking this down.\n\n> Over a local LAN this works fine, but over a VPN this fails, hinting at some sort of race condition.\n>\n> Output from strace hints that git is trying (and failing) to read from a closed file handle.\n\nI don't think this is the case.  If Git were trying to read from a\nclosed file handle, the kernel would immediately return -1 with errno\nset to EBADF.  Those operations won't block because there's nothing to\nread.\n\n> Final output from strace:\n> \n> -----------\n> openat(AT_FDCWD, \".git/objects/ad/065dad4384ae8c81c120c562985078d1f7b34b\", O_RDONLY|O_CLOEXEC) = 3\n> fstat(3, {st_mode=S_IFREG|0444, st_size=152, ...}) = 0\n> mmap(NULL, 152, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\n> close(3)                                = 0\n> munmap(0x7f3e0e4af000, 152)             = 0\n> openat(AT_FDCWD, \".git/objects/30/2508dfe5201db6c000ebf17b0c69e3afb31218\", O_RDONLY|O_CLOEXEC) = 3\n> fstat(3, {st_mode=S_IFREG|0555, st_size=214, ...}) = 0\n> mmap(NULL, 214, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\n> close(3)                                = 0\n> munmap(0x7f3e0e4af000, 214)             = 0\n> openat(AT_FDCWD, \".git/objects/d2/2323ec2ec40a74fbd519509662254c3cfda206\", O_RDONLY|O_CLOEXEC) = 3\n> fstat(3, {st_mode=S_IFREG|0444, st_size=161, ...}) = 0\n> mmap(NULL, 161, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\n> close(3)                                = 0\n\nFD 3 is closed here...\n\n> munmap(0x7f3e0e4af000, 161)             = 0\n> access(\".git/hooks/pre-push\", X_OK)     = -1 ENOENT (No such file or directory)\n> write(4, \"00953ea50e3c1f49c33f7dbbb5e3a310\"..., 149) = 149\n> write(4, \"0000\", 4)                     = 4\n> pipe([3, 6])                            = 0\n\nAnd then it's recreated here as one part of a pipe, so it isn't closed.\n\n> fcntl(6, F_GETFD)                       = 0\n> fcntl(6, F_SETFD, FD_CLOEXEC)           = 0\n> mmap(NULL, 8392704, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f3e0d641000\n> mprotect(0x7f3e0d642000, 8388608, PROT_READ|PROT_WRITE) = 0\n> clone(child_stack=0x7f3e0de40fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tid=[12802], tls=0x7f3e0de41700, child_tidptr=0x7f3e0de419d0) = 12802\n\nMy guess is that in the child (which isn't shown here) that FD 6 is\nhooked up to either standard output or standard error.  You'd need to\nfollow children to see.\n\n> pipe([7, 8])                            = 0\n> stat(\"/usr/lib/git-core/git\", {st_mode=S_IFREG|0755, st_size=3093072, ...}) = 0\n> pipe([9, 10])                           = 0\n> rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0\n> clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f3e0e1dae50) = 12803\n> rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0\n> close(10)                               = 0\n> read(9, \"\", 8)                          = 0\n> close(9)                                = 0\n> close(7)                                = 0\n> close(4)                                = 0\n> fcntl(8, F_GETFL)                       = 0x1 (flags O_WRONLY)\n> openat(AT_FDCWD, \".git/objects/3e\", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4\n> fstat(4, {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0\n> getdents64(4, /* 22 entries */, 32768)  = 1328\n> getdents64(4, /* 0 entries */, 32768)   = 0\n> close(4)                                = 0\n> fstat(8, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0\n> write(8, \"^3ea50e3c1f49c33f7dbbb5e3a31017f\"..., 83) = 83\n> close(8)                                = 0\n> Enumerating objects: 31, done.ts: 1\n> Counting objects: 100% (31/31), done.\n> Delta compression using up to 8 threads\n> Compressing objects: 100% (23/23), done.\n> Writing objects: 100% (23/23), 5.60 KiB | 212.00 KiB/s, done.\n> Total 23 (delta 14), reused 0 (delta 0)\n> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 12803\n> --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=12803, si_uid=1000, si_status=0, si_utime=2, si_stime=6} ---\n> read(3,\n\nIf FD 6 were wired up to something in the child and the child exited\n(which, having received SIGCHLD, is a safe bet), then we'd expect this\nto see this process get EOF.\n\nIt's not clear to me what's going on here, but I think this code is\nending up in connect.c (search for \"transport/file\").  Maybe someone\nelse has an idea?\n-- \nbrian m. carlson (he/him or they/them)\nToronto, Ontario, CA\n"},{"id":"454260","messageId":"fee354b5-e343-c997-b75a-63cf785b5337@jeffhostetler.com","threadId":"57770","inReplyTo":"YmIFeIrTBx6yghwn@camp.crustytoothpaste.net","subject":"Re: git push locks up forever, file protocol","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2022-04-22T14:16:35Z","receivedAt":"2022-04-22T14:16:42Z","isPatch":false,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 4/21/22 9:31 PM, brian m. carlson wrote:\n> On 2022-04-21 at 08:30:50, Jason Morgan wrote:\n>> Hi,\n>>\n>> We have a remote repo accessed using the 'file:' protocol, mounted over Samba using drvfs into a WSL2 instance of Ubuntu 20.04.\n>>\n>> We find a 'git push' waits forever. git version 2.25.1\n> \n> I seem to recall that we've fixed some various issues with protocol\n> handling in the 2.29 timeframe.  Is it possible you could try 2.36.0 to\n> see if you can reproduce it there?\n> \n> Also, it would be interesting to see if there's a difference in\n> behaviour between setting protocol.version to 0 and setting it to 2.\n> That might tell us something that would help tracking this down.\n> \n>> Over a local LAN this works fine, but over a VPN this fails, hinting at some sort of race condition.\n>>\n>> Output from strace hints that git is trying (and failing) to read from a closed file handle.\n> \n> I don't think this is the case.  If Git were trying to read from a\n> closed file handle, the kernel would immediately return -1 with errno\n> set to EBADF.  Those operations won't block because there's nothing to\n> read.\n> \n>> Final output from strace:\n>>\n>> -----------\n>> openat(AT_FDCWD, \".git/objects/ad/065dad4384ae8c81c120c562985078d1f7b34b\", O_RDONLY|O_CLOEXEC) = 3\n>> fstat(3, {st_mode=S_IFREG|0444, st_size=152, ...}) = 0\n>> mmap(NULL, 152, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\n>> close(3)                                = 0\n>> munmap(0x7f3e0e4af000, 152)             = 0\n>> openat(AT_FDCWD, \".git/objects/30/2508dfe5201db6c000ebf17b0c69e3afb31218\", O_RDONLY|O_CLOEXEC) = 3\n>> fstat(3, {st_mode=S_IFREG|0555, st_size=214, ...}) = 0\n>> mmap(NULL, 214, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\n>> close(3)                                = 0\n>> munmap(0x7f3e0e4af000, 214)             = 0\n>> openat(AT_FDCWD, \".git/objects/d2/2323ec2ec40a74fbd519509662254c3cfda206\", O_RDONLY|O_CLOEXEC) = 3\n>> fstat(3, {st_mode=S_IFREG|0444, st_size=161, ...}) = 0\n>> mmap(NULL, 161, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\n>> close(3)                                = 0\n> \n> FD 3 is closed here...\n> \n>> munmap(0x7f3e0e4af000, 161)             = 0\n>> access(\".git/hooks/pre-push\", X_OK)     = -1 ENOENT (No such file or directory)\n>> write(4, \"00953ea50e3c1f49c33f7dbbb5e3a310\"..., 149) = 149\n>> write(4, \"0000\", 4)                     = 4\n>> pipe([3, 6])                            = 0\n> \n> And then it's recreated here as one part of a pipe, so it isn't closed.\n> \n>> fcntl(6, F_GETFD)                       = 0\n>> fcntl(6, F_SETFD, FD_CLOEXEC)           = 0\n>> mmap(NULL, 8392704, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f3e0d641000\n>> mprotect(0x7f3e0d642000, 8388608, PROT_READ|PROT_WRITE) = 0\n>> clone(child_stack=0x7f3e0de40fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tid=[12802], tls=0x7f3e0de41700, child_tidptr=0x7f3e0de419d0) = 12802\n> \n> My guess is that in the child (which isn't shown here) that FD 6 is\n> hooked up to either standard output or standard error.  You'd need to\n> follow children to see.\n> \n>> pipe([7, 8])                            = 0\n>> stat(\"/usr/lib/git-core/git\", {st_mode=S_IFREG|0755, st_size=3093072, ...}) = 0\n>> pipe([9, 10])                           = 0\n>> rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0\n>> clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f3e0e1dae50) = 12803\n>> rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0\n>> close(10)                               = 0\n>> read(9, \"\", 8)                          = 0\n>> close(9)                                = 0\n>> close(7)                                = 0\n>> close(4)                                = 0\n>> fcntl(8, F_GETFL)                       = 0x1 (flags O_WRONLY)\n>> openat(AT_FDCWD, \".git/objects/3e\", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4\n>> fstat(4, {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0\n>> getdents64(4, /* 22 entries */, 32768)  = 1328\n>> getdents64(4, /* 0 entries */, 32768)   = 0\n>> close(4)                                = 0\n>> fstat(8, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0\n>> write(8, \"^3ea50e3c1f49c33f7dbbb5e3a31017f\"..., 83) = 83\n>> close(8)                                = 0\n>> Enumerating objects: 31, done.ts: 1\n>> Counting objects: 100% (31/31), done.\n>> Delta compression using up to 8 threads\n>> Compressing objects: 100% (23/23), done.\n>> Writing objects: 100% (23/23), 5.60 KiB | 212.00 KiB/s, done.\n>> Total 23 (delta 14), reused 0 (delta 0)\n>> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 12803\n>> --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=12803, si_uid=1000, si_status=0, si_utime=2, si_stime=6} ---\n>> read(3,\n> \n> If FD 6 were wired up to something in the child and the child exited\n> (which, having received SIGCHLD, is a safe bet), then we'd expect this\n> to see this process get EOF.\n> \n> It's not clear to me what's going on here, but I think this code is\n> ending up in connect.c (search for \"transport/file\").  Maybe someone\n> else has an idea?\n> \n\nNot sure I can add anything here to what Brian has already said,\nbut you might try setting GIT_TRACE2_PERF to an absolute path of\na file or an existing directory.  That'll give you tracing around\nthe child.\n\nJeff\n\n"},{"id":"454261","messageId":"02b301d85655$6881b710$39852530$@nexbridge.com","threadId":"57770","inReplyTo":"fee354b5-e343-c997-b75a-63cf785b5337@jeffhostetler.com","subject":"RE: git push locks up forever, file protocol","fromName":"","fromEmail":"rsbecker@nexbridge.com","sentAt":"2022-04-22T14:29:37Z","receivedAt":"2022-04-22T14:29:59Z","isPatch":false,"sender":{"key":"randall.becker@nexbridge.ca","avatar":"https://avatars.githubusercontent.com/u/28956764?v=4"},"body":"On April 22, 2022 10:17 AM, Jeff Hostetler wrote:\n>On 4/21/22 9:31 PM, brian m. carlson wrote:\n>> On 2022-04-21 at 08:30:50, Jason Morgan wrote:\n>>> Hi,\n>>>\n>>> We have a remote repo accessed using the 'file:' protocol, mounted over\n>Samba using drvfs into a WSL2 instance of Ubuntu 20.04.\n>>>\n>>> We find a 'git push' waits forever. git version 2.25.1\n>>\n>> I seem to recall that we've fixed some various issues with protocol\n>> handling in the 2.29 timeframe.  Is it possible you could try 2.36.0\n>> to see if you can reproduce it there?\n>>\n>> Also, it would be interesting to see if there's a difference in\n>> behaviour between setting protocol.version to 0 and setting it to 2.\n>> That might tell us something that would help tracking this down.\n>>\n>>> Over a local LAN this works fine, but over a VPN this fails, hinting at some sort\n>of race condition.\n>>>\n>>> Output from strace hints that git is trying (and failing) to read from a closed file\n>handle.\n>>\n>> I don't think this is the case.  If Git were trying to read from a\n>> closed file handle, the kernel would immediately return -1 with errno\n>> set to EBADF.  Those operations won't block because there's nothing to\n>> read.\n>>\n>>> Final output from strace:\n>>>\n>>> -----------\n>>> openat(AT_FDCWD,\n>>> \".git/objects/ad/065dad4384ae8c81c120c562985078d1f7b34b\",\n>>> O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0444, st_size=152,\n>>> ...}) = 0 mmap(NULL, 152, PROT_READ, MAP_PRIVATE, 3, 0) =\n>>> 0x7f3e0e4af000\n>>> close(3)                                = 0 munmap(0x7f3e0e4af000,\n>>> 152)             = 0 openat(AT_FDCWD,\n>>> \".git/objects/30/2508dfe5201db6c000ebf17b0c69e3afb31218\",\n>>> O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0555, st_size=214,\n>>> ...}) = 0 mmap(NULL, 214, PROT_READ, MAP_PRIVATE, 3, 0) =\n>>> 0x7f3e0e4af000\n>>> close(3)                                = 0 munmap(0x7f3e0e4af000,\n>>> 214)             = 0 openat(AT_FDCWD,\n>>> \".git/objects/d2/2323ec2ec40a74fbd519509662254c3cfda206\",\n>>> O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0444, st_size=161,\n>>> ...}) = 0 mmap(NULL, 161, PROT_READ, MAP_PRIVATE, 3, 0) =\n>>> 0x7f3e0e4af000\n>>> close(3)                                = 0\n>>\n>> FD 3 is closed here...\n>>\n>>> munmap(0x7f3e0e4af000, 161)             = 0\n>>> access(\".git/hooks/pre-push\", X_OK)     = -1 ENOENT (No such file or\n>>> directory) write(4, \"00953ea50e3c1f49c33f7dbbb5e3a310\"..., 149) = 149\n>>> write(4, \"0000\", 4)                     = 4 pipe([3, 6])\n>>> = 0\n>>\n>> And then it's recreated here as one part of a pipe, so it isn't closed.\n>>\n>>> fcntl(6, F_GETFD)                       = 0 fcntl(6, F_SETFD,\n>>> FD_CLOEXEC)           = 0 mmap(NULL, 8392704, PROT_NONE,\n>>> MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f3e0d641000\n>>> mprotect(0x7f3e0d642000, 8388608, PROT_READ|PROT_WRITE) = 0\n>>> clone(child_stack=0x7f3e0de40fb0,\n>>>\n>flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|C\n>LONE_\n>>> SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,\n>>> parent_tid=[12802], tls=0x7f3e0de41700, child_tidptr=0x7f3e0de419d0)\n>>> = 12802\n>>\n>> My guess is that in the child (which isn't shown here) that FD 6 is\n>> hooked up to either standard output or standard error.  You'd need to\n>> follow children to see.\n>>\n>>> pipe([7, 8])                            = 0\n>>> stat(\"/usr/lib/git-core/git\", {st_mode=S_IFREG|0755, st_size=3093072,\n>>> ...}) = 0 pipe([9, 10])                           = 0\n>>> rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0\n>>> clone(child_stack=NULL,\n>>> flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,\n>>> child_tidptr=0x7f3e0e1dae50) = 12803 rt_sigprocmask(SIG_SETMASK, [],\n>>> NULL, 8) = 0\n>>> close(10)                               = 0 read(9, \"\", 8)\n>>> = 0\n>>> close(9)                                = 0\n>>> close(7)                                = 0\n>>> close(4)                                = 0 fcntl(8, F_GETFL)\n>>> = 0x1 (flags O_WRONLY) openat(AT_FDCWD, \".git/objects/3e\",\n>>> O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4 fstat(4,\n>>> {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0 getdents64(4, /* 22\n>>> entries */, 32768)  = 1328 getdents64(4, /* 0 entries */, 32768)   =\n>>> 0\n>>> close(4)                                = 0 fstat(8,\n>>> {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 write(8,\n>>> \"^3ea50e3c1f49c33f7dbbb5e3a31017f\"..., 83) = 83\n>>> close(8)                                = 0 Enumerating objects: 31,\n>>> done.ts: 1 Counting objects: 100% (31/31), done.\n>>> Delta compression using up to 8 threads Compressing objects: 100%\n>>> (23/23), done.\n>>> Writing objects: 100% (23/23), 5.60 KiB | 212.00 KiB/s, done.\n>>> Total 23 (delta 14), reused 0 (delta 0)\n>>> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 12803\n>>> --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=12803,\n>>> si_uid=1000, si_status=0, si_utime=2, si_stime=6} --- read(3,\n>>\n>> If FD 6 were wired up to something in the child and the child exited\n>> (which, having received SIGCHLD, is a safe bet), then we'd expect this\n>> to see this process get EOF.\n>>\n>> It's not clear to me what's going on here, but I think this code is\n>> ending up in connect.c (search for \"transport/file\").  Maybe someone\n>> else has an idea?\n>>\n>\n>Not sure I can add anything here to what Brian has already said, but you might try\n>setting GIT_TRACE2_PERF to an absolute path of a file or an existing directory.\n>That'll give you tracing around the child.\n\nThe only time I've seen something like this was when we had a poll issue setting a continuation after a non-block condition with no data that caused the stack to get confused. IIRC it was about 4 years ago and one of my first contributions. I don't think this is the same thing because poll does not seem to be involved.\n--Randall\n\n"},{"id":"454264","messageId":"BN0PR02MB7919DBC7EA3E84270A0C5E48F2F79@BN0PR02MB7919.namprd02.prod.outlook.com","threadId":"57770","inReplyTo":"fee354b5-e343-c997-b75a-63cf785b5337@jeffhostetler.com","subject":"RE: git push locks up forever, file protocol","fromName":"Jason Morgan","fromEmail":"jasomorg@qti.qualcomm.com","sentAt":"2022-04-22T16:11:50Z","receivedAt":"2022-04-22T16:12:00Z","isPatch":false,"sender":{"key":"jasomorg@qti.qualcomm.com","avatar":null},"body":"Brian/Jeff\n\nAs requested....\n\nI tried git 2.25.1 (stock Ubuntu 20.04) and git 2.36.0 (from ppa:git-core/ppa)\n\nI tried both file://<mount_point> and /<mount_point> for remote\n\nI tried both git -c protocol.version=0 as well as git -c protocol.version=2\n\nAll with exactly the same symptoms, halts at read(3,...\n\nI also tried a user bindfs mount instead of a mount bind in fstab as I noticed that I could not access the mount point from the latter over \\\\wsl$ in windows but I could with bindfs.\nThe change made no difference to git\n\nTrace GIT_TRACE2_PERF files attached for \"git push\" on v2.36.0 with /<mount_point> protocol (files 20220422T150*)\nLast few lines of strace for each combination also attached.\nRepeated for \"git push\" using the file:// protocol  (files 20220422T1555*)\n\nI provided the 'default' GIT_TRACE2_PERF invocation (rather than strace and/or -c) as I thought that it would better represent normal program flow.\n\nHope that hints at the issue.\nLet me know if there is anything else I can try.\n\n\nOn 4/21/22 9:31 PM, brian m. carlson wrote:\n> On 2022-04-21 at 08:30:50, Jason Morgan wrote:\n>> Hi,\n>>\n>> We have a remote repo accessed using the 'file:' protocol, mounted over Samba using drvfs into a WSL2 instance of Ubuntu 20.04.\n>>\n>> We find a 'git push' waits forever. git version 2.25.1\n>\n> I seem to recall that we've fixed some various issues with protocol \n> handling in the 2.29 timeframe.  Is it possible you could try 2.36.0 \n> to see if you can reproduce it there?\n>\n> Also, it would be interesting to see if there's a difference in \n> behaviour between setting protocol.version to 0 and setting it to 2.\n> That might tell us something that would help tracking this down.\n>\n>> Over a local LAN this works fine, but over a VPN this fails, hinting at some sort of race condition.\n>>\n>> Output from strace hints that git is trying (and failing) to read from a closed file handle.\n>\n> I don't think this is the case.  If Git were trying to read from a \n> closed file handle, the kernel would immediately return -1 with errno \n> set to EBADF.  Those operations won't block because there's nothing to \n> read.\n>\n>> Final output from strace:\n>>\n>> -----------\n>> openat(AT_FDCWD, \n>> \".git/objects/ad/065dad4384ae8c81c120c562985078d1f7b34b\", \n>> O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0444, st_size=152, ...}) = 0 mmap(NULL, 152, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\n>> close(3)                                = 0\n>> munmap(0x7f3e0e4af000, 152)             = 0\n>> openat(AT_FDCWD, \n>> \".git/objects/30/2508dfe5201db6c000ebf17b0c69e3afb31218\", \n>> O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0555, st_size=214, ...}) = 0 mmap(NULL, 214, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\n>> close(3)                                = 0\n>> munmap(0x7f3e0e4af000, 214)             = 0\n>> openat(AT_FDCWD, \n>> \".git/objects/d2/2323ec2ec40a74fbd519509662254c3cfda206\", \n>> O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0444, st_size=161, ...}) = 0 mmap(NULL, 161, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3e0e4af000\n>> close(3)                                = 0\n>\n> FD 3 is closed here...\n>\n>> munmap(0x7f3e0e4af000, 161)             = 0\n>> access(\".git/hooks/pre-push\", X_OK)     = -1 ENOENT (No such file or directory)\n>> write(4, \"00953ea50e3c1f49c33f7dbbb5e3a310\"..., 149) = 149\n>> write(4, \"0000\", 4)                     = 4\n>> pipe([3, 6])                            = 0\n>\n> And then it's recreated here as one part of a pipe, so it isn't closed.\n>\n>> fcntl(6, F_GETFD)                       = 0\n>> fcntl(6, F_SETFD, FD_CLOEXEC)           = 0\n>> mmap(NULL, 8392704, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, \n>> -1, 0) = 0x7f3e0d641000 mprotect(0x7f3e0d642000, 8388608, \n>> PROT_READ|PROT_WRITE) = 0 clone(child_stack=0x7f3e0de40fb0, \n>> flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_\n>> SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, \n>> parent_tid=[12802], tls=0x7f3e0de41700, child_tidptr=0x7f3e0de419d0) \n>> = 12802\n>\n> My guess is that in the child (which isn't shown here) that FD 6 is \n> hooked up to either standard output or standard error.  You'd need to \n> follow children to see.\n>\n>> pipe([7, 8])                            = 0\n>> stat(\"/usr/lib/git-core/git\", {st_mode=S_IFREG|0755, st_size=3093072, ...}) = 0\n>> pipe([9, 10])                           = 0\n>> rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0 \n>> clone(child_stack=NULL, \n>> flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f3e0e1dae50) = 12803 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0\n>> close(10)                               = 0\n>> read(9, \"\", 8)                          = 0\n>> close(9)                                = 0\n>> close(7)                                = 0\n>> close(4)                                = 0\n>> fcntl(8, F_GETFL)                       = 0x1 (flags O_WRONLY)\n>> openat(AT_FDCWD, \".git/objects/3e\", \n>> O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4 fstat(4, \n>> {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0 getdents64(4, /* 22 entries */, 32768)  = 1328\n>> getdents64(4, /* 0 entries */, 32768)   = 0\n>> close(4)                                = 0\n>> fstat(8, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 write(8, \n>> \"^3ea50e3c1f49c33f7dbbb5e3a31017f\"..., 83) = 83\n>> close(8)                                = 0\n>> Enumerating objects: 31, done.ts: 1\n>> Counting objects: 100% (31/31), done.\n>> Delta compression using up to 8 threads Compressing objects: 100% \n>> (23/23), done.\n>> Writing objects: 100% (23/23), 5.60 KiB | 212.00 KiB/s, done.\n>> Total 23 (delta 14), reused 0 (delta 0)\n>> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 12803\n>> --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=12803, \n>> si_uid=1000, si_status=0, si_utime=2, si_stime=6} --- read(3,\n>\n> If FD 6 were wired up to something in the child and the child exited \n> (which, having received SIGCHLD, is a safe bet), then we'd expect this \n> to see this process get EOF.\n>\n> It's not clear to me what's going on here, but I think this code is \n> ending up in connect.c (search for \"transport/file\").  Maybe someone \n> else has an idea?\n>\n\nNot sure I can add anything here to what Brian has already said, but you might try setting GIT_TRACE2_PERF to an absolute path of a file or an existing directory.  That'll give you tracing around the child.\n\nJeff\n\n"}]}