From ff3bc7fd6c49545153fefe8ec8984b2dd8a278ab Mon Sep 17 00:00:00 2001 From: Jason Etheridge Date: Wed, 15 Apr 2020 08:16:16 -0400 Subject: [PATCH] toward timing Signed-off-by: Jason Etheridge --- .../lib/OpenILS/Application/Circ/Circulate.pm | 57 ++++++++++++++++++++++ 1 file changed, 57 insertions(+) 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 d99d5259c4..ab0eeb8471 100644 --- 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; } -- 2.11.0