| Subject: | POE::Wheel::Run not deleting stdout file handle on child exit |
I am seeing a problem in POE::Wheel::Run for at least POE versions
0.9989 and 0.38. When using POE::Wheel::Run to spawn an external
command, POE is properly setting up two pipes (using the default 'pipe'
Conduit via POE::Pipe::TwoWay), one for stdout and one for stderr. It
seems that when the child process terminates, the stderr pipe is
selected, it is removed from the POE kernel, and the file handle is
deleted. The stdout pipe is selected, it is removed from the POE
kernel, but the file handle is never deleted. This causes the wheel to
hang around forever (as well as the enclosing session). In a
long-running application, this behavior eventually eats up all the
available file descriptors.
I wrote a test program to illustrate. It simply invokes
[ '/bin/echo', 'hi' ]. When run "normally", the problem is illustrated.
I can "solve" the problem by calling
$kernel->_data_handle_clear_session($session)
from the CloseEvent handler of the wheel. When that internal method is
used, (in the below trace) fileno (6) is removed, removed again, and
deleted (and then a warning is generated that fileno (6) is not
registered with POE::Kernel). The session is then removed and the
program terminates properly. See the attached poe_leak.pl for the
demonstration code. Set $CLEAN_HANDLES appropriately (boolean).
Here is the relevant trace:
<fh> adding fd (6) in mode (1) at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/FileHandles.pm
line 324
<rc> incrementing refcount for session 2 (POE::Session=ARRAY(0x8559a90))
at //ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/Sessions.pm
line 358
<fh> pause test: fileno(6) mode(1) count(0) at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/FileHandles.pm
line 706
<fh> adding fd (7) in mode (0) at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/FileHandles.pm
line 324
<rc> incrementing refcount for session 2 (POE::Session=ARRAY(0x8559a90))
at //ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/Sessions.pm
line 358
...
<rc> +----- GC test for session 2 (POE::Session=ARRAY(0x8559a90))
(POE::Session=ARRAY(0x8559a90)) -----
<rc> | total refcnt : 7
<rc> | event count : 2
<rc> | post count : 2
<rc> | child sessions: 0
<rc> | handles in use: 2
<rc> | aliases in use: 0
<rc> | extra refs : 0
<rc> | pid count : 1
<rc> +---------------------------------------------------
...
<fh> decrementing event count in mode (0) for fileno (7) from count (1)
at //ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/FileHandles.pm
line 195
<ev> dispatching event 7 ``POE::Wheel::Run(1) -> select stderr'' to
session 2 (POE::Session=ARRAY(0x8559a90)) at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Kernel.pm line 972
2 -> POE::Wheel::Run(1) -> select stderr (from
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/FileHandles.pm at
254)
2 -> error_event (from
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Wheel/Run.pm at 776)
<fh> removing handle (GLOB(0x84c52d8)) fileno (7) mode (0) at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/FileHandles.pm
line 528
<fh> deleting handle (GLOB(0x84c52d8)) fileno (7) entirely at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/FileHandles.pm
line 609
<rc> decrementing refcount for session 2 (POE::Session=ARRAY(0x8559a90))
at //ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/Sessions.pm
line 331
<ev> event 7 ``POE::Wheel::Run(1) -> select stderr'' returns (undef)
<rc> +----- GC test for session 2 (POE::Session=ARRAY(0x8559a90))
(POE::Session=ARRAY(0x8559a90)) -----
<rc> | total refcnt : 4
<rc> | event count : 1
<rc> | post count : 1
<rc> | child sessions: 0
<rc> | handles in use: 1
<rc> | aliases in use: 0
<rc> | extra refs : 0
<rc> | pid count : 1
<rc> +---------------------------------------------------
...
<fh> decrementing event count in mode (0) for fileno (6) from count (1)
at //ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/FileHandles.pm
line 195
<ev> dispatching event 8 ``POE::Wheel::Run(1) -> select stdout'' to
session 2 (POE::Session=ARRAY(0x8559a90)) at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Kernel.pm line 972
2 -> POE::Wheel::Run(1) -> select stdout (from
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/FileHandles.pm at
254)
2 -> error_event (from
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Wheel/Run.pm at 676)
2 -> task_done (from
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Wheel/Run.pm at 681)
<rc> decrementing refcount for session 2 (POE::Session=ARRAY(0x8559a90))
at //ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/Sessions.pm
line 331
<rc> decrementing refcount for session 2 (POE::Session=ARRAY(0x8559a90))
at //ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/Sessions.pm
line 331
<fh> removing handle (GLOB(0x81577d4)) fileno (6) mode (0) at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/FileHandles.pm
line 528
<ev> event 8 ``POE::Wheel::Run(1) -> select stdout'' returns (undef)
<rc> +----- GC test for session 2 (POE::Session=ARRAY(0x8559a90))
(POE::Session=ARRAY(0x8559a90)) -----
<rc> | total refcnt : 2
<rc> | event count : 0
<rc> | post count : 0
<rc> | child sessions: 0
<rc> | handles in use: 1
<rc> | aliases in use: 0
<rc> | extra refs : 0
<rc> | pid count : 1
<rc> +---------------------------------------------------
...
<sg> POE::Kernel detected SIGCHLD (pid=2711; exit=0) at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/Signals.pm line 493
<ev> enqueued event 9 ``sig_child'' from session
piias1358-46b0a87000000a96 (POE::Kernel=ARRAY(0x8342170)) to session 2
(POE::Session=ARRAY(0x8559a90)) at
1185982577.61384 at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/Events.pm
line 73
...
<ev> Dispatching event 9 ``sig_child'' (CHLD 2711 0) from session
piias1358-46b0a87000000a96 (POE::Kernel=ARRAY(0x8342170)) to session 2
(POE::Session=ARRAY(0x8559a90)) at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Kernel.pm line 846
<ev> dispatching event 9 ``sig_child'' to session 2
(POE::Session=ARRAY(0x8559a90)) at
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Kernel.pm line 972
2 -> sig_child (from
//ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Resource/Signals.pm at 506)
<ev> event 9 ``sig_child'' returns (undef)
...
<rc> +----- GC test for session 2 (POE::Session=ARRAY(0x8559a90))
(POE::Session=ARRAY(0x8559a90)) -----
<rc> | total refcnt : 1
<rc> | event count : 0
<rc> | post count : 0
<rc> | child sessions: 0
<rc> | handles in use: 1
<rc> | aliases in use: 0
<rc> | extra refs : 0
<rc> | pid count : 0
<rc> +---------------------------------------------------
...
<rc> ,----- Kernel Activity -----
<rc> | Events : 1
<rc> | Files : 1
<rc> | Extra : 0
<rc> | Procs :
<rc> `---------------------------
<rc> ... at //ms/dist/perl5/PROJ/POE/0.9989/lib/perl5/POE/Kernel.pm line 596
<ev> Kernel::run() iterating. now(1.6166) timeout(28.9307) then(30.5473)
<fh> ,----- SELECT BITS IN -----
<fh> | READ : 00000000
<fh> | WRITE : 00000000
<fh> | EXPEDITE: 00000000
<fh> `--------------------------
...
| Subject: | poe_leak.pl |
#!/ms/dist/perl5/bin/perl5.8
use strict;
use warnings;
use MSDW::Version
'POE' => '0.9989',
# 'POE' => '0.38',
;
use vars qw(
$CLEAN_HANDLES
$DELAY
$TIMEOUT
$VERBOSE
);
sub POE::Kernel::TRACE_DEFAULT () { 1 }
sub POE::Kernel::TRACE_DESTROY () { 1 }
sub POE::Kernel::TRACE_EVENTS () { 1 }
sub POE::Kernel::TRACE_FILES () { 1 }
sub POE::Kernel::TRACE_PROFILE () { 1 }
sub POE::Kernel::TRACE_REFCNT () { 1 }
sub POE::Kernel::TRACE_RETVALS () { 1 }
sub POE::Kernel::TRACE_SESSIONS () { 1 }
sub POE::Kernel::TRACE_SIGNALS () { 1 }
sub POE::Kernel::ASSERT_EVENTS () { 1 }
sub POE::Kernel::ASSERT_FILES () { 1 }
sub POE::Kernel::CATCH_EXCEPTIONS () { 1 }
use POE qw(
Wheel::Run
Filter::Reference
Filter::Line
);
sub log_it {
my $mesg = shift;
my $retval = print STDOUT ($mesg);
return($retval);
};
{
$CLEAN_HANDLES = 1;
$DELAY = 5;
$TIMEOUT = 30;
$VERBOSE = 5;
my $session = POE::Session->create(
'inline_states' => {
'_start' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $session_id = $session->ID();
($VERBOSE > 2)
&& log_it(
"$alias: do_system_session: started session: '$session_id'"
. "\n"
);
$kernel->yield('next_task');
},
'_stop' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $session_id = $session->ID();
($VERBOSE > 2)
&& log_it(
"${alias}: do_system_session: stopped session: "
. "'$session_id'\n"
);
},
'_child' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $session_id = $session->ID();
($VERBOSE > 2)
&& log_it(
"${alias}: do_system_session: sigchld session: "
. "'$session_id'\n"
);
},
'_parent' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $session_id = $session->ID();
($VERBOSE > 2)
&& log_it(
"${alias}: do_system_session: child session '$session_id' "
. "has new parent\n"
);
},
'_default' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $session_id = $session->ID();
($VERBOSE > 2)
&& log_it(
"${alias}: do_system_session: default caught an unhandled "
. "'$_[ARG0]' event. These '$_[ARG1]' parameters were "
. "sent. session: '$session_id'\n"
);
},
'sig_child' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $session_id = $session->ID();
my $pid = $_[ARG1];
my $rc = $_[ARG2];
my $id = $heap->{'ids'}{$pid} || "";
($VERBOSE > 3)
&& log_it(
"sig_child(): session = $session_id, wheel = $id, entered "
. "sig_child, pid = $pid, rc = $rc, alias = $alias\n"
);
# child death signals are issued by the OS and sent to all
# sessions; we want to handle only our own children
if ($id) {
($POE::VERSION >= 0.20)
&& $kernel->sig_handled();
my %args = ('id' => $id, 'rc' => $rc);
if ($heap->{'closed'}{$id}) {
delete($heap->{'ids'}{$pid});
delete($heap->{'pids'}{$id});
}
($VERBOSE > 2)
&& log_it(
"sig_child(): session = $session_id, wheel = $id, "
. "pid = $pid, rc = $rc\n"
);
}
},
'_kill' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $session_id = $session->ID();
($VERBOSE > 2)
&& log_it(
"${alias}: do_system_session: _kill timeout: '$TIMEOUT' "
. "session: '$session_id'\n"
);
ID:
foreach my $id (keys(%{ $heap->{'dss_task'} })) {
$heap->{'dss_task'}{$id}->kill(9);
}
},
'next_task' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $session_id = $session->ID();
($VERBOSE > 2)
&& log_it(
"${alias}: do_system_session: next_task session: "
. "'$session_id'\n"
);
$heap->{'task'} = POE::Wheel::Run->new(
'Program' => [ '/bin/echo', 'hi' ],
'CloseEvent' => 'task_done',
'StdoutEvent' => 'task_result',
'StderrEvent' => 'task_debug',
'StdinEvent' => 'task_debug',
'ErrorEvent' => 'error_event',
'StdoutFilter' => POE::Filter::Line->new(),
# 'Conduit' => 'socketpair',
);
$heap->{'task'}
|| die("$0: can't POE::Wheel::Run->new");
my $pid = $heap->{'task'}->PID();
($VERBOSE > 3)
&& log_it(
"$alias: do_system_session: successfully started task "
. "pid: '$pid' in session: '$session_id'\n"
);
$kernel->delay_set('_kill', $TIMEOUT);
$kernel->sig_child($pid, 'sig_child');
my $id = $heap->{'task'}->ID();
$heap->{'pids'}{$id} = $pid;
$heap->{'ids'}{$pid} = $id;
$heap->{'dss_task'}{$id} = $heap->{'task'};
$heap->{'pid_to_wheel'}{$pid} = $heap->{'task'};
$heap->{'id_to_wheel'}{$id} = $heap->{'task'};
},
'task_result' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $txt = $_[ARG0];
my $wheel = $_[ARG1];
my $session_id = $session->ID();
log_it(
"$alias: txt: '$txt', wheel: '$wheel', "
. "session: '$session_id' stdout\n"
);
},
'task_done' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $wheel = $_[ARG0];
my $session_id = $session->ID();
$kernel->delay('_kill');
log_it(
"$alias: wheel: '$wheel' session: '$session_id' has finished\n"
);
my $wheel_run = $heap->{'task'};
$heap->{'closed'}{$wheel} = 1;
$heap->{'task'} = 2;
$wheel_run->kill();
($CLEAN_HANDLES)
&& $kernel->_data_handle_clear_session($session);
},
'task_debug' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $op = $_[ARG0];
my $errno = $_[ARG1];
my $error = $_[ARG2];
my $wheel = $_[ARG3];
my $fh = $_[ARG4];
my $session_id = $session->ID();
($VERBOSE > 3)
&& log_it(
"$alias: error op: '$op', errno: '$errno', error: "
. "'error', wheel: '$wheel', fh: '$fh' stderr "
. "session: '$session_id'\n"
);
},
'error_event' => sub {
my $kernel = $_[KERNEL];
my $heap = $_[HEAP];
my $session = $_[SESSION];
my $alias = $heap->{'alias'};
my $op = $_[ARG0];
my $errno = $_[ARG1];
my $error = $_[ARG2];
my $wheel = $_[ARG3];
my $fh = $_[ARG4];
my $session_id = $session->ID();
if ( ($op eq 'read') && ($errno eq '0') && ($error eq '') ) {
# POE network components seem to emit read "errors" at shutdown
} else {
log_it(
"$alias: error op: '$op', errno: '$errno', error: '$error', "
. "wheel: '$wheel', fh: '$fh', session: '$session_id'\n"
);
$heap->{'txt'}{'out'} = [
"failed: $alias: error op: '$op', errno: '$errno', error: "
. "'$error', wheel: '$wheel', fh: '$fh' error event "
. "session: '$session_id'"
];
}
},
},
'heap' => {
'alias' => "do_system_session",
},
'options' => {
'trace' => ($VERBOSE > 3) ? 1 : 0,
'debug' => ($VERBOSE > 1) ? 1 : 0,
},
);
POE::Kernel->run();
log_it("Program ended.\n");
exit(0);
}