toward timing

Signed-off-by: Jason Etheridge <jason@EquinoxInitiative.org>

diff --git a/Open-ILS/src/perlmods/lib/OpenILS/Application/Circ/Circulate.pm b/Open-ILS/src/perlmods/lib/OpenILS/Application/Circ/Circulate.pm
index d99d525..ab0eeb8 100644 (file)
--- a/Open-ILS/src/perlmods/lib/OpenILS/Application/Circ/Circulate.pm
+++ b/Open-ILS/src/perlmods/lib/OpenILS/Application/Circ/Circulate.pm
@@ -173,6 +173,7 @@ __PACKAGE__->register_method(
 
 
 sub run_method {
+    $logger->info('phasefx: top of run method');
     my( $self, $conn, $auth, $args ) = @_;
     translate_legacy_args($args);
     $args->{override_args} = { all => 1 } unless defined $args->{override_args};
@@ -182,8 +183,10 @@ sub run_method {
     my $circulator = 
         OpenILS::Application::Circ::Circulator->new($auth, %$args);
 
+    $logger->info('phasefx: first bail out') if $circulator->bail_out;
     return circ_events($circulator) if $circulator->bail_out;
 
+    $logger->info('phasefx: determine booking status');
     $circulator->use_booking(determine_booking_status());
 
     # --------------------------------------------------------------------------
@@ -192,6 +195,7 @@ sub run_method {
     # --------------------------------------------------------------------------
 
     if ($circulator->use_booking && (my $bc = $circulator->copy_barcode) && $api !~ /checkout|inspect/) { # do we have a barcode?
+        $logger->info('phasefx: considering booking, top of if');
         my $resources = $circulator->editor->search_booking_resource( { barcode => $bc } ); # any resources by this barcode?
         if (@$resources) { # yes!
 
@@ -233,9 +237,11 @@ sub run_method {
                 $circulator->editor->commit;
                 # Formerly this branch just stopped here. Argh!
                 $conn->respond_complete($success_event);
+                $logger->info('phasefx: return for booking transit');
                 return;
             }
         }
+        $logger->info('phasefx: considering booking, bottom of if');
     }
 
     if ($circulator->use_booking) {
@@ -256,6 +262,7 @@ sub run_method {
     $circulator->mk_env();
     $circulator->noop(1) if $circulator->claims_never_checked_out;
 
+    $logger->info('phasefx: second bail out') if $circulator->bail_out;
     return circ_events($circulator) if $circulator->bail_out;
 
     if( $api =~ /checkout\.permit/ ) {
@@ -289,13 +296,16 @@ sub run_method {
         $circulator->do_reservation_return();
         $circulator->do_checkin() if ($circulator->copy());
     } elsif( $api =~ /checkin/ ) {
+        $logger->info('phasefx: about to do_checkin()');
         $circulator->do_checkin();
+        $logger->info('phasefx: finished with do_checkin()');
 
     } elsif( $api =~ /renew/ ) {
         $circulator->do_renew($api);
     }
 
     if( $circulator->bail_out ) {
+        $logger->info('phasefx: third bail out');
 
         my @ee;
         # make sure no success event accidentally slip in
@@ -308,6 +318,7 @@ sub run_method {
         $logger->info("circulator: bailing out with events: " . (join ", ", @ee));
 
         $circulator->editor->rollback;
+        $logger->info('phasefx: rollback for said bail out');
 
     } else {
 
@@ -316,16 +327,22 @@ sub run_method {
         # actor.last_xact_id.  Perform a no-op update on the patron to
         # force an update to last_xact_id.
         if ($circulator->claims_never_checked_out && $circulator->patron) {
+            $logger->info('phasefx: possible fourth bail out');
             $circulator->editor->update_actor_user(
                 $circulator->editor->retrieve_actor_user($circulator->patron->id))
                 or return $circulator->editor->die_event;
         }
 
+        $logger->info('phasefx: about to commit');
         $circulator->editor->commit;
+        $logger->info('phasefx: finished with commit');
     }
     
+    $logger->info('phasefx: about to respond complete');
     $conn->respond_complete(circ_events($circulator));
+    $logger->info('phasefx: finished with respond complete');
 
+    $logger->info('phasefx: fifth bail out') if $circulator->bail_out;
     return undef if $circulator->bail_out;
 
     $circulator->do_hold_notify($circulator->notify_hold)
@@ -334,6 +351,7 @@ sub run_method {
     $circulator->append_reading_list;
     $circulator->make_trigger_events;
     
+    $logger->info('phasefx: bottom of run method');
     return undef;
 }
 
@@ -2641,9 +2659,11 @@ sub checkin_retarget {
 }
 
 sub do_checkin {
+    $logger->info('phasefx: top of do_checkin');
     my $self = shift;
     $self->log_me("do_checkin()");
 
+    $logger->info('phasefx: do_checkin first bail out') unless $self->copy;
     return $self->bail_on_events(
         OpenILS::Event->new('ASSET_COPY_NOT_FOUND')) 
         unless $self->copy;
@@ -2653,6 +2673,7 @@ sub do_checkin {
 
     # the renew code and mk_env should have already found our circulation object
     unless( $self->circ ) {
+        $logger->info('phasefx: do_checkin: did not already have circ object');
 
         my $circs = $self->editor->search_action_circulation(
             { target_copy => $self->copy->id, checkin_time => undef });
@@ -2698,9 +2719,11 @@ sub do_checkin {
         $latest_inventory->inventory_workstation($self->editor->requestor->wsid);
         $latest_inventory->copy($self->copy->id());
     } else {
+        $logger->info('phasefx: do_checkin: grabbing latest inventory');
         my $alci = $self->editor->search_asset_latest_inventory(
             {copy => $self->copy->id}
         );
+        $logger->info('phasefx: do_checkin: finished grabbing latest inventory');
         $latest_inventory = $alci->[0]
     }
     $self->latest_inventory($latest_inventory);
@@ -2712,10 +2735,12 @@ sub do_checkin {
             $self->hold->pickup_lib($self->circ_lib);
         }
         $self->checkin_flesh_events;
+        $logger->info('phasefx: do_checkin: NO_CHANGE');
         return;
     }
 
     unless( $self->is_renewal ) {
+        $logger->info('phasefx: do_checkin: bail out if not renewal and no COPY_CHECKIN perm');
         return $self->bail_on_events($self->editor->event)
             unless $self->editor->allowed('COPY_CHECKIN');
     }
@@ -2731,19 +2756,27 @@ sub do_checkin {
     $self->check_circ_deposit();
 
     # handle the overridable events 
+    $logger->info('phasefx: do_checkin: handling override_events') unless $self->is_renewal;
     $self->override_events unless $self->is_renewal;
+    $logger->info('phasefx: do_checkin: finished handling override_events') unless $self->is_renewal;
+    $logger->info('phasefx: do_checkin: bail out') if $self->bail_out;
     return if $self->bail_out;
     
     if( $self->copy and !$self->transit ) {
+        $logger->info('phasefx: do_checkin: searching for transit');
         $self->transit(
             $self->editor->search_action_transit_copy(
                 { target_copy => $self->copy->id, dest_recv_time => undef, cancel_time => undef }
             )->[0]
         ); 
+        $logger->info('phasefx: do_checkin: finished searching for transit');
     }
 
     if( $self->circ ) {
+        $logger->info('phasefx: do_checkin: checkin_handle_circ_start');
         $self->checkin_handle_circ_start;
+        $logger->info('phasefx: do_checkin: finished checkin_handle_circ_start');
+        $logger->info('phasefx: do_checkin: bail out') if $self->bail_out;
         return if $self->bail_out;
 
         if (!$dont_change_lost_zero) {
@@ -2768,17 +2801,25 @@ sub do_checkin {
             $self->circ->stop_fines( OILS_STOP_FINES_CLAIMS_NEVERCHECKEDOUT ) if( $self->claims_never_checked_out );
 
             # handle fines for this circ, including overdue gen if needed
+            $logger->info('phasefx: do_checkin: handle_fines');
             $self->handle_fines;
+            $logger->info('phasefx: do_checkin: finished handle_fines');
         }
 
+        $logger->info('phasefx: do_checkin: checkin_handle_circ_finish');
         $self->checkin_handle_circ_finish;
+        $logger->info('phasefx: do_checkin: finished checkin_handle_circ_finish');
+        $logger->info('phasefx: do_checkin: bail out') if $self->bail_out;
         return if $self->bail_out;
         $self->checkin_changed(1);
 
     } elsif( $self->transit ) {
+        $logger->info('phasefx: do_checkin: process_received_transit');
         my $hold_transit = $self->process_received_transit;
+        $logger->info('phasefx: do_checkin: finished process_received_transit');
         $self->checkin_changed(1);
 
+        $logger->info('phasefx: do_checkin: bail_out') if $self->bail_out;
         if( $self->bail_out ) { 
             $self->checkin_flesh_events;
             return;
@@ -2789,6 +2830,7 @@ sub do_checkin {
             my $ev = $self->events;
             $self->events([$e]);
             $self->override_events;
+            $logger->info('phasefx: do_checkin: copy status bail out') if $self->bail_out;
             return if $self->bail_out;
             $self->events($ev);
         }
@@ -2799,11 +2841,14 @@ sub do_checkin {
 
             my $hold;
             if( $hold_transit ) {
+                $logger->info('phasefx: do_checkin: fetching hold transit');
                $hold = $self->editor->retrieve_action_hold_request($hold_transit->hold);
             } else {
+                $logger->info('phasefx: do_checkin: fetching open hold');
                    ($hold) = $U->fetch_open_hold_by_copy($self->copy->id);
             }
 
+            $logger->info('phasefx: do_checkin: setting hold');
             $self->hold($hold);
 
             if( $hold and ( $hold->cancel_time or $hold->fulfillment_time ) ) { # this transited hold was cancelled or filled mid-transit
@@ -2813,16 +2858,19 @@ sub do_checkin {
                 $self->cancelled_hold_transit(1);
                 $self->notify_hold(0); # don't notify for cancelled holds
                 $self->fake_hold_dest(0);
+                $logger->info('phasefx: do_checkin: bail out for cancelled/filled transit hold') if $self->bail_out;
                 return if $self->bail_out;
 
             } elsif ($hold and $hold->hold_type eq 'R') {
 
+                $logger->info('phasefx: do_checkin: R hold');
                 $self->copy->status(OILS_COPY_STATUS_CATALOGING);
                 $self->notify_hold(0); # No need to notify
                 $self->fake_hold_dest(0);
                 $self->noop(1); # Don't try and capture for other holds/transits now
                 $self->update_copy();
                 $hold->fulfillment_time('now');
+                $logger->info('phasefx: do_checkin: possible bail out');
                 $self->bail_on_events($self->editor->event)
                     unless $self->editor->update_action_hold_request($hold);
 
@@ -2833,6 +2881,7 @@ sub do_checkin {
                     $hold->pickup_lib($self->circ_lib);
                 }
                 $self->checkin_flesh_events;
+                $logger->info('phasefx: do_checkin: return for hold transited to correct location');
                 return;
             }
         } 
@@ -2842,6 +2891,7 @@ sub do_checkin {
         $logger->warn("circulator: we have a copy ".$self->copy->barcode.
             " that is in-transit, but there is no transit.. repairing");
         $self->reshelve_copy(1);
+        $logger->info('phasefx: do_checkin: copy in transit bail out') if $self->bail_out;
         return if $self->bail_out;
     }
 
@@ -2849,6 +2899,7 @@ sub do_checkin {
         $self->finish_fines_and_voiding;
         return if $self->bail_out;
         $self->push_events(OpenILS::Event->new('SUCCESS'));
+        $logger->info('phasefx: do_checkin: renewal return');
         return;
     }
 
@@ -2873,6 +2924,7 @@ sub do_checkin {
                         "hold" => $potential_hold,
                         "reservation" => $potential_reservation
                     ));
+                    $logger->info('phasefx: do_checkin: item could fulfill a hold or reservation bailout') if $self->bail_out;
                     return if $self->bail_out;
                 } elsif ($potential_hold) {
                     $needed_for_something =
@@ -2885,6 +2937,7 @@ sub do_checkin {
                 $needed_for_something = $self->attempt_checkin_hold_capture;
             }
         }
+        $logger->info('phasefx: do_checkin: needed for something early bailout');
         return if $self->bail_out;
     
         unless($needed_for_something) {
@@ -2916,6 +2969,7 @@ sub do_checkin {
                 # copy is where it needs to be, either for hold or reshelving
     
                 $self->checkin_handle_precat();
+                $logger->info('phasefx: do_checkin: pre-cat bailout') if $self->bail_out;
                 return if $self->bail_out;
     
             } else {
@@ -2941,6 +2995,7 @@ sub do_checkin {
                     my $bc = $self->copy->barcode;
                     $logger->info("circulator: copy $bc at the wrong location, sending to $circ_lib");
                     $self->checkin_build_copy_transit($circ_lib);
+                    $logger->info('phasefx: do_checkin: copy at wrong location bailout') if $self->bail_out;
                     return if $self->bail_out;
                     $self->push_events(OpenILS::Event->new('ROUTE_ITEM', org => $circ_lib));
                 }
@@ -2978,6 +3033,7 @@ sub do_checkin {
         $self->reshelve_copy unless $needed_for_something;
     }
 
+    $logger->info('phasefx: do_checkin: line 3036 bailout') if $self->bail_out;
     return if $self->bail_out;
 
     unless($self->checkin_changed) {
@@ -3001,6 +3057,7 @@ sub do_checkin {
         $self->editor, $self->patron->id, $self->circ_lib) if $self->patron;
 
     $self->checkin_flesh_events;
+    $logger->info('phasefx: do_checkin: last return');
     return;
 }