Bug 18382 - action_logs entry for module HOLDS, action SUSPEND is spammy
Summary: action_logs entry for module HOLDS, action SUSPEND is spammy
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Hold requests (show other bugs)
Version: master
Hardware: All All
: P5 - low enhancement (vote)
Assignee: Kyle M Hall
QA Contact: Marcel de Rooy
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-04-04 14:16 UTC by Barton Chittenden
Modified: 2018-12-03 20:04 UTC (History)
7 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Trivial patch
Bot Control: ---
When did the bot last check this:
Who signed the patch off:
Text to go in the release notes:


Attachments
Sample Action logs entry for suspend. (64.21 KB, text/plain)
2017-04-04 14:16 UTC, Barton Chittenden
Details
Bug 18382 - action_logs entry for module HOLDS, action SUSPEND is spammy (1.09 KB, patch)
2017-06-05 14:49 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 18382: [FOLLOW-UP] Ensure user can still enter an empty date (852 bytes, patch)
2017-10-18 21:42 UTC, Aleisha Amohia
Details | Diff | Splinter Review
Bug 18382 - action_logs entry for module HOLDS, action SUSPEND is spammy (1.14 KB, patch)
2017-10-21 22:31 UTC, Katrin Fischer
Details | Diff | Splinter Review
Bug 18382: [FOLLOW-UP] Ensure user can still enter an empty date (910 bytes, patch)
2017-10-21 22:31 UTC, Katrin Fischer
Details | Diff | Splinter Review
Bug 18382: action_logs entry for module HOLDS, action SUSPEND is spammy (1.32 KB, patch)
2018-03-09 15:07 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 18382: action_logs entry for module HOLDS, action SUSPEND is spammy (1.41 KB, patch)
2018-03-22 08:26 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 18382: (QA follow-up) Replace ->ymd by ->datetime (1.24 KB, patch)
2018-03-22 08:26 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 18382 [QA Followup]: Don't set suspend_until if dt if undefined (831 bytes, patch)
2018-03-27 14:45 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 18382: Add a test (1.18 KB, patch)
2018-03-27 17:10 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 18382 [QA Followup]: Make new unit test pass (1.07 KB, patch)
2018-03-29 12:01 UTC, Kyle M Hall
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
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