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

data about what event defs / hooks are being processed and when/if they complete or timeout.

git-svn-id: svn://svn.open-ils.org/ILS/trunk@16677 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 d014c99..b12e897 100644 (file)
--- a/Open-ILS/src/perlmods/OpenILS/Application/Trigger.pm
+++ b/Open-ILS/src/perlmods/OpenILS/Application/Trigger.pm
@@ -479,9 +479,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) {
 
@@ -496,8 +508,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;
@@ -526,7 +542,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;
     }
 
@@ -554,7 +570,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;
     }
 
@@ -590,7 +606,7 @@ sub pending_events {
     }
 
     return $editor->search_action_trigger_event(
-        $query, { idlist=> 1, timeout => 7200 }
+        $query, { idlist=> 1, timeout => 7200, substream => 1 }
     );
 }
 __PACKAGE__->register_method(
@@ -608,6 +624,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");
 
@@ -618,7 +641,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; 
@@ -626,7 +649,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) {
@@ -670,6 +693,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(
@@ -678,11 +702,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(
@@ -691,9 +718,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 909d8dc..79af2fb 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;
 
 # DEFAULT values
 
@@ -146,8 +148,21 @@ sub process_hooks {
         $method =~ s/passive/active/ if $config->{active};
         
         my $req = $ses->request($method, $hook, $config->{context_org}, $config->{filter}, $opt_granularity);
-        while (my $resp = $req->recv(timeout => 1800)) {
-            $opt_debug_stdout and 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");
         }
     }
 }
@@ -160,7 +175,7 @@ sub run_pending {
     my $req = $ses->request('open-ils.trigger.event.run_all_pending' => $opt_granularity);
 
     my $check_lockfile = 1;
-    while (my $resp = $req->recv(timeout => 7200)) {
+    while (my $resp = $req->recv(timeout => $req_timeout)) {
         if ($check_lockfile && -e $opt_lockfile) {
             open LF, $opt_lockfile;
             my $contents = <LF>;