added a number of info messages to the action/trigger runner and server code. the...

git-svn-id: svn://svn.open-ils.org/ILS/branches/rel_1_6_0@16675 dcc99617-32d9-48b4-a31d-7c20da2025e4

diff --git a/Open-ILS/src/perlmods/OpenILS/Application/Trigger.pm b/Open-ILS/src/perlmods/OpenILS/Application/Trigger.pm
index e430109..c5d38bd 100644 (file)
--- a/Open-ILS/src/perlmods/OpenILS/Application/Trigger.pm
+++ b/Open-ILS/src/perlmods/OpenILS/Application/Trigger.pm
@@ -422,9 +422,21 @@ sub create_batch_events {
 
         $class =~ s/^Fieldmapper:://o;
         $class =~ s/::/_/go;
-
         my $method = 'search_'. $class;
-        my $object_ids = $editor->$method( $filter, {idlist => 1, timeout => 7200} );
+
+        # for cleaner logging
+        my $def_id = $def->id;
+        my $hook = $def->hook;
+
+        $logger->info("trigger: create_batch_events() collecting object IDs for def=$def_id / hook=$hook");
+
+        my $object_ids = $editor->$method( $filter, {idlist => 1, timeout => 10800} );
+
+        if($object_ids) {
+            $logger->info("trigger: create_batch_events() fetched ".scalar(@$object_ids)." object IDs for def=$def_id / hook=$hook");
+        } else {
+            $logger->warn("trigger: create_batch_events() timeout occurred collecting object IDs for def=$def_id / hook=$hook");
+        }
 
         for my $o_id (@$object_ids) {
 
@@ -437,8 +449,12 @@ sub create_batch_events {
 
             $client->respond( $event->id );
         }
+        
+        $logger->info("trigger: create_batch_events() successfully created events for def=$def_id / hook=$hook");
     }
 
+    $logger->info("trigger: create_batch_events() done creating events");
+
     $editor->commit;
 
     return undef;
@@ -467,7 +483,7 @@ sub fire_single_event {
     my $e = OpenILS::Application::Trigger::Event->new($event_id);
 
     if ($e->validate->valid) {
-        $logger->info("Event is valid, reacting...");
+        $logger->info("trigger: Event is valid, reacting...");
         $e->react->cleanup;
     }
 
@@ -495,7 +511,7 @@ sub fire_event_group {
     my $e = OpenILS::Application::Trigger::EventGroup->new(@$events);
 
     if ($e->validate->valid) {
-        $logger->info("Event group is valid, reacting...");
+        $logger->info("trigger: Event group is valid, reacting...");
         $e->react->cleanup;
     }
 
@@ -523,7 +539,7 @@ sub pending_events {
 
     return $editor->search_action_trigger_event(
         [{ state => 'pending', run_time => {'<' => 'now'} }, { order_by => { atev => [ qw/run_time add_time/] } }],
-        { idlist=> 1, timeout => 7200 }
+        { idlist=> 1, timeout => 7200, substream => 1 }
     );
 }
 __PACKAGE__->register_method(
@@ -540,6 +556,13 @@ sub grouped_events {
 
     my %groups = ( '*' => [] );
 
+    if($events) {
+        $logger->info("trigger: grouped_events found ".scalar(@$events)." pending events to process");
+    } else {
+        $logger->warn("trigger: grouped_events timed out loading pending events");
+        return \%groups;
+    }
+
     for my $e_id ( @$events ) {
         $logger->info("trigger: processing event $e_id");
 
@@ -550,7 +573,7 @@ sub grouped_events {
         try {
            $e = OpenILS::Application::Trigger::Event->new($e_id);
         } catch Error with {
-            $logger->error("Event creation failed with ".shift());
+            $logger->error("trigger: Event creation failed with ".shift());
         };
 
         next unless $e; 
@@ -558,7 +581,7 @@ sub grouped_events {
         try {
             $e->build_environment;
         } catch Error with {
-            $logger->error("Event environment building failed with ".shift());
+            $logger->error("trigger: Event environment building failed with ".shift());
         };
 
         if (my $group = $e->event->event_def->group_field) {
@@ -601,6 +624,7 @@ sub run_all_events {
 
     for my $def ( keys %$groups ) {
         if ($def eq '*') {
+            $logger->info("trigger: run_all_events firing un-grouped events");
             for my $event ( @{ $$groups{'*'} } ) {
                 try {
                     $client->respond(
@@ -609,11 +633,14 @@ sub run_all_events {
                             ->run($event)
                     );
                 } catch Error with { 
-                    $logger->error("event firing failed with ".shift());
+                    $logger->error("trigger: event firing failed with ".shift());
                 };
             }
+            $logger->info("trigger: run_all_events completed firing un-grouped events");
+
         } else {
             my $defgroup = $$groups{$def};
+            $logger->info("trigger: run_all_events firing events for grouped event def=$def");
             for my $ident ( keys %$defgroup ) {
                 try {
                     $client->respond(
@@ -622,9 +649,10 @@ sub run_all_events {
                             ->run($$defgroup{$ident})
                     );
                 } catch Error with {
-                    $logger->error("event firing failed with ".shift());
+                    $logger->error("trigger: event firing failed with ".shift());
                 };
             }
+            $logger->info("trigger: run_all_events completed firing events for grouped event def=$def");
         }
     }
                 

diff --git a/Open-ILS/src/support-scripts/action_trigger_runner.pl b/Open-ILS/src/support-scripts/action_trigger_runner.pl
index e1246a2..8e7ac89 100755 (executable)
--- a/Open-ILS/src/support-scripts/action_trigger_runner.pl
+++ b/Open-ILS/src/support-scripts/action_trigger_runner.pl
@@ -19,8 +19,10 @@ use Getopt::Long;
 use OpenSRF::System;
 use OpenSRF::AppSession;
 use OpenSRF::Utils::JSON;
+use OpenSRF::Utils::Logger qw/$logger/;
 use OpenSRF::EX qw(:try);
 use OpenILS::Utils::Fieldmapper;
+my $req_timeout = 10800;
 
 my $opt_lockfile = '/tmp/action-trigger-LOCK';
 my $opt_osrf_config = '/openils/conf/opensrf_core.xml';
@@ -128,10 +130,21 @@ sub process_hooks {
         $method =~ s/passive/active/ if $config->{active};
         
         my $req = $ses->request($method, $hook, $config->{context_org}, $config->{filter});
-        while(my $resp = $req->recv(timeout => 1800)) {
-            if($opt_debug_stdout) {
-                print OpenSRF::Utils::JSON->perl2JSON($resp->content) . "\n";
-            }
+ 
+        my $debug_hook = "'$hook' and filter ".OpenSRF::Utils::JSON->perl2JSON($config->{filter});
+        $logger->info("at_runner: creating events for $debug_hook");
+
+        my @event_ids;
+        while (my $resp = $req->recv(timeout => $req_timeout)) {
+            push(@event_ids, $resp->content);
+        }
+
+        if(@event_ids) {
+            $logger->info("at_runner: created ".scalar(@event_ids)." events for $debug_hook");
+        } elsif($req->complete) {
+            $logger->info("at_runner: no events to create for $debug_hook");
+        } else {
+            $logger->warn("at_runner: timeout occurred during event creation for $debug_hook");
         }
     }
 }
@@ -140,7 +153,7 @@ sub run_pending {
     return unless $opt_run_pending;
     my $ses = OpenSRF::AppSession->create('open-ils.trigger');
     my $req = $ses->request('open-ils.trigger.event.run_all_pending');
-    while(my $resp = $req->recv(timeout => 600)) {
+    while (my $resp = $req->recv(timeout => $req_timeout)) {
         if($opt_debug_stdout) {
             print OpenSRF::Utils::JSON->perl2JSON($resp->content) . "\n";
         }