From: Tyler Riddle <t.riddle@shadowcat.co.uk>
Date: Sat, 15 Sep 2012 04:45:43 +0000 (-0700)
Subject: added logging to runloop
X-Git-Tag: v0.003001_01~117
X-Git-Url: http://git.shadowcat.co.uk/gitweb/gitweb.cgi?p=scpubgit%2FObject-Remote.git;a=commitdiff_plain;h=a63cd862186adf328e26dd1294e7a3b1adc42ed6

added logging to runloop
---

diff --git a/lib/Object/Remote/Logging.pm b/lib/Object/Remote/Logging.pm
index 0622648..432b797 100644
--- a/lib/Object/Remote/Logging.pm
+++ b/lib/Object/Remote/Logging.pm
@@ -40,18 +40,22 @@ sub init_logging_stderr {
     our $Log_Output = Object::Remote::LogDestination->new(
         logger => Log::Contextual::SimpleLogger->new({ 
             levels_upto => $Log_Level,
-            coderef => sub { warn "[$hostname $$] ", @_ },
+            coderef => sub { 
+                my @t = localtime();
+                my $time = sprintf("%0.2i:%0.2i:%0.2i", $t[2], $t[1], $t[0]);
+                warn "[$hostname $$] $time ", @_ 
+            },
         })
     );
     $Log_Output->connect($class->arg_router);
 }
 
 sub init_logging_forwarding {
-    my ($class, $remote_parent) = @_; 
-    chomp(my $host = `hostname`);
-    $class->arg_router->description("$$ $host");
-    $class->arg_router->parent_router($remote_parent);
-    $remote_parent->add_child_router($class->arg_router);
+#    my ($class, $remote_parent) = @_; 
+#    chomp(my $host = `hostname`);
+#    $class->arg_router->description("$$ $host");
+#    $class->arg_router->parent_router($remote_parent);
+#    $remote_parent->add_child_router($class->arg_router);
 }
 
 1;
diff --git a/lib/Object/Remote/MiniLoop.pm b/lib/Object/Remote/MiniLoop.pm
index 3951bf9..4531946 100644
--- a/lib/Object/Remote/MiniLoop.pm
+++ b/lib/Object/Remote/MiniLoop.pm
@@ -2,6 +2,7 @@ package Object::Remote::MiniLoop;
 
 use IO::Select;
 use Time::HiRes qw(time);
+use Object::Remote::Logging qw( :log );
 use Moo;
 
 # this is ro because we only actually set it using local in sub run
@@ -18,6 +19,7 @@ has _timers => (is => 'ro', default => sub { [] });
 
 sub pass_watches_to {
   my ($self, $new_loop) = @_;
+  log_debug { "passing watches to new run loop" };
   foreach my $fh ($self->_read_select->handles) {
     $new_loop->watch_io(
       handle => $fh,
@@ -35,6 +37,7 @@ sub pass_watches_to {
 sub watch_io {
   my ($self, %watch) = @_;
   my $fh = $watch{handle};
+  log_debug { my $type = ref($fh); "Adding watch for ref of type '$type'" };
   if (my $cb = $watch{on_read_ready}) {
     $self->_read_select->add($fh);
     $self->_read_watches->{$fh} = $cb;
@@ -49,6 +52,7 @@ sub watch_io {
 sub unwatch_io {
   my ($self, %watch) = @_;
   my $fh = $watch{handle};
+  log_debug { my $type = ref($fh); "Removing watch for ref of type '$type'" };
   if ($watch{on_read_ready}) {
     $self->_read_select->remove($fh);
     delete $self->_read_watches->{$fh};
@@ -70,11 +74,13 @@ sub watch_time {
   my $timers = $self->_timers;
   my $new = [ $at => $code ];
   @{$timers} = sort { $a->[0] <=> $b->[0] } @{$timers}, $new;
+  log_debug { "Created new timer with id of '$new' that expires at '$at'" };
   return "$new";
 }
 
 sub unwatch_time {
   my ($self, $id) = @_;
+  log_debug { "Removing timer with id of '$id'" };
   @$_ = grep !($_ eq $id), @$_ for $self->_timers;
   return;
 }
@@ -83,23 +89,34 @@ sub loop_once {
   my ($self) = @_;
   my $read = $self->_read_watches;
   my $write = $self->_write_watches;
+  my @c = caller;
+  log_trace {  sprintf("Run loop: loop_once() has been invoked by $c[1]:$c[2] with read:%i write:%i", scalar(keys(%$read)), scalar(keys(%$write))) };
   my ($readable, $writeable) = IO::Select->select(
     $self->_read_select, $self->_write_select, undef, 0.5
   );
+  log_debug { 
+      my $readable_count = defined $readable ? scalar(@$readable) : 0;
+      my $writable_count = defined $writeable ? scalar(@$writeable) : 0;
+      "run loop has readable:$readable_count writeable:$writable_count";
+  };
   # I would love to trap errors in the select call but IO::Select doesn't
   # differentiate between an error and a timeout.
   #   -- no, love, mst.
+  log_trace { "Reading from all ready filehandles" };
   foreach my $fh (@$readable) {
     $read->{$fh}() if $read->{$fh};
   }
+  log_trace { "Writing to all ready filehandles" };
   foreach my $fh (@$writeable) {
     $write->{$fh}() if $write->{$fh};
   }
   my $timers = $self->_timers;
   my $now = time();
+  log_trace { "Checking timers" };
   while (@$timers and $timers->[0][0] <= $now) {
     (shift @$timers)->[1]->();
   }
+  log_debug { "Run loop: single loop is completed" };
   return;
 }
 
@@ -110,7 +127,9 @@ sub want_run {
 
 sub run_while_wanted {
   my ($self) = @_;
+  log_debug { "Run loop: run_while_wanted() invoked" };
   $self->loop_once while $self->{want_running};
+  log_debug { "Run loop: run_while_wanted() completed" };
   return;
 }
 
@@ -121,10 +140,12 @@ sub want_stop {
 
 sub run {
   my ($self) = @_;
+  log_info { "Run loop: run() invoked" };
   local $self->{is_running} = 1;
   while ($self->is_running) {
     $self->loop_once;
   }
+  log_info { "Run loop: run() completed" };
   return;
 }