Bug 18382

Summary: action_logs entry for module HOLDS, action SUSPEND is spammy
Product: Koha Reporter: Barton Chittenden <barton>
Component: Hold requestsAssignee: Kyle M Hall <kyle>
Status: CLOSED FIXED QA Contact: Marcel de Rooy <m.de.rooy>
Severity: enhancement    
Priority: P5 - low CC: aleisha, gmcharlt, jonathan.druart, katrin.fischer, kyle, m.de.rooy, nick
Version: Main   
Hardware: All   
OS: All   
See Also: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=14642
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=28700
Change sponsored?: --- Patch complexity: Trivial patch
Documentation contact: Documentation submission:
Text to go in the release notes:
Version(s) released in:
Attachments: Sample Action logs entry for suspend.
Bug 18382 - action_logs entry for module HOLDS, action SUSPEND is spammy
Bug 18382: [FOLLOW-UP] Ensure user can still enter an empty date
Bug 18382 - action_logs entry for module HOLDS, action SUSPEND is spammy
Bug 18382: [FOLLOW-UP] Ensure user can still enter an empty date
Bug 18382: action_logs entry for module HOLDS, action SUSPEND is spammy
Bug 18382: action_logs entry for module HOLDS, action SUSPEND is spammy
Bug 18382: (QA follow-up) Replace ->ymd by ->datetime
Bug 18382 [QA Followup]: Don't set suspend_until if dt if undefined
Bug 18382: Add a test
Bug 18382 [QA Followup]: Make new unit test pass

Description Barton Chittenden 2017-04-04 14:16:33 UTC
Created attachment 61842 [details]
Sample Action logs entry for suspend.

When a hold is suspended, 'suspend_until' is represented as a DateTime object, complete with locale. All told, this is about 800 lines of text.

See the attached 'action_logs.out'

To replicate:

To test:
- Enable the HoldsLog syspref
- Add a hold on a record/item
- Click on the <Suspend> button

Check the logs using module 'Holds' and Action 'Suspend'
Comment 1 Aleisha Amohia 2017-04-18 23:57:10 UTC
I am not seeing this error.
When I click Suspend, this is the entry that gets inserted into the action log:

$VAR1 = {'waitingdate' => undef,'itemnumber' => undef,'timestamp' => '2017-04-18 23:54:43','notificationdate' => undef,'priority' => '1','biblionumber' => '21','expirationdate' => undef,'cancellationdate' => undef,'reminderdate' => undef,'found' => undef,'reservedate' => '2017-04-18','suspend_until' => bless( {'locale' => bless( {'default_time_format_length' => 'medium','en_complete_name' => 'English United States','native_territory' => 'United States','default_date_format_length' => 'medium','native_language' => 'English','en_territory' => 'United States','native_complete_name' => 'English United States','en_language' => 'English','id' => 'en_US'}, 'DateTime::Locale::en_US' ),'tz' => bless( {'name' => 'UTC'}, 'DateTime::TimeZone::UTC' ),'utc_rd_days' => 736440,'utc_rd_secs' => 0,'local_rd_secs' => 0,'offset_modifier' => 0,'local_rd_days' => 736440,'rd_nanosecs' => 0,'local_c' => {'year' => 2017,'month' => 4,'day' => 21,'day_of_quarter' => 21,'quarter' => 2,'hour' => 0,'minute' => 0,'day_of_year' => 111,'day_of_week' => 5,'second' => 0},'formatter' => undef,'utc_year' => 2018}, 'DateTime' ),'lowestPriority' => '0','branchcode' => 'CPL','suspend' => 1,'reserve_id' => '232','reservenotes' => '','itemtype' => undef,'borrowernumber' => '51'};

It's a little long, sure, but it doesn't separate for each new line like in your attachment.
Comment 2 Barton Chittenden 2017-04-19 22:55:25 UTC
(In reply to Aleisha Amohia from comment #1)
> I am not seeing this error.
> When I click Suspend, this is the entry that gets inserted into the action
> log:
> 
> $VAR1 = {'waitingdate' => undef,'itemnumber' => undef,'timestamp' =>
> '2017-04-18 23:54:43','notificationdate' => undef,'priority' =>
> '1','biblionumber' => '21','expirationdate' => undef,'cancellationdate' =>
> undef,'reminderdate' => undef,'found' => undef,'reservedate' =>
> '2017-04-18','suspend_until' => bless( {'locale' => bless(
> {'default_time_format_length' => 'medium','en_complete_name' => 'English
> United States','native_territory' => 'United
> States','default_date_format_length' => 'medium','native_language' =>
> 'English','en_territory' => 'United States','native_complete_name' =>
> 'English United States','en_language' => 'English','id' => 'en_US'},
> 'DateTime::Locale::en_US' ),'tz' => bless( {'name' => 'UTC'},
> 'DateTime::TimeZone::UTC' ),'utc_rd_days' => 736440,'utc_rd_secs' =>
> 0,'local_rd_secs' => 0,'offset_modifier' => 0,'local_rd_days' =>
> 736440,'rd_nanosecs' => 0,'local_c' => {'year' => 2017,'month' => 4,'day' =>
> 21,'day_of_quarter' => 21,'quarter' => 2,'hour' => 0,'minute' =>
> 0,'day_of_year' => 111,'day_of_week' => 5,'second' => 0},'formatter' =>
> undef,'utc_year' => 2018}, 'DateTime' ),'lowestPriority' => '0','branchcode'
> => 'CPL','suspend' => 1,'reserve_id' => '232','reservenotes' =>
> '','itemtype' => undef,'borrowernumber' => '51'};
> 
> It's a little long, sure, but it doesn't separate for each new line like in
> your attachment.

My formatting came from the fact that I queried action_logs via the command line, using mysql's '\G' query terminator, which puts in the line breaks. Apparently your 'locale' variable is fairly compact... mine isn't. 

In any case 'suspend_until' is still refers to a datetime object which is dumped in its entirity, that *may* get huge, and none of it is information that the user will need or want.
Comment 3 Katrin Fischer 2017-06-05 10:42:04 UTC
I agree it's a bit much and possibly hard to understand for people writing reports. Could we shorten the information to a normal timestamp like format?
Comment 4 Kyle M Hall 2017-06-05 14:49:22 UTC
Created attachment 63962 [details] [review]
Bug 18382 - action_logs entry for module HOLDS, action SUSPEND is spammy

When a hold is suspended, 'suspend_until' is represented as a DateTime object, complete with locale. All told, this is about 800 lines of text.

Test Plan:
1) Enable the HoldsLog syspref
2) Add a hold on a record/item
3) Suspend the hold with a date to resume
4) Note the massive amount of date in the suspend_until field
5) Apply this patch
6) Suspend another hold with a date to resume
7) Note the log has an acutal date in the suspend_until field

Check the logs using module 'Holds' and Action 'Suspend'
Comment 5 Katrin Fischer 2017-10-15 08:56:39 UTC
With this patch you can no longer suspend without a date set. Internal server error:

Can't call method "ymd" on an undefined value at /home/vagrant/kohaclone/Koha/Hold.pm line 65.
Comment 6 Aleisha Amohia 2017-10-18 21:42:17 UTC
Created attachment 68281 [details] [review]
Bug 18382: [FOLLOW-UP] Ensure user can still enter an empty date

Follow above test plan
Also check that you can suspend with no date
Comment 7 Katrin Fischer 2017-10-21 22:31:44 UTC
Created attachment 68363 [details] [review]
Bug 18382 - action_logs entry for module HOLDS, action SUSPEND is spammy

When a hold is suspended, 'suspend_until' is represented as a DateTime object, complete with locale. All told, this is about 800 lines of text.

Test Plan:
1) Enable the HoldsLog syspref
2) Add a hold on a record/item
3) Suspend the hold with a date to resume
4) Note the massive amount of date in the suspend_until field
5) Apply this patch
6) Suspend another hold with a date to resume
7) Note the log has an acutal date in the suspend_until field

Check the logs using module 'Holds' and Action 'Suspend'

Signed-off-by: Katrin Fischer <katrin.fischer.83@web.de>
Comment 8 Katrin Fischer 2017-10-21 22:31:48 UTC
Created attachment 68364 [details] [review]
Bug 18382: [FOLLOW-UP] Ensure user can still enter an empty date

Follow above test plan
Also check that you can suspend with no date

Signed-off-by: Katrin Fischer <katrin.fischer.83@web.de>
Comment 9 Marcel de Rooy 2017-11-03 09:37:56 UTC
Your solution is not limited to action_logs.
You truncate, so to speak, already at the holds level.
Please add your fix at the hold unblessed level when sending it to the logs.
Squash the patches too.
Thanks.
Comment 10 Kyle M Hall 2018-03-09 15:07:51 UTC
Created attachment 72610 [details] [review]
Bug 18382: action_logs entry for module HOLDS, action SUSPEND is spammy

When a hold is suspended, 'suspend_until' is represented as a DateTime object, complete with locale. All told, this is about 800 lines of text.

Test Plan:
1) Enable the HoldsLog syspref
2) Add a hold on a record/item
3) Suspend the hold with a date to resume
4) Note the massive amount of date in the suspend_until field
5) Apply this patch
6) Suspend another hold with a date to resume
7) Note the log has an acutal date in the suspend_until field

Check the logs using module 'Holds' and Action 'Suspend'

Signed-off-by: Katrin Fischer <katrin.fischer.83@web.de>
Comment 11 Kyle M Hall 2018-03-09 15:08:58 UTC
(In reply to Marcel de Rooy from comment #9)
> Your solution is not limited to action_logs.
> You truncate, so to speak, already at the holds level.
> Please add your fix at the hold unblessed level when sending it to the logs.
> Squash the patches too.
> Thanks.

I'm not sure I understand your request. Can you give me a bit more detail? Thanks!
Comment 12 Marcel de Rooy 2018-03-22 08:26:21 UTC
(In reply to Kyle M Hall from comment #11)
> (In reply to Marcel de Rooy from comment #9)
> > Your solution is not limited to action_logs.
> > You truncate, so to speak, already at the holds level.
> > Please add your fix at the hold unblessed level when sending it to the logs.
> > Squash the patches too.
> > Thanks.
> 
> I'm not sure I understand your request. Can you give me a bit more detail?
> Thanks!

Yes, it was rather cryptic ;)
I overlooked the truncate statement in the start of the sub. So just ignore it.
Comment 13 Marcel de Rooy 2018-03-22 08:26:42 UTC
Created attachment 73149 [details] [review]
Bug 18382: action_logs entry for module HOLDS, action SUSPEND is spammy

When a hold is suspended, 'suspend_until' is represented as a DateTime object, complete with locale. All told, this is about 800 lines of text.

Test Plan:
1) Enable the HoldsLog syspref
2) Add a hold on a record/item
3) Suspend the hold with a date to resume
4) Note the massive amount of date in the suspend_until field
5) Apply this patch
6) Suspend another hold with a date to resume
7) Note the log has an acutal date in the suspend_until field

Check the logs using module 'Holds' and Action 'Suspend'

Signed-off-by: Katrin Fischer <katrin.fischer.83@web.de>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 14 Marcel de Rooy 2018-03-22 08:26:47 UTC
Created attachment 73150 [details] [review]
Bug 18382: (QA follow-up) Replace ->ymd by ->datetime

The first patch makes Hold.t fail on:
not ok 8 - Hold is suspended with a date, truncation takes place automatically
   Failed test 'Hold is suspended with a date, truncation takes place automatically'
   at Hold.t line 94.
          got: '2018-03-22'
     expected: '2018-03-22T00:00:00'

We could remove the midnight time there, but we also could replace ymd by
datetime. The cpan doc tells us:
    Same as $dt->ymd('-') . 'T' . $dt->hms(':')

Test plan:
With this patch, run Hold.t again. It should pass now.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 15 Jonathan Druart 2018-03-26 19:09:45 UTC
The change reads wrong, please adjust.

 94     if ( defined $dt ){
 95         $self->suspend_until( $dt->datetime );
 96     } else {
 97         $self->suspend_until( $dt );
 98     }
Comment 16 Jonathan Druart 2018-03-26 19:11:30 UTC
I think we should clean the existing dirty entries: select from action_logs where suspend_until, dump the structure, modify the date and update it.
Comment 17 Kyle M Hall 2018-03-27 14:00:41 UTC
(In reply to Jonathan Druart from comment #15)
> The change reads wrong, please adjust.
> 
>  94     if ( defined $dt ){
>  95         $self->suspend_until( $dt->datetime );
>  96     } else {
>  97         $self->suspend_until( $dt );
>  98     }

Can you explain what you mean by it "reads wrong"?

Thanks!
Comment 18 Kyle M Hall 2018-03-27 14:45:41 UTC
Created attachment 73317 [details] [review]
Bug 18382 [QA Followup]: Don't set suspend_until if dt if undefined
Comment 19 Jonathan Druart 2018-03-27 17:09:23 UTC
Kyle, I was not expecting your follow-up patch to work, I was expecting that ->suspend_hold would not update suspend_until

What is supposed to do:
  $hold->suspend_hold( $dt );
  $hold->suspend_hold;
?

I would expect suspend_until to be set to undef
Comment 20 Jonathan Druart 2018-03-27 17:10:32 UTC
Created attachment 73343 [details] [review]
Bug 18382: Add a test

This is what I am expecting but I may be wrong.
Comment 21 Kyle M Hall 2018-03-29 12:01:02 UTC
Created attachment 73420 [details] [review]
Bug 18382 [QA Followup]: Make new unit test pass
Comment 22 Jonathan Druart 2018-04-02 21:14:30 UTC
Pushed to master for 18.05, thanks to everybody involved!
Comment 23 Nick Clemens 2018-05-14 14:31:09 UTC
Enhancement, not backporting for 17.11.x