On Thu Dec 06 12:45:18 2018, PEVANS wrote:
Show quoted text> I elect this is an IPC::Open3 bug.
Aaaactually, this looks more complicated than that.
I added some printing of opened filehandles according to the kernel, either side of the open3() call:
print STDERR `lsof -p $$ +E`;
my $pid = IPC::Open3::open3(my $stdin, my $stdout, my $stderr = gensym, $cmd);
print STDERR `lsof -p $$ +E`;
The output of which is:
Before:
perl 2954 leo 0u CHR 136,3 0t0 6 /dev/pts/3
perl 2954 leo 1w FIFO 0,12 0t0 43396 pipe 2953,perl,4r
perl 2954 leo 2w FIFO 0,12 0t0 43397 pipe 2953,perl,6r
perl 2954 leo 3r FIFO 0,12 0t0 40623 pipe 2955,lsof,1w
perl 2954 leo 9w FIFO 0,12 0t0 43398 pipe 2953,perl,8r
As was expected; STDIN remained from the terminal, STDOUT and STDERR are pipes to the parent process, fd 3 is the qx() pipe from lsof, and fd 9 is the status pipe for IO::Async::Process.
After:
perl 2954 leo 0u CHR 136,3 0t0 6 /dev/pts/3
perl 2954 leo 1w FIFO 0,12 0t0 43396 pipe 2953,perl,4r
perl 2954 leo 2w FIFO 0,12 0t0 43397 pipe 2953,perl,6r
perl 2954 leo 3r FIFO 0,12 0t0 40623 pipe
perl 2954 leo 4r FIFO 0,12 0t0 43401 pipe 2954,perl,5w
perl 2954 leo 5w FIFO 0,12 0t0 43401 pipe 2954,perl,4r
perl 2954 leo 6r FIFO 0,12 0t0 43402 pipe 2954,perl,7w
perl 2954 leo 7w FIFO 0,12 0t0 43402 pipe 2954,perl,6r
perl 2954 leo 8r FIFO 0,12 0t0 43403 pipe
perl 2954 leo 9w FIFO 0,12 0t0 43398 pipe 2953,perl,8r
perl 2954 leo 10r FIFO 0,12 0t0 43405 pipe 2960,lsof,1w
We have gained fds 4+5 and 6+7 for which we're holding *both* sides. Hrm...
I further added logging inside IPC/Open3.pm to the xclose() function, having it print the values of filehandles it is attempting to close. It really tried:
sub xclose {
print STDERR "ENTER xclose($_[0]/IO=${\fileno $_[0]})\n";
...
Output:
ENTER xclose(GLOB(0x557681ad8840)/IO=4)
ENTER xclose(GLOB(0x557681b156d0)/IO=7)
ENTER xclose(GLOB(0x557681b07df0)/IO=10)
It tried to close 4, 7 and 10, but yet those remain open.
I now compare to a working case where the child doesn't deadlock, by commenting out the part where the ->open_process call replaces the child's stderr. Now I get:
Before:
perl 4534 leo 0u CHR 136,3 0t0 6 /dev/pts/3
perl 4534 leo 1w FIFO 0,12 0t0 62923 pipe 4533,perl,4r
perl 4534 leo 2u CHR 136,3 0t0 6 /dev/pts/3
perl 4534 leo 3r FIFO 0,12 0t0 64257 pipe 4535,lsof,1w
perl 4534 leo 7w FIFO 0,12 0t0 62924 pipe 4533,perl,6r
Output:
ENTER xclose(GLOB(0x55ae34a8f2a8)/IO=4)
ENTER xclose(GLOB(0x55ae34a8ef48)/IO=8)
ENTER xclose(GLOB(0x55ae34a8ed98)/IO=10)
After:
perl 4534 leo 0u CHR 136,3 0t0 6 /dev/pts/3
perl 4534 leo 1w FIFO 0,12 0t0 62923 pipe 4533,perl,4r
perl 4534 leo 2u CHR 136,3 0t0 6 /dev/pts/3
perl 4534 leo 3r FIFO 0,12 0t0 64257 pipe
perl 4534 leo 4r FIFO 0,12 0t0 62925 pipe 4534,perl,5w
perl 4534 leo 5w FIFO 0,12 0t0 62925 pipe 4534,perl,4r
perl 4534 leo 6r FIFO 0,12 0t0 62926 pipe
perl 4534 leo 7w FIFO 0,12 0t0 62924 pipe 4533,perl,6r
perl 4534 leo 8r FIFO 0,12 0t0 62929 pipe 4538,lsof,1w
perl 4534 leo 9r FIFO 0,12 0t0 62927 pipe
It still manages to be holding both sides of the fd 4+5 pair, but its attempt to close 8 and 10 were successful (8 has been reused for lsof, 10 is now closed)
Something oddly strange is occurring, whereby perl code executes the close() operator, but that doesn't always result in a close(2) system call. Whether or not it does, seems to depend on what happens to STDERR.
--
Paul Evans
