Cygwin hanging in pselect

[Erik Bray <erik dot m dot bray at gmail dot com>]

Hello, and happy new-ish year,

I've been working on and off over the past few months on bringing
Python's compatibility with Cygwin up to snuff, including having all
pertinent tests passing.  I've noticed that there are several tests
(which I currently skip) that cause the process to hang indefinitely,
and not respond to any signals from Cygwin (it can only be killed from
Windows).  This is Cygwin 64-bit--I have not tested 32-bit.

I finally looked into this problem and found the lockup to be in
pselect() somewhere.  Attached I've provided the most minimal example
I've been able to come up with so far that reproduces the problem,
which I'll describe in a bit more detail next. I would attach a
cygcheck output if requested, but I was also able to reproduce this on
a recent build from source.

So far as I've been able to tell, the problem only occurs with AF_UNIX
sockets.  In the example I have a 'server' socket and a 'client'
socket both set to non-blocking.  The client connects to the socket,
returning errno EINPROGRESS as expected.  Then I do a pselect on the
client socket to wait until it is ready to be read from.  The hang
only happens when I pselect on the client socket, and not on the
server socket.  It doesn't seem to make a difference what the timeout
is.  One thing I have no tried is if the client and server are
actually different processes, but the example from the Python tests
this is reproducing is where they are both in the same process.

Below is (I think) the most relevant output from strace on the test
case.  It seems to hang somewhere in socket_cleanup, but I haven't
investigated any further than that.

Thanks,
Erik

  261   14732 [main] poll_test 79200 cygwin_socket: socket (1, 1 (flags 0x0), 0)
--- Process 79200 loaded C:\Windows\System32\ws2_32.dll at 00007FFF8D5D0000
  985   15717 [main] poll_test 79200 wsock_init: res 0
   21   15738 [main] poll_test 79200 wsock_init: wVersion 514
   15   15753 [main] poll_test 79200 wsock_init: wHighVersion 514
   12   15765 [main] poll_test 79200 wsock_init: szDescription WinSock 2.0
   13   15778 [main] poll_test 79200 wsock_init: szSystemStatus Running
   17   15795 [main] poll_test 79200 wsock_init: iMaxSockets 0
   16   15811 [main] poll_test 79200 wsock_init: iMaxUdpDg 0
--- Process 79200 loaded C:\Windows\System32\mswsock.dll at 00007FFF89540000
  557   16368 [main] poll_test 79200 build_fh_pc: fh 0x18030BE70, dev 001E0079
   87   16455 [main] poll_test 79200 fhandler_base::set_flags: flags
0x10002, supplied_bin 0x0
   18   16473 [main] poll_test 79200 fhandler_base::set_flags:
O_TEXT/O_BINARY set in flags 0x10000
   15   16488 [main] poll_test 79200 fhandler_base::set_flags:
filemode set to binary
   15   16503 [main] poll_test 79200 fdsock: fd 3, name '', soc 0x180
   21   16524 [main] poll_test 79200 cygwin_socket: 3 = socket(1, 1
(flags 0x0), 0)
   15   16539 [main] poll_test 79200 fcntl64: fcntl(3, 3, ...)
   17   16556 [main] poll_test 79200 fhandler_base::fcntl: GETFL: 0x10002
   15   16571 [main] poll_test 79200 fcntl64: 65538 = fcntl(3, 3, 0x0)
   16   16587 [main] poll_test 79200 fcntl64: fcntl(3, 4, ...)
   22   16609 [main] poll_test 79200 fhandler_socket::ioctl: socket is
now nonblocking
   22   16631 [main] poll_test 79200 fhandler_socket::ioctl: 0 =
ioctl_socket(8004667E, 0xFFFFC9FC)
   17   16648 [main] poll_test 79200 fhandler_base::set_flags: flags
0x14002, supplied_bin 0x0
   18   16666 [main] poll_test 79200 fhandler_base::set_flags:
O_TEXT/O_BINARY set in flags 0x10000
   15   16681 [main] poll_test 79200 fhandler_base::set_flags:
filemode set to binary
   15   16696 [main] poll_test 79200 fcntl64: 0 = fcntl(3, 4, 0x14002)
   21   16717 [main] poll_test 79200 normalize_posix_path: src @test.sock

   ... snip path checking stuff...

   19   17118 [main] poll_test 79200 path_conv::check:
this->path(C:\Users\Erik M. Bray\src\python\cpython\@test.sock),
has_acls(1)
   70   17188 [main] poll_test 79200 fhandler_socket::bind: AF_LOCAL:
socket bound to port 55085
  298   17486 [main] poll_test 79200 set_posix_access: ACL-Size: 100
   37   17523 [main] poll_test 79200 set_posix_access: Created SD-Size: 176
--- Process 79200 loaded C:\Windows\System32\cryptbase.dll at 00007FFF898B0000
--- Process 79200 loaded C:\Windows\System32\bcryptprimitives.dll at
00007FFF8AE30000
 3492   21015 [main] poll_test 79200 cygwin_bind: 0 = bind(3, 0xFFFFCB10, 110)
  112   21127 [main] poll_test 79200 getpid: 79200 = getpid()
   27   21154 [main] poll_test 79200 cygwin_listen: 0 = listen(3, 5)
   21   21175 [main] poll_test 79200 cygwin_socket: socket (1, 1 (flags 0x0), 0)
   68   21243 [main] poll_test 79200 build_fh_pc: fh 0x18030C310, dev 001E0079
   44   21287 [main] poll_test 79200 fhandler_base::set_flags: flags
0x10002, supplied_bin 0x0
   15   21302 [main] poll_test 79200 fhandler_base::set_flags:
O_TEXT/O_BINARY set in flags 0x10000
   13   21315 [main] poll_test 79200 fhandler_base::set_flags:
filemode set to binary
   13   21328 [main] poll_test 79200 fdsock: fd 4, name '', soc 0x188
   20   21348 [main] poll_test 79200 cygwin_socket: 4 = socket(1, 1
(flags 0x0), 0)
   16   21364 [main] poll_test 79200 fcntl64: fcntl(4, 3, ...)
   15   21379 [main] poll_test 79200 fhandler_base::fcntl: GETFL: 0x10002
   13   21392 [main] poll_test 79200 fcntl64: 65538 = fcntl(4, 3, 0x0)
   17   21409 [main] poll_test 79200 fcntl64: fcntl(4, 4, ...)
   14   21423 [main] poll_test 79200 fhandler_socket::ioctl: socket is
now nonblocking
   14   21437 [main] poll_test 79200 fhandler_socket::ioctl: 0 =
ioctl_socket(8004667E, 0xFFFFC9FC)
   13   21450 [main] poll_test 79200 fhandler_base::set_flags: flags
0x14002, supplied_bin 0x0
   13   21463 [main] poll_test 79200 fhandler_base::set_flags:
O_TEXT/O_BINARY set in flags 0x10000
   13   21476 [main] poll_test 79200 fhandler_base::set_flags:
filemode set to binary
   12   21488 [main] poll_test 79200 fcntl64: 0 = fcntl(4, 4, 0x14002)
   20   21508 [main] poll_test 79200 normalize_posix_path: src @test.sock

...

   76   21922 [main] poll_test 79200 getpid: 79200 = getpid()
--- Process 79200 thread 18528 created
  350   22272 [main] poll_test 79200 __set_errno: void
__set_winsock_errno(const char*, int):224 setting errno 119
   26   22298 [main] poll_test 79200 __set_winsock_errno: connect:1232
- winsock error 10036 -> errno 119
   17   22315 [main] poll_test 79200 cygwin_connect: -1 = connect(4,
0xFFFFCB10, 110), errno 119
  100   22415 [main] poll_test 79200 time: 1483702462 = time(0x0)
  731   23146 [main] poll_test 79200
pwdgrp::fetch_account_from_windows: line:
<Administrators:S-1-5-32-544:544:>
  108   23254 [main] poll_test 79200 stat64: entering
   32   23286 [main] poll_test 79200 normalize_posix_path: src /dev
   30   23316 [main] poll_test 79200 normalize_posix_path: /dev =
normalize_posix_path (/dev)
   26   23342 [main] poll_test 79200 mount_info::conv_to_win32_path:
conv_to_win32_path (/dev)
   27   23369 [main] poll_test 79200 set_flags: flags: binary (0x2)
   23   23392 [main] poll_test 79200 mount_info::conv_to_win32_path:
src_path /dev, dst C:\cygwin64\dev, flags 0x3000A, rc 0
   54   23446 [main] poll_test 79200 symlink_info::check: 0x0 =
NtCreateFile (\??\C:\cygwin64\dev)
   37   23483 [main] poll_test 79200 symlink_info::check: not a symlink
   29   23512 [main] poll_test 79200 symlink_info::check: 0 =
symlink.check(C:\cygwin64\dev, 0xFFFFB250) (0x43000A)
   39   23551 [main] poll_test 79200 build_fh_pc: fh 0x18030C700, dev 000000C1
   30   23581 [main] poll_test 79200 stat_worker:
(\??\C:\cygwin64\dev, 0x1802E2A20, 0x18030C700), file_attributes 16
  194   23775 [main] poll_test 79200 fhandler_base::fstat_helper: 0 =
fstat (\??\C:\cygwin64\dev, 0x1802E2A20) st_size=0, st_mode=040755,
st_ino=562949953536516st_atim=57696141.1B43B4B0
st_ctim=57696141.1B43B4B0 st_mtim=57696141.1B43B4B0
st_birthtim=5769612C.1F3F08BC
   44   23819 [main] poll_test 79200 stat_worker: 0 =
(\??\C:\cygwin64\dev,0x1802E2A20)
   38   23857 [main] poll_test 79200 fstat64: 0 = fstat(1, 0xFFFFC580)
   48   23905 [main] poll_test 79200 isatty: 1 = isatty(1)
  154   24059 [main] poll_test 79200 fhandler_pty_slave::write: pty9,
write(0x6000426B0, 40)
   51   24110 [main] poll_test 79200
fhandler_pty_common::process_opost_output: (1901): pty output_mutex
(0x140): waiting -1 ms
   47   24157 [main] poll_test 79200
fhandler_pty_common::process_opost_output: (1901): pty output_mutex:
acquired
   23   24180 [main] poll_test 79200
fhandler_pty_common::process_opost_output: (1940): pty
output_mutex(0x140) released
Ret from client connect: -1; errno: 119
   23   24203 [main] poll_test 79200 write: 40 = write(1, 0x6000426B0, 40)
   99   24302 [main] poll_test 79200 pselect: pselect (5, 0xFFFFCB90,
0x0, 0x0, 0xFFFFCB80, 0x0)
   20   24322 [main] poll_test 79200 pselect: to->tv_sec 1,
to->tv_nsec 0, us 1000000
   41   24363 [main] poll_test 79200 dtable::select_read:  fd 4
   33   24396 [main] poll_test 79200 select: sel.always_ready 0
   97   24493 [main] poll_test 79200 start_thread_socket: stuff_start 0xFFFFC8E8
--- Process 79200 thread 46528 created
  172   24665 [socksel] poll_test 79200 cygthread::stub: thread
'socksel', id 0xB5C0, stack_ptr 0x12ECCD0
   24   24689 [socksel] poll_test 79200 thread_socket: stuff_start
0xFFFFC8E8, timeout 4294967295
   23   24712 [main] poll_test 79200 select_stuff::wait: m 4, us
1000000, wmfo_timeout -1
   31   24743 [socksel] poll_test 79200
fhandler_socket::af_local_connect: af_local_connect called,
no_getpeereid=0
  106   24849 [socksel] poll_test 79200
fhandler_socket::af_local_send_secret: Sending af_local secret
succeeded
999984 1024833 [main] poll_test 79200 select_stuff::wait: wait_ret 3,
m = 4.  verifying
   65 1024898 [main] poll_test 79200 select_stuff::wait: timed out
   38 1024936 [main] poll_test 79200 select_stuff::wait: returning 1
   31 1024967 [main] poll_test 79200 select: sel.wait returns 1
   18 1024985 [main] poll_test 79200 select_stuff::cleanup: calling
cleanup routines
   16 1025001 [main] poll_test 79200 socket_cleanup: si 0x6000526C0
si->thread 0x1801FE758

#include <arpa/inet.h>
#include <sys/socket.h>
#include <string.h>
#include <stdio.h>
#include <fcntl.h>
#include <sys/time.h>
#include <sys/un.h>
#include <errno.h>


#define SET_NONBLOCKING(sock) fcntl(sock, F_SETFL, fcntl(sock, F_GETFL, 0) | O_NONBLOCK);


int main(void) {
    fd_set rfds;
    struct timespec tv;
    int sock_server, sock_client;
    int retval;
    struct sockaddr_un addr; \

    memset(&addr, 0, sizeof(addr)); \
    addr.sun_family = AF_UNIX; \
    strcpy(addr.sun_path, "@test.sock");

    sock_server = socket(AF_UNIX, SOCK_STREAM, 0);
    SET_NONBLOCKING(sock_server);
    if (bind(sock_server, (struct sockaddr*)&addr, sizeof(addr))) {
        printf("binding server socket failed");
        return 1;
    }
    listen(sock_server, 5);

    sock_client = socket(AF_UNIX, SOCK_STREAM, 0);
    SET_NONBLOCKING(sock_client);
    retval = connect(sock_client, (struct sockaddr*)&addr, sizeof(addr));
    printf("Ret from client connect: %d; errno: %d\n", retval, errno);

    FD_ZERO(&rfds);
    FD_SET(sock_client, &rfds);
    tv.tv_sec = 1;
    tv.tv_nsec = 0;

    retval = pselect(sock_client + 1, &rfds, NULL, NULL, &tv, NULL);

    return 0;
}

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple