{"action":"created","issue":{"url":"https://api.github.com/repos/Microsoft/BashOnWindows/issues/419","repository_url":"https://api.github.com/repos/Microsoft/BashOnWindows","labels_url":"https://api.github.com/repos/Microsoft/BashOnWindows/issues/419/labels{/name}","comments_url":"https://api.github.com/repos/Microsoft/BashOnWindows/issues/419/comments","events_url":"https://api.github.com/repos/Microsoft/BashOnWindows/issues/419/events","html_url":"https://github.com/Microsoft/BashOnWindows/issues/419","id":156377249,"number":419,"title":"select sometimes block forever on a ready TCP sockets","user":{"login":"xilun","id":6464553,"avatar_url":"https://avatars.githubusercontent.com/u/6464553?v=3","gravatar_id":"","url":"https://api.github.com/users/xilun","html_url":"https://github.com/xilun","followers_url":"https://api.github.com/users/xilun/followers","following_url":"https://api.github.com/users/xilun/following{/other_user}","gists_url":"https://api.github.com/users/xilun/gists{/gist_id}","starred_url":"https://api.github.com/users/xilun/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/xilun/subscriptions","organizations_url":"https://api.github.com/users/xilun/orgs","repos_url":"https://api.github.com/users/xilun/repos","events_url":"https://api.github.com/users/xilun/events{/privacy}","received_events_url":"https://api.github.com/users/xilun/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":7,"created_at":"2016-05-23T22:04:51Z","updated_at":"2016-05-24T23:24:12Z","closed_at":null,"body":"Hi,\r\n\r\nAttached are two straces captured, while developing [cbwin](https://github.com/xilun/cbwin), with:\r\n\r\n    $ strace -tt -o select_block.txt wcmd dir /s c:\\\\windows | cat\r\n\r\n[select_block.txt](https://github.com/Microsoft/BashOnWindows/files/278329/select_block.txt)\r\n\r\n[pselect_block.txt](https://github.com/Microsoft/BashOnWindows/files/278331/pselect_block.txt)\r\n\r\nThey show that select() (or pselect(), on a dev version of my tool) sometimes block forever (see at the end, I then interrupt the program with CTRL-C) on ready sockets. The peer has no reason to block forever at this point, and both `> dir /s c:\\\\windows` and `$ wcmd dir /s c:\\\\windows` work correctly until the end. With `| cat` the problem occur very far from the expected termination (several MB of data should still be transmitted). The problem does not occur with `| wc` (at least the few dozen of times I ran it) and straces with `| wc` shows that read() never returns 16384 bytes in this case, implying TCP buffers are always quite empty. OTOH `| cat` is probably slowed down by console display, and somehow the end result is this unexpected blocking.\r\n\r\nPlease note that when it blocks, the last read/write syscalls before show the following pattern:\r\n\r\n    21:07:23.289414 read(5, \"236F_FC70_11D3_A536_0090278A1BB8\"..., 16384) = 16384\r\n    21:07:23.289414 write(1, \"236F_FC70_11D3_A536_0090278A1BB8\"..., 16384) = 16384\r\n    21:07:23.289414 read(5, \"soft_WindowsPhone_CPP_Version_x8\"..., 16384) = 16384\r\n    21:07:23.289414 write(1, \"soft_WindowsPhone_CPP_Version_x8\"..., 16384) = 16384\r\n    21:07:23.289414 read(5, \"       309\\302\\240326 ProductIcon.ico\\r\"..., 16384) = 16384\r\n    21:07:23.289414 write(1, \"       309\\302\\240326 ProductIcon.ico\\r\"..., 16384) = 16384\r\n    21:07:23.383613 read(5, 0x6081c8, 16384) = -1 EAGAIN (Resource temporarily unavailable)\r\n    21:07:23.383613 select(6, [5], [], NULL, NULL) = -1 EINTR (Interrupted system call)\r\n    21:09:00.149997 --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---\r\n\r\n[5] is the socket, connected to the Win32 side, that causes problems.\r\nBlocks of 16384 (my buffer size) are completely filled and output to stdout which is the pipe connected to `cat`, until read() abruptly returns -1 EAGAIN. This in itself seems a bit odd - to transition from a filled TCP buffer to exactly empty by reads of complete blocks of 16384 bytes - but not impossible, although the problem seems to only occur with this pattern and there are various non problematic occurrences of < 16384 bytes reads followed by -1 EAGAIN sooner.\r\n\r\nMy reproducibility is 100%. I'm on build 14342. When it happens both wcmd and cmd.exe processes are not in a suspended state but use exactly 0% of the CPU. When not stracing, gdb can attach to wcmd and confirms it is blocked in select/pselect. At the same time, the stack of cmd.exe is:\r\n\r\n    ntdll.dll!ZwWriteFile+0x14\r\n    KERNELBASE.dll!WriteFile+0x88\r\n    cmd.exe+0xe3a7\r\n    cmd.exe+0x12fb5\r\n    cmd.exe+0x2328c\r\n    cmd.exe+0x1d310\r\n    cmd.exe+0xf277\r\n    cmd.exe+0xd569\r\n    cmd.exe+0xd827\r\n    cmd.exe+0xfab9\r\n    cmd.exe+0x11957\r\n    cmd.exe+0x119bd\r\n    cmd.exe+0xb9d9\r\n    cmd.exe+0xb295\r\n    cmd.exe+0x53b2\r\n    cmd.exe+0x1531d\r\n    KERNEL32.DLL!BaseThreadInitThunk+0x14\r\n    ntdll.dll!RtlUserThreadStart+0x21\r\n\r\nI've not yet tried to isolate whether or not Win32 redirection of standard handles to sockets plays a role in this situation, nor reduce how to trigger the bug to smaller programs, however please note that this time the Winsock handle remains open in outbash.exe that called CreateProcess(\"cmd\") until after cmd.exe terminates (contrary to #347 ), and I've plenty of evidence that shows that select/pselect() (or something beneath it) is actually misbehaving.\r\nAlthough not equivalent at all, a quick test of \"cmd /C dir /s c:\\\\windows | cat\" under Cygwin64 under the windows console shows no problem -- this let me think that at least it's not just cmd.exe that got upset by any redirections...\r\n"},"comment":{"url":"https://api.github.com/repos/Microsoft/BashOnWindows/issues/comments/221431518","html_url":"https://github.com/Microsoft/BashOnWindows/issues/419#issuecomment-221431518","issue_url":"https://api.github.com/repos/Microsoft/BashOnWindows/issues/419","id":221431518,"user":{"login":"xilun","id":6464553,"avatar_url":"https://avatars.githubusercontent.com/u/6464553?v=3","gravatar_id":"","url":"https://api.github.com/users/xilun","html_url":"https://github.com/xilun","followers_url":"https://api.github.com/users/xilun/followers","following_url":"https://api.github.com/users/xilun/following{/other_user}","gists_url":"https://api.github.com/users/xilun/gists{/gist_id}","starred_url":"https://api.github.com/users/xilun/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/xilun/subscriptions","organizations_url":"https://api.github.com/users/xilun/orgs","repos_url":"https://api.github.com/users/xilun/repos","events_url":"https://api.github.com/users/xilun/events{/privacy}","received_events_url":"https://api.github.com/users/xilun/received_events","type":"User","site_admin":false},"created_at":"2016-05-24T23:24:12Z","updated_at":"2016-05-24T23:24:12Z","body":"@sunilmut I might have previously misread one of your sentence.\r\n\r\n> We recently fixed a bug in the socket EPOLL where a select (EPOLLIN) would block on a disconnected TCP socket, if a subsequent read drained all the data.\r\n\r\nTo buffer do seem to be emptied on this half-closed connection *after* it has been half-closed because this is actually performed right after connect/accept, before any data is transmitted. However the traces show the buffer is emptied several time before the bug, and in those case everything continues to work as expected (select unblocks ASA more data is available, that is at max after a few ms given this test)\r\n\r\nThe buffer is not emptied after a complete close, though, because we are several MB away from the end and I also checked that the socket is still in CLOSE_WAIT and FIN_WAIT_2 when it is improperly blocked.\r\n"}}
{"actor":{"display_login":"xilun"}}