Skip to content
Browse files

Speed up a test by adding an idle event to POE::Wheel::FollowTail.

Rather than wait for several seconds to elapse, tests can set a low
PollInterval and use IdleEvent handlers to tell when it's ready to
move on.

As a proof of concept, this commit also removes about 8 seconds from a
regression test using the new IdleEvent.
  • Loading branch information...
1 parent d30f5b3 commit 65cf8fc77ce18a7d803a70f6fc9dd7a91f687aec @rcaputo committed Jul 11, 2014
Showing with 125 additions and 72 deletions.
  1. +35 −0 lib/POE/Wheel/FollowTail.pm
  2. +90 −72 t/90_regression/whjackson-followtail.t
View
35 lib/POE/Wheel/FollowTail.pm
@@ -27,6 +27,7 @@ sub SELF_UNIQUE_ID () { 8 }
sub SELF_STATE_READ () { 9 }
sub SELF_LAST_STAT () { 10 }
sub SELF_FOLLOW_MODE () { 11 }
+sub SELF_EVENT_IDLE () { 12 }
sub MODE_TIMER () { 0x01 } # Follow on a timer loop.
sub MODE_SELECT () { 0x02 } # Follow via select().
@@ -109,6 +110,7 @@ sub new {
undef, # SELF_STATE_READ
[ (-1) x 8 ], # SELF_LAST_STAT
undef, # SELF_FOLLOW_MODE
+ delete $params{IdleEvent}, # SELF_EVENT_IDLE
], $type;
if (defined $filename) {
@@ -234,6 +236,7 @@ sub _define_select_states {
my $event_input = \$self->[SELF_EVENT_INPUT];
my $event_error = \$self->[SELF_EVENT_ERROR];
my $event_reset = \$self->[SELF_EVENT_RESET];
+ my $event_idle = \$self->[SELF_EVENT_IDLE];
TRACE_POLL and warn "<poll> defining select state";
@@ -279,6 +282,9 @@ sub _define_select_states {
$$event_error and
$k->call($ses, $$event_error, 'read', ($!+0), $!, $unique_id);
}
+ elsif (defined $$event_idle) {
+ $k->call($ses, $$event_idle, $unique_id);
+ }
$k->select_read($$handle => undef);
eval { IO::Handle::clearerr($$handle) }; # could be a globref
@@ -324,6 +330,7 @@ sub _generate_filehandle_timer {
my $event_input = \$self->[SELF_EVENT_INPUT];
my $event_error = \$self->[SELF_EVENT_ERROR];
my $event_reset = \$self->[SELF_EVENT_RESET];
+ my $event_idle = \$self->[SELF_EVENT_IDLE];
$self->[SELF_STATE_READ] = ref($self) . "($unique_id) -> handle timer read";
my $state_read = \$self->[SELF_STATE_READ];
@@ -437,6 +444,9 @@ sub _generate_filehandle_timer {
sysseek($$handle, 0, SEEK_SET);
}
+ else {
+ $k->call($ses, $$event_idle, $unique_id);
+ }
# The file didn't roll. Try again shortly.
@$last_stat = @new_stat;
@@ -461,6 +471,7 @@ sub _generate_filename_timer {
my $event_input = \$self->[SELF_EVENT_INPUT];
my $event_error = \$self->[SELF_EVENT_ERROR];
my $event_reset = \$self->[SELF_EVENT_RESET];
+ my $event_idle = \$self->[SELF_EVENT_IDLE];
$self->[SELF_STATE_READ] = ref($self) . "($unique_id) -> name timer read";
my $state_read = \$self->[SELF_STATE_READ];
@@ -481,6 +492,7 @@ sub _generate_filename_timer {
# Couldn't open yet.
unless ($$handle) {
+ $k->call($ses, $$event_idle, $unique_id) if defined $$event_idle;
$k->delay($$state_read, $poll_interval) if defined $$state_read;
return;
}
@@ -581,6 +593,9 @@ sub _generate_filename_timer {
$k->delay($$state_read, 0) if defined $$state_read;
return;
}
+ else {
+ $k->call($ses, $$event_idle, $unique_id);
+ }
# The file didn't roll. Try again shortly.
@$last_stat = @new_stat;
@@ -614,6 +629,9 @@ sub event {
elsif ($name eq 'ResetEvent') {
$self->[SELF_EVENT_RESET] = $event;
}
+ elsif ($name eq 'IdleEvent') {
+ $self->[SELF_EVENT_IDLE] = $event;
+ }
else {
carp "ignoring unknown FollowTail parameter '$name'";
}
@@ -825,6 +843,15 @@ required, however.
See the L</SYNOPSIS> for an example.
+=head3 IdleEvent
+
+C<IdleEvent> is an optional event. If specified, it will fire
+whenever POE::Wheel::FollowTail checks for activity but sees nothing.
+It was added in POE 1.362 as a way to advance certain test programs
+without needing to wait conservatively large amounts of time.
+
+C<IdleEvent> is described in L</PUBLIC EVENTS>.
+
=head3 InputEvent
The C<InputEvent> parameter is required, and it specifies the event to
@@ -900,6 +927,14 @@ resume watching the file where tell() left off.
POE::Wheel::FollowTail emits a small number of events.
+=head2 IdleEvent
+
+C<IdleEvent> specifies the name of an event to be fired when
+POE::Wheel::FollowTail doesn't detect activity on the watched file.
+
+C<$_[ARG0]> contains the ID of the POE::Wheel::FollowTail object that
+fired the event.
+
=head2 InputEvent
C<InputEvent> sets the name of the event to emit when new data arrives
View
162 t/90_regression/whjackson-followtail.t
@@ -1,9 +1,20 @@
#!/usr/bin/perl
# vim: ts=2 sw=2 filetype=perl expandtab
+# This regression test verifies what happens when the following
+# happens in between two polls of a log file:
+#
+# 1. A log file is rolled by being renamed out of the way.
+# 2. The new log is created by appending to the original file location.
+#
+# The desired result is the first log lines are fetched to completion
+# before the new log is opened. No data is lost in this case.
+
use strict;
use warnings;
+sub POE::Kernel::ASSERT_DEFAULT () { 1 }
+
use Test::More;
use POE qw(Wheel::FollowTail);
@@ -21,32 +32,54 @@ use constant OLD_LOG => 'test_log.1';
}
close $fh;
unlink LOG, OLD_LOG;
- plan tests => 10;
}
-my @expected = (
- [ append_to_log => "a" ],
- [ reset_event => 0 ],
- [ got_log => "a" ],
- [ append_to_log => "b" ],
- [ roll_log => 0 ],
- [ append_to_log => "c" ],
- [ got_log => "b" ],
- [ reset_event => 0 ],
- [ got_log => "c" ],
- [ done => 0 ],
+my @expected_results = (
+ [ got_start_event => 0, sub {
+ $_[HEAP]{wheel} = POE::Wheel::FollowTail->new(
+ InputEvent => 'input_event',
+ ResetEvent => 'reset_event',
+ IdleEvent => 'idle_event',
+ Filename => LOG,
+ PollInterval => 1,
+ );
+ }
+ ],
+ [ got_idle_event => 0, sub { append_to_log("a") } ],
+ [ did_log_append => "a", sub { undef } ],
+ [ got_reset_event => 0, sub { undef } ], # Initial open is a reset.
+ [ got_input_event => "a", sub { undef} ],
+ [ got_idle_event => 0, sub {
+ append_to_log("b");
+ roll_log();
+ append_to_log("c");
+ }
+ ],
+ [ did_log_append => "b", sub { undef } ],
+ [ did_log_roll => 0, sub { undef } ],
+ [ did_log_append => "c", sub { undef } ],
+ [ got_input_event => "b", sub { undef } ],
+ [ got_reset_event => 0, sub { undef } ],
+ [ got_input_event => "c", sub { append_to_log("d") } ],
+ [ did_log_append => "d", sub { undef } ],
+ [ got_input_event => "d", sub { delete $_[HEAP]{wheel} } ],
+ [ got_stop_event => 0, sub {
+ # Clean up test log files, if we can.
+ unlink LOG or die "unlink failed: $!";
+ unlink OLD_LOG or die "unlink failed: $!";
+ }
+ ],
);
+plan tests => scalar @expected_results;
+
POE::Session->create(
inline_states => {
- _start => \&_start_handler,
- append_to_log => \&append_to_log,
- roll_log => \&roll_log,
- done => \&done,
-
- # FollowTail events
- input_event => \&input_handler,
- reset_event => \&reset_handler,
+ _start => \&handle_start_event,
+ _stop => \&handle_stop_event,
+ input_event => \&handle_input_event,
+ reset_event => \&handle_reset_event,
+ idle_event => \&handle_idle_event,
}
);
@@ -57,59 +90,58 @@ exit;
# subs
#
-sub logger {
- my $log_info = [ @_ ];
- my $next = shift @expected;
- is_deeply( $log_info, $next );
- return;
+sub test_event {
+ my ($event, $parameter) = @_;
+ my $expected_result = shift @expected_results;
+ unless (defined $expected_result) {
+ fail("Got an unexpected result ($event, $parameter). Time to bye.");
+ exit;
+ }
+
+ my $next_action = pop @$expected_result;
+
+ note "Testing (@$expected_result)";
+
+ is_deeply( [ $event, $parameter ], $expected_result );
+
+ return $next_action;
+}
+
+sub handle_reset_event {
+ my $next_action = test_event("got_reset_event", 0);
+ goto $next_action;
}
-sub _start_handler {
- my ($kernel, $heap) = @_[KERNEL, HEAP];
-
- $heap->{wheel} = POE::Wheel::FollowTail->new(
- InputEvent => 'input_event',
- ResetEvent => 'reset_event',
- Filename => LOG,
- PollInterval => 4,
- );
-
- #
- # what when arg
- #----------------------------------------------
- # poll log file 1
- $kernel->delay_add('append_to_log', 2, 'a');
- # necessary no-op gap 3
- # poll log file 4
- $kernel->delay_add('append_to_log', 5, 'b');
- $kernel->delay_add('roll_log', 6 );
- $kernel->delay_add('append_to_log', 7, 'c');
- # poll log file 8
- $kernel->delay_add('done', 10 );
+sub handle_idle_event {
+ my $next_action = test_event("got_idle_event", 0);
+ goto $next_action;
+}
- return;
+sub handle_input_event {
+ my $next_action = test_event("got_input_event", $_[ARG0]);
+ goto $next_action;
}
-sub input_handler {
- my ($kernel, $line) = @_[KERNEL, ARG0];
- logger got_log => $line;
- return;
+sub handle_start_event {
+ my $next_action = test_event("got_start_event", 0);
+ goto $next_action;
}
-sub reset_handler {
- logger reset_event => 0;
- return;
+sub handle_stop_event {
+ my $next_action = test_event("got_stop_event", 0);
+ goto $next_action;
}
sub roll_log {
- logger roll_log => 0;
+ test_event did_log_roll => 0;
rename LOG, OLD_LOG or die "rename failed: $!";
return;
}
sub append_to_log {
- my $line = $_[ARG0];
- logger append_to_log => $line;
+ my ($line) = @_;
+
+ test_event did_log_append => $line;
open my $fh, '>>', LOG or die "open failed: $!";
print {$fh} "$line\n";
@@ -118,19 +150,5 @@ sub append_to_log {
return;
}
-sub done {
- my ($kernel, $heap) = @_[KERNEL, HEAP];
-
- logger done => 0;
-
- # cleanup the test log files
- unlink LOG or die "unlink failed: $!";
- unlink OLD_LOG or die "unlink failed: $!";
-
- # delete the wheel so the POE session can end
- delete $heap->{wheel};
-
- return;
-}
1;

0 comments on commit 65cf8fc

Please sign in to comment.
Something went wrong with that request. Please try again.