Bug 28692

Yes, that makes sense. Shouldn't we actually have the Dump call in logaction and pass the Koha::Hold object?

We could have something like
  if ( ref($infos) eq 'Koha::Hold') {
    $infos = Data::Dumper->new([$infos->unblessed], [qw(hold)])->Indent(0)->Sortkeys(1)->Dump;
  }

What do you think?

Don't forget to run the koha-qa.pl script before you submit a patch ;)

Data::Dumper->new([$self->unblessed], [qw(item)])->Indent(0)->Sortkeys(1)->Dump )

Hmm Not really like the looks of this statement personally. Not so intuitive as the easy functional interface print Dumper($a,$b)
Since we use that so often, this might be confusing.

Another thought:
Why not set a BEGIN block in C4/Log with something like:
$Data::Dumper::Indent = 0;
etc

And if you like preferences ;) you might wanna control this value somehow..

Created attachment 122782 [details] [review]
Bug 28692: log without indentation to decrease DB action_log table size

Indentation symbols like spaces and newlines take up a large amount of
extra space. Example: fully indented action_log item MODIFY record
weighs from 1.6 to 370 KB while the version of it without any
indentation takes 1.1 to 46 KB accordingly.

This changes logaction subroutine to perform a special transformation,
if$info came as known object, that adds Indent(0) parameter of
Data::Dumper to output without indentation.

To reproduce for item:
1) edit any item you see fit, save it.
2) check the action_logs table and find there a newly created MODIFY
item row, "info" column of that contains dumped data, see that it has
indentation, optional: check and note about the size of it.
3) apply the patch.
4) edit that item again and save it afterwards.
5) "info" column of the newly created row should contain non-indented
text now. If you did check the size of the previous dump, compare it
with this new one, check the difference it makes.

To reproduce for hold:
1) in syspref set HoldsLog to Log.
1) go to the biblio page and suspend and resume any hold you see fit.
2) check the action_logs table and find there a newly created SUSPEND
item row, "info" column of that contains dumped data, see that it has
indentation, optional: check and note about the size of it.
3) apply the patch.
4) edit that item again and save it afterwards.
5) "info" column of the newly created row should contain non-indented
text now. If you did check the size of the previous dump, compare it
with this new one, check the difference it makes.

Note: Jonathan, Bug 28700 has much bigger impact on logs records size

Interested in this as I recently was looking at a 30GB Koha database where 20GB was in the action_log table alone.

Looks great.

But :
Koha/Item.pm
-          : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, "item " . Dumper( $self->unblessed ) );
+          : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, "item " . $self );

This is a string concatenation, seems wrong.

(In reply to Fridolin Somers from comment #7)
> Looks great.
> 
> But :
> Koha/Item.pm
> -          : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, "item "
> . Dumper( $self->unblessed ) );
> +          : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, "item "
> . $self );
> 
> This is a string concatenation, seems wrong.

Yup, it's a bug. Marking as FQA to get Petro's attention.

Created attachment 125692 [details] [review]
Bug 28692: log without indentation to decrease DB action_log table size

Indentation symbols like spaces and newlines take up a large amount of
extra space. Example: fully indented action_log item MODIFY record
weighs from 1.6 to 370 KB while the version of it without any
indentation takes 1.1 to 46 KB accordingly.

This changes logaction subroutine to perform a special transformation,
if$info came as known object, that adds Indent(0) parameter of
Data::Dumper to output without indentation.

To reproduce for item:
1) edit any item you see fit, save it.
2) check the action_logs table and find there a newly created MODIFY
item row, "info" column of that contains dumped data, see that it has
indentation, optional: check and note about the size of it.
3) apply the patch.
4) edit that item again and save it afterwards.
5) "info" column of the newly created row should contain non-indented
text now. If you did check the size of the previous dump, compare it
with this new one, check the difference it makes.

To reproduce for hold:
1) in syspref set HoldsLog to Log.
1) go to the biblio page and suspend and resume any hold you see fit.
2) check the action_logs table and find there a newly created SUSPEND
item row, "info" column of that contains dumped data, see that it has
indentation, optional: check and note about the size of it.
3) apply the patch.
4) edit that item again and save it afterwards.
5) "info" column of the newly created row should contain non-indented
text now. If you did check the size of the previous dump, compare it
with this new one, check the difference it makes.

(In reply to Marcel de Rooy from comment #3)

Looking again here, thx for responding :)

Will be testing this a bit. But can tell you now that we need tests. Might be adding one, not sure yet.

I tend to think that we should solve this issue and the unblessed-thing on bug 28700 together.

    if ( ref $infos eq 'Koha::Hold' ) {
        $varname = 'hold';
    } elsif ( ref $infos eq 'Koha::Item' ) {
        $varname = 'item';
    }
    if ($varname) {
        $infos = Data::Dumper->new( [ $infos->unblessed ], [$varname] )->Indent(0)->Sortkeys(1)->Dump;
    }

This is a bit ugly :)

The 'infos' parameter of logaction is really inconsistent in general.. I'd love to see it consistently be JSON myself.. as a universally easy thing to encode/decode with handling built-in at the object level for consistent handling of numbers and dates.

I also prefer 'diff' to 'whole object dumps'.. when improving the change log for patron modification I chose to create a json representation of just the changed fields rather than dumping the whole patron object into the logs... having said that.. some of the log output I've since learnt depends on doing diffs at the point of display so need whole object dumps at the moment.

See https://git.koha-community.org/Koha-community/Koha/src/branch/master/Koha/Patron.pm#L307-L348 for the JSON 'changed field' structure we opted for.

and see https://git.koha-community.org/Koha-community/Koha/src/branch/master/koha-tmpl/intranet-tmpl/prog/en/modules/tools/viewlog.tt for the jsdiff based diff we display.

Removing whitespace will confuse that diff display I reckon... certainly worth checking for regressions there.

I think we should grab the more general handling from the middle two patches on bug 28700 for here.

Created attachment 127289 [details] [review]
Bug 28700: Get from storage before log actions

To make sure we have logging the values from DB.
It will reduce DB action_log table size when we log the full object and
it contains DateTime object.

This patch is more or less the same as Petro, but 1. it calls get_from_storage and 2. deals with any Koha::Object we will pass.

There is much more to do for logging correctly, this patch is only impacting calls where Dumper($object->unblessed) were passed to logaction.

We certainly need to improve the whole thing and pass an object from everywhere, deal with logic in logaction (depending on the objects we have), log a pre/post stringified versions of the object in 2 different columns (to allow a nice diff from the UI), and finally stringify using JSON (that is currently done only for acquisition logs and patron modification, which is quite inconsistent). This is definitely for a separate bug report, but I think we should focus on it (as a team) for 22.05.

Created attachment 127446 [details] [review]
Bug 28692: Get from storage before log actions

To make sure we have logging the values from DB.
It will reduce DB action_log table size when we log the full object and
it contains DateTime object.

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Great, this is a good first step and enough at this late stage in the cycle for the next release in my opinion.

I'd have been tempted to drop the 'item' prepension, but that would lead to questions like "Should we run a DB update to fix existing cases"

Signing off.

QA: Looking here

Promising: Undefined subroutine &C4::Log::Dumper called at /usr/share/koha/C4/Log.pm line 81

(In reply to Martin Renvoize from comment #20)
> Great, this is a good first step and enough at this late stage in the cycle
> for the next release in my opinion.
> 
> I'd have been tempted to drop the 'item' prepension, but that would lead to
> questions like "Should we run a DB update to fix existing cases"
> 
> Signing off.

How did you test it? First thing is a crash on missing module..

+        $infos = Dumper( $infos->unblessed );
+
+        if ( $infos->isa('Koha::Item') && $modulename eq 'CATALOGUING' && $actionname eq 'MODIFY' ) {

Ha. If you change the variable to a string, it wont be a Koha::Item anymore ;)
Will fix it.

Koha::Item

Not sure if there was an idea to log the item version before we store (get_from_storage call) but we only save the current stage:

    my $result = $self->SUPER::store;
    if ( $log_action && C4::Context->preference("CataloguingLog") ) {
        $action eq 'create'
          ? logaction( "CATALOGUING", "ADD", $self->itemnumber, "item" )
          : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, $self );
    }

We already super stored. So if we wanted the version without the changes like the BIBLIO BEFORE then we should move the super store here?
In that case I would also add a BEFORE.

-    my $result = $self->SUPER::store;
     if ( $log_action && C4::Context->preference("CataloguingLog") ) {
         $action eq 'create'
           ? logaction( "CATALOGUING", "ADD", $self->itemnumber, "item" )
           : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, $self );
     }
+    my $result = $self->SUPER::store;

Created attachment 127574 [details] [review]
Bug 28692: Get from storage before log actions

To make sure we have logging the values from DB.
It will reduce DB action_log table size when we log the full object and
it contains DateTime object.

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Created attachment 127575 [details] [review]
Bug 28962: (QA follow-up) Add module

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Created attachment 127576 [details] [review]
Bug 28962: (QA follow-up) Sort hash keys of unblessed

Trivial add. Reads much better. And might help future diffs.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Created attachment 127577 [details] [review]
Bug 28962: (QA follow-up) Fix test for objects

Simpler to check the ref instead of isa.
Fix the bug where object is first stringified and then tested for
being a Koha::Item.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Development and testing seems to be done too hastily. Three follow-ups ;)
Comment25 and 26 leaving open.
Note that I didnt have time to add some additional test for logaction. But you are  welcome to still add it, Jonathan.

(In reply to Marcel de Rooy from comment #30)
> Created attachment 127577 [details] [review] [review]
> Bug 28962: (QA follow-up) Fix test for objects
> 
> Simpler to check the ref instead of isa.
> Fix the bug where object is first stringified and then tested for
> being a Koha::Item.
> 
> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

This is not correct, we have modules in Koha:: that are not Koha::Object-based objects.

Created attachment 127630 [details] [review]
Bug 28692: Correctly prefix "item " for Koha::Item MODIFY logs

or the isa won't work

Comments 25 and 26 need more attention, and tests are missing.

Help welcomed.

(In reply to Jonathan Druart from comment #34)
> Comments 25 and 26 need more attention, and tests are missing.
> 
> Help welcomed.

Revisiting it now

Created attachment 127639 [details] [review]
Bug 28692: (QA follow-up) Add module

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Created attachment 127640 [details] [review]
Bug 28692: (QA follow-up) Sort hash keys of unblessed

Trivial add. Reads much better. And might help future diffs.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Created attachment 127642 [details] [review]
Bug 28692: (QA follow-up) Fix test for objects

Fix the bug where object is first stringified and then tested for
being a Koha::Item.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Created attachment 127645 [details] [review]
Bug 28692: Get from storage before log actions

To make sure we have logging the values from DB.
It will reduce DB action_log table size when we log the full object and
it contains DateTime object.

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Created attachment 127646 [details] [review]
Bug 28692: (QA follow-up) Add module

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Created attachment 127647 [details] [review]
Bug 28692: (QA follow-up) Sort hash keys of unblessed

Trivial add. Reads much better. And might help future diffs.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Created attachment 127648 [details] [review]
Bug 28692: (QA follow-up) Fix test for objects

Fix the bug where object is first stringified and then tested for
being a Koha::Item.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Created attachment 127649 [details] [review]
Bug 28692: (follow-up) Add tests

Test plan:
Run t/db_dependent/Log.t

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

(In reply to Jonathan Druart from comment #34)
> Comments 25 and 26 need more attention, and tests are missing.
> 
> Help welcomed.

Added tests.
It seems to me that we should postpone comments 25 and 26. They feel a bit out of scope here too. We want to reduce log size here.

(In reply to Jonathan Druart from comment #32)
> (In reply to Marcel de Rooy from comment #30)
> > Created attachment 127577 [details] [review] [review] [review]
> > Bug 28962: (QA follow-up) Fix test for objects
> > 
> > Simpler to check the ref instead of isa.
> > Fix the bug where object is first stringified and then tested for
> > being a Koha::Item.
> > 
> > Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
> 
> This is not correct, we have modules in Koha:: that are not
> Koha::Object-based objects.

Fixed

Pushed to master for 21.11, thanks to everybody involved!

Doesn't apply to 21.05.x. Please rebase and let me know if you think this should be backported.

(In reply to Kyle M Hall from comment #48)
> Doesn't apply to 21.05.x. Please rebase and let me know if you think this
> should be backported.

It really should have :) My 20.11 logs were growing steadily with these datetime object dumps. The rebase was trivial..

*** Bug 28700 has been marked as a duplicate of this bug. ***