Bug 28700 - "Unblessed" method in Object.pm has blessed values for keys in some cases
Summary: "Unblessed" method in Object.pm has blessed values for keys in some cases
Status: RESOLVED DUPLICATE of bug 28692
Alias: None
Product: Koha
Classification: Unclassified
Component: Database (show other bugs)
Version: master
Hardware: All All
: P5 - low major (vote)
Assignee: Peter Vashchuk
QA Contact: Testopia
URL:
Keywords:
: 24182 29192 (view as bug list)
Depends on:
Blocks:
 
Reported: 2021-07-12 07:40 UTC by Peter Vashchuk
Modified: 2022-03-28 08:49 UTC (History)
8 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:


Attachments
Bug 28700 - unblessed in Object.pm has blessed values in some cases (4.35 KB, patch)
2021-07-12 07:46 UTC, Peter Vashchuk
Details | Diff | Splinter Review
Bug 28700: unblessed in Object.pm has blessed values in some cases (4.35 KB, patch)
2021-07-12 12:09 UTC, Peter Vashchuk
Details | Diff | Splinter Review
Bug 28700: unblessed in Object.pm has blessed values in some cases (4.36 KB, patch)
2021-07-13 10:08 UTC, Peter Vashchuk
Details | Diff | Splinter Review
Bug 28700: Get from storage before log actions (930 bytes, patch)
2021-10-12 09:45 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 28700: unblessed in Object.pm has blessed values in some cases (4.09 KB, patch)
2021-10-13 12:25 UTC, Peter Vashchuk
Details | Diff | Splinter Review
Bug 28700: hotfix for scalar in $infos (901 bytes, patch)
2021-10-18 13:53 UTC, Andrii Nugged
Details | Diff | Splinter Review
Bug 28700: Throw exception on dirty columns for unblessed (1.54 KB, patch)
2021-10-26 10:25 UTC, Martin Renvoize
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Peter Vashchuk 2021-07-12 07:40:52 UTC

    
Comment 1 Peter Vashchuk 2021-07-12 07:46:20 UTC Comment hidden (obsolete)
Comment 2 Peter Vashchuk 2021-07-12 12:09:50 UTC Comment hidden (obsolete)
Comment 3 Peter Vashchuk 2021-07-13 10:08:58 UTC
Created attachment 122797 [details] [review]
Bug 28700: unblessed in Object.pm has blessed values in some cases

This "unblessed" sub acts as such: creates a hash from fields prepared
in memory by DBIX::Class. In case when we get data from DB our fields
are filled with scalars and all unblessed hash returned as keys with
scalar values. This is the expected behavior and feature for which
this method was created.

But in some cases, when we modify the DBIX::Class field in Perl code
(and then it get stored into DB), we pass some special objects to
DBIX::Class, not scalars. For example DateTime object. It is stored
in proper form into DB (converted by DBIX::Class to proper text form
with required date format), but still kept in memory for this field
_as object_! And this is the source of the bug: because now when we use
the "unblessed" method, the value for DATE or TIMESTAMP field is
returned for us by DBIX::Class in the same form as we provided it
some lines above in Perl code: i.e. as "DateTime Object".

For example: when the "dateaccessioned" column in the "items" table
is NULL, "dateaccessioned" gets prefilled by this Perl code
(file: KohaCommunity/Koha/Item.pm around line 198):

    unless ( $self->dateaccessioned ) {
        $self->dateaccessioned($today);
    }

    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, "item
           " . Dumper( $self->unblessed ) );
    }

it gets assigned with DateTime object, stored in Perl process in
DBIX::Class as Object, and converted to scalar only when stored to DB,
but, in the same code piece above, when we have
Dumper( $self->unblessed ), it is passed as blessed value for key
"dateaccessioned", so as we see, when we dumping this record just a few
lines below into object_log, the "dateaccessioned" value appears as a
blessed object rather than the standard date/time text scalar we expect
it to be.

This patch adds the ability for the "unblessed" subroutine in the
Object.pm to make scalar results for ref type DateTime.

I have chosen "->stringify" for DateTime because that anyway will
happen if we try to use the DateTime object in any strings,
concatenations, or prints. For now, it returns the iso8601 text date
which has all the needed data saved. It might be different from which
value stored in the end into DB because the DB field might be simpler
(just date), but anyway we _expect_ that unblessed method should give
just scalars as keys/values, or refs to deeper structures like
arrays/hashes but scalars as well, not objects inside
(nothing blessed inside).

I also added a warning for us to have it logged if we have any other
blessed values returned as a key by the unblessed method.

To reproduce:
1) at the items table pick any item you see fit, find the
"dateaccessioned" column of it, and set it NULL.
2) go to your koha and edit that item (doesn't matter what you change
as long as you make some change), save it afterward.
3) check the action_logs table and find there a newly created MODIFY
item row, "info" column of that contains dumped data, find
"dateaccessioned" among that data and notice that it is an object,
optional: check and note about the size of it.
4) apply the patch.
5) repeat steps 1-3, ensure that "dateaccessioned" contains usual
date/time data (iso8601 formatted in our case).
Comment 4 Martin Renvoize 2021-07-15 14:37:38 UTC
This is a bit strange.. the underlying method in DBIx::Class claims to give column data not inflated objects.. https://metacpan.org/pod/DBIx::Class::Row#get_columns

Is this a bug upstream?
Comment 5 Jonathan Druart 2021-08-19 08:56:47 UTC
Actually I am wondering if the proper fix here would not be to ->get_from_storage before the ->unblessed call.
Comment 6 Andrii Nugged 2021-08-19 08:58:49 UTC
will it lead sometimes to +1 SQL request which is not so fast... but this method used intensively all around?
Comment 7 Jonathan Druart 2021-08-19 09:00:35 UTC
*** Bug 24182 has been marked as a duplicate of this bug. ***
Comment 8 Jonathan Druart 2021-08-19 09:15:53 UTC Comment hidden (obsolete)
Comment 9 Jonathan Druart 2021-08-19 09:16:23 UTC
(In reply to Andrew Nugged from comment #6)
> will it lead sometimes to +1 SQL request which is not so fast... but this
> method used intensively all around?

It will do a fetch, but it's what we want I think.

When an object is stored (added or modified) and we want to log what has been modified, I guess we want to log what has been effectively stored in the DB (like we have trigger in some ->store methods, or the default values defined at schema level).
Comment 10 Tomás Cohen Arazi 2021-09-21 13:21:01 UTC
If we do

  $self->attribute( dt_from_string );

the 'attribute' will obviously have a DateTime in it, as Koha::Object-derived objects are just blessed hashrefs. We could be doing any weird stuff on those assignments.

So far we have sticked to the 'know what you're doing' approach, so if you know you don't care about the stored object, just move on; and if you need it, you call ->discard_changes.

I'm inclined to think we should keep it like this, and in this particular case assume there's a bug in Koha::Item->store, which is callig $self->SUPER::store and then tries to use the resulting object without calling ->discard_changes as it should.

I can see reasons to prefer not to call ->discard_changes all the time (in API controllers it is a common mistake not to do it, yielding super weird and hard to debug errors). But the tradeoff tells me it is not worth making it implicit.

That's my honest opinion on the subject.
Comment 11 Jonathan Druart 2021-09-21 15:29:10 UTC
Tomas, which means you agree with comment 5?
Comment 12 Tomás Cohen Arazi 2021-09-21 15:34:09 UTC
(In reply to Jonathan Druart from comment #11)
> Tomas, which means you agree with comment 5?

Yes, but locally. Not implicitly in unblessed.
Comment 13 Jonathan Druart 2021-09-21 15:40:27 UTC Comment hidden (obsolete)
Comment 14 Jonathan Druart 2021-09-21 15:40:49 UTC
(In reply to Tomás Cohen Arazi from comment #12)
> (In reply to Jonathan Druart from comment #11)
> > Tomas, which means you agree with comment 5?
> 
> Yes, but locally. Not implicitly in unblessed.

That's what comment 5 is suggesting :D
Comment 15 Martin Renvoize 2021-09-27 08:21:17 UTC
I think we are perhaps trying to solve two problems here when we should be doing different things in different situations.

I don't think we should implicitly call get_from_storage/discard_changes inside the unblessed method as it has knock-on effects for the object.  For cases where we want the stored object back, including any DB level trigger updates, I think we should call that specifically as suggested by Tomas. So where we're giving API responses, or just prior to calling logaction in many cases.

I do however, think wherever possible 'unblessed' should indeed return a stringified value and not an object.

I think Peters solution is nearly there.. but instead of handling datetimes specifically and throwing errors otherwise, I'd just stringify all values and thus catch whatever we can.

Thus, my proposal would be

for my $k (keys %res) {
  $res{$k} = "$res{$k}";
}
Comment 16 Jonathan Druart 2021-09-28 07:56:10 UTC
(In reply to Martin Renvoize from comment #15)
> Thus, my proposal would be
> 
> for my $k (keys %res) {
>   $res{$k} = "$res{$k}";
> }

What's the cost of that? What's the side-effects (casting float to string for instance)?

I would like to keep a pragmatic and safe approach for backport. If we all agree that the explicit ->discard_changes call is a simple and good idea, let's go with that.
Comment 17 Jonathan Druart 2021-10-12 09:45:13 UTC
Created attachment 126082 [details] [review]
Bug 28700: Get from storage before log actions

To make sure we have logging the values from DB
Comment 18 Jonathan Druart 2021-10-12 09:45:45 UTC
Trying to revive the discussion here. What about this patch?
Comment 19 Peter Vashchuk 2021-10-13 12:25:28 UTC Comment hidden (obsolete)
Comment 20 Jonathan Druart 2021-10-13 13:13:51 UTC
(In reply to Jonathan Druart from comment #18)
> Trying to revive the discussion here. What about this patch?

kidclamp> should we just address this per case? do we need a global solution? i.e. we know if we touch an object variable we can introduce this problem, so we should know to fetch from storage if an unblessed is need
Joubu> kidclamp: do you mean we should call ->get_from_storage->unblessed before we call actionlog? 
Joubu> basically what my patch does but explicitely
kidclamp> yes, asking why we want to build it into logging rather than place responsibility on the caller
Joubu> to not forget occurrences :)
Joubu> we could create a new object instead of modifying the one passed
Comment 21 Andrii Nugged 2021-10-18 10:09:49 UTC
(In reply to Jonathan Druart from comment #17)
> Created attachment 126082 [details] [review] [review]

This is beside main discussion (I still not yet formed up my opinion on this), but to fix last patch bug:

      if ref($infos) !~ /HASH|ARRAY/ && $infos->isa('Koha::Object');

should be:

      if ref($infos) !~ /HASH|ARRAY|^$/ && $infos->isa('Koha::Object');

or (whatever is more elegant):

      if ref($infos) && ref($infos) !~ /HASH|ARRAY/ && $infos->isa('Koha::Object');

this is to prevent to walk to $infos->isa when there is ref "", i.e. scalar in $infos.
Comment 22 Andrii Nugged 2021-10-18 13:53:05 UTC
Created attachment 126437 [details] [review]
Bug 28700: hotfix for scalar in $infos

to test: just creation of new borrowers blocked without this hotfix.
Comment 23 Jonathan Druart 2021-10-19 14:20:09 UTC
We have bug 24190 that will be part of 21.11, and it will store acquisition logs using json.
I think we MUST fix this one before 21.11.00 is released, or it will be a mess in the logs depending on the versions and modules.

If we agree on passing the Koha::Object and doing the job in logaction, I can provide a patch very soon.

Please let me know!
Comment 24 Nick Clemens 2021-10-22 12:14:14 UTC
I still prefer making the code handle the necessary objects in each case.

If we must have a central solution I would side with Martin/Kyle and suggest stringifying each value in the object.

In any case, I agree that we should resolve before release so will SO/QA whichever solution is offered when bug is out of discussion
Comment 25 Tomás Cohen Arazi 2021-10-22 13:23:02 UTC
What about using ->TO_JSON instead of ->unblessed? It is a bit smarter, specially regarding dates.
Comment 26 Andrii Nugged 2021-10-26 05:27:09 UTC
Tomás: switching to JSON will save logs messages ("dumps") well.

JSON in 'action_logs' also ok for me, 

Main "bug" (unexpected behavior) it won't solve but will solve LOGs crazy growth.

I mean - that won't resolve behavior when by design "->unblessed" is expected to return the hash of scalars, and it "sometimes" returns references to objects.

If to solve with fixing "unblessed" behavior I am also as Nick more to "explicit workarounds", as was in 1st patch from Petro - that allows detecting more another wrong (non-scalar) data coming in if some more than DateTime present.
Comment 27 Andrii Nugged 2021-10-26 05:27:39 UTC
Btw, 2 Petro: I found with unblessed another "reference" happens when saving to action_logs: "ref to SCALAR" comes when in timestamp there is = \"current_timestamp" value (slash here means Perl ref, i.e. when DBIX::Class have there subroutine call instead of scalar).
Comment 28 Andrii Nugged 2021-10-26 05:42:03 UTC
Jonathan: 

yours (and my patch over it) solution is separated from Petro's one (so Petro should re-do sending to logs refs/objects instead of concatenated strings), 

but this solution works also in limited scope: only for logging, "unblessed" still behaves sometimes by "bringing non-scalars" for developers in other places, i.e. I'd say "partial solution" (bug still there).

Why I am still hesitating about "get_from_storage" – as it is written in docs:
https://metacpan.org/pod/DBIx::Class::Row#get_from_storage

"This copy can then be used to compare to an existing result object, to determine if any changes have been made in the database since it was created."

that said it fetches copy from storage, "to compare", which means, it even CAN DIFFER from current data precollected in dbic object,

but we are not allowed to "force" "store" by "unblessed": that will be +1 more unexpected behavior... Eh?

And another "con" against "get_from_storage" is that +1 SQL request (productivity POV).
Comment 29 Martin Renvoize 2021-10-26 10:08:11 UTC
I'm coming round to Tomas's thinking.. why not just use TO_JSON...

Let me justify that.. for stringification, TO_JSON already handles the majority of cases.. we look at the column definitions to ascertain booleans, numbers, decimals and dates and then do the right thing to 'stringify' them based on that information.

I find the 'unblessed' method generally a bit strange if I'm honest.. it doesn't return all internal fields in a hash (there might be other local data fields in the objects messages structure for example)... it only deals with database columns.. also TO_JSON doesn't actually return a JSON string.. it returns a hashref which is then turned into a JSON string later... the one caveat here is we have Mojo::JSON based boolean objects instead of true/false strings which we might expect in an 'unblessed' return.
Comment 30 Martin Renvoize 2021-10-26 10:16:20 UTC
OK, New thought... how about we look for dirty columns and throw an exception if unblessed is called when any exist?

That way we're catching cases where such oddities may exist and telling the developer... and it pushes us to be considered in when we call unblessed without calling get_from_storage first.
Comment 31 Martin Renvoize 2021-10-26 10:25:25 UTC
Created attachment 126902 [details] [review]
Bug 28700: Throw exception on dirty columns for unblessed

This patch updates the unblessed method to throw an exception when
called with dirty columns.
Comment 32 Jonathan Druart 2021-10-26 10:29:32 UTC
If we are here to fix the log verbosity I would prefer to not modify ->unblessed behaviour.

If we are here to fix ->unblessed behaviour, then... why do we want to fix it?
Comment 33 Martin Renvoize 2021-10-26 10:31:50 UTC
I should note.. my final patch there is an alternative to all that preceded it.. the idea being that we throw an exception and thus force developers to consider their unblessed uses and call get_from_storage appropriately themselves.

No.. it does NOT fix the specific issue here.. but rather catches it so we can fix it in all the right locations methodically and prevent future occurrences from coming up..

I think this would be very helpful for spotting the exact same case that comes up in API responses as well as logging.. and perhaps some template issues too as we seem to call unblessed a fair bit in controller code (in a lot of cases I think needlessly).

I'd be tempted to push my version for the beginning of next cycle to catch the errant cases it's bound to surface.. and push Peter's this cycle for just this branch as a temporary middle step for the next stable.
Comment 34 Martin Renvoize 2021-10-26 10:38:21 UTC
Also.. when is logaction ever actually passed a Koha::Object as the $infos param... as far as I can tell the call to 'unblessed' is always called before the call to logaction.. thus I'm not sure how Jonathans patch works.. are you also saying lets replace all the existing logaction calls that pass either a Dumped or unblessed Koha::Object in to infos to pass the actually Koha::Object instead?
Comment 35 Jonathan Druart 2021-10-26 11:17:55 UTC
(In reply to Martin Renvoize from comment #34)
> Also.. when is logaction ever actually passed a Koha::Object as the $infos
> param... as far as I can tell the call to 'unblessed' is always called
> before the call to logaction.. thus I'm not sure how Jonathans patch works..
> are you also saying lets replace all the existing logaction calls that pass
> either a Dumped or unblessed Koha::Object in to infos to pass the actually
> Koha::Object instead?

I was suggesting to pass the object, yes.
Comment 36 Jonathan Druart 2021-10-26 11:20:13 UTC
(In reply to Martin Renvoize from comment #31)
> Created attachment 126902 [details] [review] [review]
> Bug 28700: Throw exception on dirty columns for unblessed
> 
> This patch updates the unblessed method to throw an exception when
> called with dirty columns.

I am expecting unblessed to work on an object that is not in storage. I guess this patch will introduce regressions.
Comment 37 Marcel de Rooy 2021-10-26 11:40:18 UTC
(In reply to Jonathan Druart from comment #32)
> If we are here to fix the log verbosity I would prefer to not modify
> ->unblessed behaviour.
> 
> If we are here to fix ->unblessed behaviour, then... why do we want to fix
> it?

Yes, stick to scope ;)
Comment 38 Marcel de Rooy 2021-10-26 11:43:10 UTC
+    $infos = $infos->get_from_storage
+      if ref($infos) !~ /HASH|ARRAY/ && $infos->isa('Koha::Object');

Hmm. Shouldnt we make the caller responsible for whatever he wants to log?
This feels a bit hacky.
Comment 39 Marcel de Rooy 2021-10-26 11:47:11 UTC
(In reply to Jonathan Druart from comment #20)
> 
> kidclamp> should we just address this per case? do we need a global
> solution? i.e. we know if we touch an object variable we can introduce this
> problem, so we should know to fetch from storage if an unblessed is need
> kidclamp> yes, asking why we want to build it into logging rather than place
> responsibility on the caller

I tend to agree here. What is the biggest problem items with datetimes, as referred to in first comment? Others?
Comment 40 Martin Renvoize 2021-10-26 11:57:43 UTC
(In reply to Marcel de Rooy from comment #39)
> (In reply to Jonathan Druart from comment #20)
> > 
> > kidclamp> should we just address this per case? do we need a global
> > solution? i.e. we know if we touch an object variable we can introduce this
> > problem, so we should know to fetch from storage if an unblessed is need
> > kidclamp> yes, asking why we want to build it into logging rather than place
> > responsibility on the caller
> 
> I tend to agree here. What is the biggest problem items with datetimes, as
> referred to in first comment? Others?

That's the entire point of my patch... generally, the expectation of unblessed is that it returns a hash of the object data.. thus catching when that is likely to not be the case and throwing an error to get the developer to check seems like the right thing to do.. 

In short: 

kidclamp> should we just address this per case?

Yes

kidclamp> if we touch an object variable we can introduce this problem, so we should know to fetch from storage if an unblessed is need.

My patch makes that more explicit by throwing an exception when the object has been touched.

Jonathan> I was suggesting to pass the object, yes.

That's a big change requiring all calls to logaction be looked at.. that's kinda the same as my patch.. it also requires all calls to unblessed be looked at and prevents future regressions in calls to unblessed.
Comment 41 Martin Renvoize 2021-10-26 12:02:06 UTC
OK, so logaction is called 203 times across the codebase whilst unblessed is called 639.  So inspecting logaction has that advantage... but I feel like we're likely making mistakes/assumptions in our calls to unblessed allot and this would highlight lots of other errors/issues.
Comment 42 Jonathan Druart 2021-10-26 12:31:15 UTC
Having a Koha::Object sent to logaction would let us flexibility if we want to modify the behaviour later :)
Comment 43 Martin Renvoize 2021-10-26 13:19:38 UTC
OK.. I think for this bug description.. we should either properly unbless everything in the object or throw an exception for cases where unbless is likely to pass back unexpected nested objects.

I think we should move the middle two patches of Jonathans to bug 28692 for handling the logaction case.. in that case I like the idea of passing Koha::Objects wherever we can and handling the storage/stringification/diffing inside that logaction method.  My vote, at the moment, is to use json with utf8 and canonical enabled.. thus sidestepping some of the flaws of unblessed (as TO_JSON handles them).  Longer term, for log size issues I feel like json-patch, json-merge-patch or perhaps our custom json based diff from Koha::Patron store should be used.. but I'm not sure how that looks when output in the log viewer.
Comment 44 Jonathan Druart 2021-11-04 10:26:29 UTC
Regarding the move on bug 28692 and the recent discussions we had, I think we should drop those patches and mark the bug report as invalid.

We should use JSON::to_json for logging objects.
Comment 45 Jonathan Druart 2021-11-04 10:26:51 UTC
*** Bug 29192 has been marked as a duplicate of this bug. ***
Comment 46 Marcel de Rooy 2022-03-28 08:49:17 UTC
We can close this report now.

*** This bug has been marked as a duplicate of bug 28692 ***