Bug #57277 for IPC-Run: timeout causes delay with output not captured

Fri May 07 05:16:16 2010 NCLEATON [...] cpan.org - Ticket created

Subject:

timeout causes delay with output not captured

If I run a command that does not exit right away with a timeout and without capturing either stdout or stderr, then IPC::Run appears to wait for the timeout even if the command finishes sooner: # This takes 10 seconds, should only take 1 second run ['perl', '-e', 'sleep 1'], \undef, \*STDOUT, \*STDERR, timeout(10); Tested against 0.89. Capturing either STDOUT or STDERR to a string buffer or replacing the command with one that exits right away eliminates the problem. Nick

Subject:

perlv.txt

Summary of my perl5 (revision 5 version 10 subversion 0) configuration: Platform: osname=linux, osvers=2.6.24-23-server, archname=i486-linux-gnu-thread-multi uname='linux rothera 2.6.24-23-server #1 smp wed apr 1 22:22:14 utc 2009 i686 gnulinux ' config_args='-Dusethreads -Duselargefiles -Dccflags=-DDEBIAN -Dcccdlflags=-fPIC -Darchname=i486-linux-gnu -Dprefix=/usr -Dprivlib=/usr/share/perl/5.10 -Darchlib=/usr/lib/perl/5.10 -Dvendorprefix=/usr -Dvendorlib=/usr/share/perl5 -Dvendorarch=/usr/lib/perl5 -Dsiteprefix=/usr/local -Dsitelib=/usr/local/share/perl/5.10.0 -Dsitearch=/usr/local/lib/perl/5.10.0 -Dman1dir=/usr/share/man/man1 -Dman3dir=/usr/share/man/man3 -Dsiteman1dir=/usr/local/man/man1 -Dsiteman3dir=/usr/local/man/man3 -Dman1ext=1 -Dman3ext=3perl -Dpager=/usr/bin/sensible-pager -Uafs -Ud_csh -Ud_ualarm -Uusesfio -Uusenm -DDEBUGGING=-g -Doptimize=-O2 -Duseshrplib -Dlibperl=libperl.so.5.10.0 -Dd_dosuid -des' hint=recommended, useposix=true, d_sigaction=define useithreads=define, usemultiplicity=define useperlio=define, d_sfio=undef, uselargefiles=define, usesocks=undef use64bitint=undef, use64bitall=undef, uselongdouble=undef usemymalloc=n, bincompat5005=undef Compiler: cc='cc', ccflags ='-D_REENTRANT -D_GNU_SOURCE -DDEBIAN -fno-strict-aliasing -pipe -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64', optimize='-O2 -g', cppflags='-D_REENTRANT -D_GNU_SOURCE -DDEBIAN -fno-strict-aliasing -pipe -I/usr/local/include' ccversion='', gccversion='4.3.2', gccosandvers='' intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234 d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=12 ivtype='long', ivsize=4, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8 alignbytes=4, prototype=define Linker and Libraries: ld='cc', ldflags =' -L/usr/local/lib' libpth=/usr/local/lib /lib /usr/lib /usr/lib64 libs=-lgdbm -lgdbm_compat -ldb -ldl -lm -lpthread -lc -lcrypt perllibs=-ldl -lm -lpthread -lc -lcrypt libc=/lib/libc-2.8.90.so, so=so, useshrplib=true, libperl=libperl.so.5.10.0 gnulibc_version='2.8.90' Dynamic Linking: dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E' cccdlflags='-fPIC', lddlflags='-shared -O2 -g -L/usr/local/lib' Characteristics of this binary (from libperl): Compile-time options: MULTIPLICITY PERL_DONT_CREATE_GVSV PERL_IMPLICIT_CONTEXT PERL_MALLOC_WRAP USE_ITHREADS USE_LARGE_FILES USE_PERLIO USE_REENTRANT_API Built under linux Compiled at Jun 26 2009 19:08:22 @INC: /etc/perl /usr/local/lib/perl/5.10.0 /usr/local/share/perl/5.10.0 /usr/lib/perl5 /usr/share/perl5 /usr/lib/perl/5.10 /usr/share/perl/5.10 /usr/local/lib/site_perl .

Tue May 11 14:23:41 2010 NCLEATON [...] cpan.org - Correspondence added

Subject:

[PATCH] timeout causes delay with output not captured

On Fri May 07 05:16:16 2010, NCLEATON wrote: Show quoted text

> If I run a command that does not exit right away with a timeout and > without capturing either stdout or stderr, then IPC::Run appears to wait > for the timeout even if the command finishes sooner: > > > # This takes 10 seconds, should only take 1 second > run ['perl', '-e', 'sleep 1'], \undef, \*STDOUT, \*STDERR, timeout(10);

Patch attached.

Subject:

IPC-Run-0.89-patch.txt

diff -Nurd a/lib/IPC/Run.pm b/lib/IPC/Run.pm --- a/lib/IPC/Run.pm 2010-04-01 05:30:34.000000000 +0100 +++ b/lib/IPC/Run.pm 2010-05-11 19:11:05.255026523 +0100 @@ -2998,7 +2998,7 @@ ## we have I/O, or are just waiting for children to exit. my $p = $self->pumpable; last unless $p; - if ( $p > 0 && ( ! defined $timeout || $timeout > 0.1 ) ) { + if ( $p != 0 && ( ! defined $timeout || $timeout > 0.1 ) ) { ## No I/O will wake the select loop up, but we have children ## lingering, so we need to poll them with a short timeout. ## Otherwise, assume more input will be coming. diff -Nurd a/t/timeout.t b/t/timeout.t --- a/t/timeout.t 2010-04-01 04:40:08.000000000 +0100 +++ b/t/timeout.t 2010-05-11 19:14:03.155026629 +0100 @@ -20,7 +20,7 @@ } ## Separate from run.t so run.t is not too slow. -use Test::More tests => 25; +use Test::More tests => 26; use IPC::Run qw( harness timeout ); my $h; @@ -85,3 +85,12 @@ my $elapsed = time - $started; $elapsed >= 1 ? ok( 1 ) : is( $elapsed, ">= 1" ); } + +SCOPE: { + $h = harness( [ $^X, '-e', 'sleep 1' ], timeout( 10 ) ); + my $started_at = time; + $h->start; + $h->finish; + my $finished_at = time; + ok( $finished_at-$started_at <= 2, 'not too slow to reap' ); +}

Tue May 11 22:31:07 2010 engstrom+bitcard [...] mtu.net - Correspondence added

From:

engstrom

On Fri May 07 05:16:16 2010, NCLEATON wrote: Show quoted text

> If I run a command that does not exit right away with a timeout and > without capturing either stdout or stderr, then IPC::Run appears to > wait for the timeout even if the command finishes sooner: > > # This takes 10 seconds, should only take 1 second > run ['perl', '-e', 'sleep 1'], \undef, \*STDOUT, \*STDERR, timeout(10);

I can confirm this (pre suggested patch, on Mac OS X 10.6.3, Perl 5.8.9). I also see the same behavior with output sent to a file, as in: run ["perl", "-e", "sleep 2"], \undef, "&>", "/tmp/foo", timeout(10);' However, I've found two workarounds: 1. use an empty string for input: run ["perl", "-e", "sleep 2"], "", "&>", "/tmp/foo", timeout(10);' 2. use a subroutine for output: run ["perl", "-e", "sleep 2"], \undef, "&>", sub {print @_}, timeout(10);' Regarding the suggested patch, I'm not convinced that is the right approach. Yes, it works, but it will cause the _select_loop to _ALWAYS_ use a minimal (sub-second) timeout, if I read the code correctly. I also note that the comments to pumpable indicate that it should sometimes return a value > 0, but the code will never do that. I will defer to those who know the code-base better, as I've only been perusing it for today.

Tue May 11 22:31:09 2010 The RT System itself - Status changed from 'new' to 'open'

Fri May 14 00:58:06 2010 TODDR [...] cpan.org - Correspondence added 120 min

So, The suggested work around just ignores the use of select with a timeout. Looking closer at this, I think the design might be fundamentally wrong for how this works. Looking back in the code, it's been this way since it's inception. I'll have to look at it closer later. I don't have a quick fix at the moment and I agree that the patch isn't really the right one. I will add the patch for the test since This should have been in the test suite from the beginning. Thanks!

Fri May 14 00:58:12 2010 TODDR [...] cpan.org - Given to TODDR

Fri Jul 01 00:30:41 2011 TODDR [...] cpan.org - Correspondence added

The test is now shipped as a TODO.

Fri Jul 01 00:30:45 2011 TODDR [...] cpan.org - Status changed from 'open' to 'stalled'

Tue Jan 10 19:14:24 2012 ribasushi [...] leporine.io - Correspondence added

Any outlook on having this fixed? Cheers!

Tue Jan 10 19:14:25 2012 The RT System itself - Status changed from 'stalled' to 'open'

Mon Jan 16 02:37:19 2012 TODDR [...] cpan.org - Correspondence added

On Tue Jan 10 19:14:24 2012, RIBASUSHI wrote: Show quoted text

> Any outlook on having this fixed? Cheers!

I've put a dev release out with just this one change. Let's see how it performs on all platforms.

Tue Feb 14 04:46:57 2012 ribasushi [...] leporine.io - Correspondence added

On Mon Jan 16 02:37:19 2012, TODDR wrote: Show quoted text

> On Tue Jan 10 19:14:24 2012, RIBASUSHI wrote:

> > Any outlook on having this fixed? Cheers!

> > I've put a dev release out with just this one change. Let's see how it > performs on all platforms.

As per IRC: <ribasushi> toddr: on IPC::Run - you have all green, including a win32 and a cygwin that rurban just sent out like 30 secs ago. The two fails are both from BSD's clock sucking in a VM (reap takes way too long - perhaps up the timer?) <ribasushi> toddr: can haz IPC::Run released proper? :) Reini Urban said he smoked the devrel on everything he had and got all green as well. http://matrix.cpantesters.org/?dist=IPC-Run%200.91_01

Wed Feb 15 00:07:01 2012 TODDR [...] cpan.org - Fixed in 0.91_01 added

Wed Feb 15 00:07:15 2012 TODDR [...] cpan.org - Correspondence added

0.91 released to CPAN

Wed Feb 15 00:07:16 2012 TODDR [...] cpan.org - Status changed from 'open' to 'resolved'

Thu Oct 18 16:23:30 2012 cpanrt [...] edsantiago.com - Correspondence added

On Tue May 11 22:31:07 2010, engstrom wrote: Show quoted text

> I also note that the comments to pumpable indicate that it should > sometimes return a value > 0, but the code will never do that.

See RT#68859 comment 1 (18 Oct 2012) For a different approach that could work better for long timeouts (less polling).

Thu Oct 18 16:23:31 2012 The RT System itself - Status changed from 'resolved' to 'open'

Thu Oct 18 16:25:46 2012 cpanrt [...] edsantiago.com - Correspondence added

Argh. Sorry. RT told me I could reply while leaving the ticket resolved. Let's see if I can force it back.

Mon Oct 22 14:31:34 2012 cpanrt [...] edsantiago.com - Cc ESM added

Fri May 12 08:58:06 2017 TODDR [...] cpan.org - Correspondence added

Ticket migrated to github as https://github.com/toddr/IPC-Run/issues/83

Fri May 12 08:58:07 2017 TODDR [...] cpan.org - Status changed from 'open' to 'resolved'