Bug #86874 for System-Command: System::Command Closing Handles Prematurely

Thu Jul 11 22:22:12 2013 NNUTTER [...] cpan.org - Ticket created

Subject:

System::Command Not Setting Any Exit Code, -1 or Otherwise

System::Command is not setting any exit code, not even -1. This could be a Mac OS X bug; if I get more information I'll let you know. I noticed because Git::Repository::Command was not die when Git should be return fatal exit codes, e.g. when trying to push to a remote that doesn't exist. $ perl -e 'use System::Command; my $c = System::Command->new(q(false)); print $c->exit, qq(\n);' $ perl -e 'use System::Command; my $c = System::Command->new(q(true)); print $c->exit, qq(\n);' $ perl -e 'use System::Command; print $System::Command::VERSION, qq(\n);' 1.101

Subject:

perlv.txt

Summary of my perl5 (revision 5 version 12 subversion 5) configuration: Platform: osname=darwin, osvers=12.4.0, archname=darwin-2level uname='darwin x 12.4.0 darwin kernel version 12.4.0: wed may 1 17:57:12 pdt 2013; root:xnu-2050.24.15~1release_x86_64 x86_64 ' config_args='-de -Dprefix=/Users/nnutter/.perlbrew/perls/perl-5.12.5 -Aeval:scriptdir=/Users/nnutter/.perlbrew/perls/perl-5.12.5/bin' hint=recommended, useposix=true, d_sigaction=define useithreads=undef, usemultiplicity=undef useperlio=define, d_sfio=undef, uselargefiles=define, usesocks=undef use64bitint=define, use64bitall=define, uselongdouble=undef usemymalloc=n, bincompat5005=undef Compiler: cc='cc', ccflags ='-fno-common -DPERL_DARWIN -fno-strict-aliasing -pipe -fstack-protector -I/usr/local/include', optimize='-O3', cppflags='-fno-common -DPERL_DARWIN -fno-strict-aliasing -pipe -fstack-protector -I/usr/local/include' ccversion='', gccversion='4.2.1 Compatible Apple LLVM 4.2 (clang-425.0.27)', gccosandvers='' intsize=4, longsize=8, ptrsize=8, doublesize=8, byteorder=12345678 d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=16 ivtype='long', ivsize=8, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8 alignbytes=8, prototype=define Linker and Libraries: ld='env MACOSX_DEPLOYMENT_TARGET=10.3 cc', ldflags =' -fstack-protector -L/usr/local/lib' libpth=/usr/local/lib /usr/lib libs=-lgdbm -ldbm -ldl -lm -lutil -lc perllibs=-ldl -lm -lutil -lc libc=, so=dylib, useshrplib=false, libperl=libperl.a gnulibc_version='' Dynamic Linking: dlsrc=dl_dlopen.xs, dlext=bundle, d_dlsymun=undef, ccdlflags=' ' cccdlflags=' ', lddlflags=' -bundle -undefined dynamic_lookup -L/usr/local/lib -fstack-protector' Characteristics of this binary (from libperl): Compile-time options: PERL_DONT_CREATE_GVSV PERL_MALLOC_WRAP USE_64_BIT_ALL USE_64_BIT_INT USE_LARGE_FILES USE_PERLIO USE_PERL_ATOF Built under darwin Compiled at Jun 6 2013 21:51:49 %ENV: PERL5LIB="/Users/nnutter/lib/perl5" PERLBREW_BASHRC_VERSION="0.64" PERLBREW_HOME="/Users/nnutter/.perlbrew" PERLBREW_MANPATH="/Users/nnutter/.perlbrew/perls/perl-5.12.5/man" PERLBREW_PATH="/Users/nnutter/.perlbrew/bin:/Users/nnutter/.perlbrew/perls/perl-5.12.5/bin" PERLBREW_PERL="perl-5.12.5" PERLBREW_ROOT="/Users/nnutter/.perlbrew" PERLBREW_VERSION="0.64" @INC: /Users/nnutter/lib/perl5 /Users/nnutter/.perlbrew/perls/perl-5.12.5/lib/site_perl/5.12.5/darwin-2level /Users/nnutter/.perlbrew/perls/perl-5.12.5/lib/site_perl/5.12.5 /Users/nnutter/.perlbrew/perls/perl-5.12.5/lib/5.12.5/darwin-2level /Users/nnutter/.perlbrew/perls/perl-5.12.5/lib/5.12.5 .

Thu Jul 11 22:23:42 2013 NNUTTER [...] cpan.org - Correspondence added

OK, I'm guessing this is a waitpid issue: $ time perl -e 'use System::Command; my $c = System::Command->new(qw(sleep 10)); print $c->exit, qq(\n);' real 0m0.041s user 0m0.026s sys 0m0.008s

Thu Jul 11 22:31:28 2013 NNUTTER [...] cpan.org - Correspondence added

System::Command::new does not add an exit key to the object but exit is treated as a simple, key-based, attribute.

Thu Jul 11 22:34:30 2013 NNUTTER [...] cpan.org - Correspondence added

Ugh, this whole thing might be a bad bug report... sorry. At least the previous usage was wrong so not a waitpid issue. ! time perl -e 'use System::Command; $DB::single = 1; my $c = System::Command->new(qw(sleep 2)); $c->close(); print $c->exit, qq(\n);' 0 real 0m2.036s

Thu Jul 11 22:48:36 2013 NNUTTER [...] cpan.org - Correspondence added

OK, to prove I am not totally insane. Here's it failing when I try to debug it and passing when I don't: $ perl -d -I lib t/branch.t main::(t/branch.t:20): $push->close(); auto(-1) DB<1> {{v DB<2> c Died at t/branch.t line 23. at t/branch.t line 23. Debugged program terminated. Use q to quit or R to restart, use o inhibit_exit to avoid stopping after program termination, h q, h R or h o to get additional info. auto(-1) DB<2> v 9549 9550 9551 sub at_exit { 9552==> "Debugged program terminated. Use `q' to quit or `R' to restart."; 9553 } 9554 9555 package DB; # Do not trace this 1; below! DB<2> q $ perl -I lib t/branch.t Name "DB::single" used only once: possible typo at t/branch.t line 18. ok 1 - got a Branch object ok 2 - full_name = refs/heads/master ok 3 - name = master 1..3

Thu Jul 11 22:58:26 2013 NNUTTER [...] cpan.org - Correspondence added

Still trying to work this out but here's how to make sense of the debug failing but non-debug not; it's time-based: # without a sleep before close() it passes $ perl -e 'use System::Command; my $c = System::Command->new(qw(git push nowhere master)); $c->close(); print $c->exit, qq(\n);' 0 # with a sleep 2 it fails $ perl -e 'use System::Command; my $c = System::Command->new(qw(git push nowhere master)); sleep 2; $c->close(); print $c->exit, qq(\n);' 128

Thu Jul 11 23:27:47 2013 NNUTTER [...] cpan.org - Correspondence added

In close(), if I move the $self->_reap(); to before the file handle closes then it behaves as expected.

Thu Jul 11 23:32:15 2013 NNUTTER [...] cpan.org - Correspondence added

On Thu Jul 11 23:27:47 2013, NNUTTER wrote: Show quoted text

> In close(), if I move the $self->_reap(); to before the file handle > closes then it behaves as expected.

And now when I think I've reverted my changes I can't even reproduce it.

Fri Jul 12 00:05:42 2013 NNUTTER [...] cpan.org - Correspondence added

On Thu Jul 11 23:27:47 2013, NNUTTER wrote: Show quoted text

> In close(), if I move the $self->_reap(); to before the file handle > closes then it behaves as expected.

OK, I think this is part bug and mostly user error. I made two errors in usage that confused me: - not calling close() before checking exit() - not checking signal() However, I think there is a bug. My theory is that close() is closing the STDERR, STDIN, and STDOUT handles while the process is still trying to write to them causing the process to signal. I may have seen hints of this when debugging where $! was set to Illegal Seek (but I don't know that it's not just coincidence). I don't know how to confirm this but if this is the case then close() should reap the process before calling close on the handles. This whole thing started because a Git::Repository->run() wasn't failing when I expected it to (trying to push to a remote that didn't exist) but I can't reproduce that anymore and run uses Git::Repository::Command::final_output which would avoid the above bug because it waits for STDERR and STDOUT to be closed by the process.

Fri Jul 12 00:06:22 2013 NNUTTER [...] cpan.org - Subject changed from 'System::Command Not Setting Any Exit Code, -1 or Otherwise' to 'System::Command Closing Handles Prematurely'

Mon Jul 15 12:24:29 2013 book [...] cpan.org - Correspondence added

Many thanks for the detailed report. :-) On Thu Jul 11 22:58:26 2013, NNUTTER wrote: Show quoted text

> Still trying to work this out but here's how to make sense of the > debug failing but non-debug not; it's time-based: > > # without a sleep before close() it passes > $ perl -e 'use System::Command; my $c = System::Command->new(qw(git > push nowhere master)); $c->close(); print $c->exit, qq(\n);' > 0 > > # with a sleep 2 it fails > $ perl -e 'use System::Command; my $c = System::Command->new(qw(git > push nowhere master)); sleep 2; $c->close(); print $c->exit, qq(\n);' > 128

I think what happens is that the call to close() happens before the git command has had a chance to run entirely. Without the sleep, you basically start the subprocess, and then immediately close all its communication ports before waiting for it to terminate. With the sleep, the process has enough time to do its task, and when the parent process does a waitpid() it gets the actual exit status. Actually, it could even be that the call to close happens before the forked child has had a chance to exec() into the git command. And the fact that all pipes are closed fires up something that prevents the exec() call to actually be performed. Maybe. Anyway, you're only supposed to use close() when you know the command is completed. The most used command in Git::Repository is actually run(). The above code example would be written: $ perl -MGit::Repository -e 'Git::Repository->new->run( qw( push nowhere master ) )' Note that you can still access the exit status using $? (See https://metacpan.org/module/Git::Repository#run-cmd for details). It's also possible (in recent versions) to use the 'fatal' option to finely control which exit statuses will cause run() to die. command() (which returns a System:::Command object) is actually meant for those cases where you want to do more than get the output of the git command or die trying. In most cases, you won'd need it. Hoping that helps. -- BooK

Mon Jul 15 12:24:30 2013 The RT System itself - Status changed from 'new' to 'open'

Wed Jul 17 23:24:29 2013 NNUTTER [...] cpan.org - Correspondence added

On Mon Jul 15 12:24:29 2013, BOOK wrote: Show quoted text

> Many thanks for the detailed report. :-)

Yeah, I was going crazy. =) Show quoted text

> Anyway, you're only supposed to use close() when you know the command > is completed.

Would it make sense for close to warn or even die then if the child is still running? Is that not something you can check portability-wise? Otherwise I think we can just resolve this ticket. Show quoted text

> The most used command in Git::Repository is actually run().

I was using run() but it wasn't failing at some point that I thought it should have but given how confused I had become who knows what that original problem was. Thanks!

Thu Jul 18 08:26:24 2013 book [...] cpan.org - Correspondence added

On Wed Jul 17 23:24:29 2013, NNUTTER wrote: Show quoted text

> On Mon Jul 15 12:24:29 2013, BOOK wrote: >

> > Anyway, you're only supposed to use close() when you know the command > > is completed.

> > Would it make sense for close to warn or even die then if the child is > still running? Is that not something you can check portability-wise? > Otherwise I think we can just resolve this ticket.

Actually, the goal of close is to stop the process. When stdin/stdout/stderr are closed the git process gets a SIGPIPE and dies (I think). I could very well be that this just creates zombies in many situations. System::Command is mostly used by Git::Repository, so I didn't get many reports about zombies (yet). https://metacpan.org/requires/distribution/System-Command The easiest way to create zombies with System::Command since v1.03 is to do this: my $out = System::Command->new( ... )->stdout; When the System::Command object gets out of scope (right after we get our hands on the stdout filehandle of the child process), it is destroyed, and we have nothing to call waitpid() on. If you look in the history of System::Command, you'll see I have tried several approaches to deal with that. The best explanation is there: https://github.com/book/Git-Repository/commit/16a03c7d42e17ce66e7051a5cc83c0a8716cc911 Before that, I used DESTROY to kill the child process and close all filehandles as soon as the (at the time, before I forked off most of the code into System::Command) Git::Repository::Command went out of scope. That broke the above technique, since $out would now point to a closed filehandle. So I delegated reaping the child process to a reaper object that handled the cleaning up as soon as all objects went out of scope. Then a friend conviced me that I didn't need all that complexity, and I removed the Reaper logic (DESTROY was already gone). All my tests still passed, and I had forgotten about the zombie issue. Some details here: https://github.com/book/System-Command/commit/a8d0b1b44814d929bfc6e4a014aa1b2098509434 I recently found that Git::Repository itself was creating zombies when checking its git binary, which brought back the whole issue. I fixed the client code in Git::Repository to not use the above technique. I might fix the more general zombie issue in System::Command in the future. Show quoted text

> > The most used command in Git::Repository is actually run().

> > I was using run() but it wasn't failing at some point that I thought > it should have but given how confused I had become who knows what that > original problem was. >

By default run() only dies when git exits with statuses 128 and 129. It turns out that this is not enough for all cases, so I added the 'fatal' option: https://metacpan.org/module/Git::Repository::Tutorial#Finely-control-when-run-dies You probably want to use this line: $r = Git::Repository->new( { fatal => "!0" } ); -- BooK

Thu Feb 27 03:11:48 2014 book [...] cpan.org - Correspondence added

On Thu Jul 18 08:26:24 2013, BOOK wrote: Show quoted text

> > The easiest way to create zombies with System::Command since v1.03 is > to do this: > > my $out = System::Command->new( ... )->stdout; > > When the System::Command object gets out of scope (right after we get our hands > on the stdout filehandle of the child process), it is destroyed, and we have > nothing to call waitpid() on. If you look in the history of System::Command, > you'll see I have tried several approaches to deal with that.

That specific issue is actually fixed since 1.106 (published on 2013-10-12). -- BooK

Thu Feb 27 03:12:16 2014 book [...] cpan.org - Status changed from 'open' to 'resolved'