Created attachment 122770 [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).
Created attachment 122776 [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).
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).
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?
Actually I am wondering if the proper fix here would not be to ->get_from_storage before the ->unblessed call.
will it lead sometimes to +1 SQL request which is not so fast... but this method used intensively all around?
*** Bug 24182 has been marked as a duplicate of this bug. ***
(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? I will do a fetch, but it's what we want. 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).
(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).
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.
Tomas, which means you agree with comment 5?
(In reply to Jonathan Druart from comment #11) > Tomas, which means you agree with comment 5? Yes, but locally. Not implicitly in unblessed.
(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 why comment 5 is suggesting :D
(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
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}"; }
(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.
Created attachment 126082 [details] [review] Bug 28700: Get from storage before log actions To make sure we have logging the values from DB
Trying to revive the discussion here. What about this patch?
Created attachment 126181 [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: 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).
(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
(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.
Created attachment 126437 [details] [review] Bug 28700: hotfix for scalar in $infos to test: just creation of new borrowers blocked without this hotfix.
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!
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
What about using ->TO_JSON instead of ->unblessed? It is a bit smarter, specially regarding dates.
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.
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).
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).
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.
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.
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.
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?
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.
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?
(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.
(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.
(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 ;)
+ $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.
(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?
(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.
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.
Having a Koha::Object sent to logaction would let us flexibility if we want to modify the behaviour later :)
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.
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.
*** Bug 29192 has been marked as a duplicate of this bug. ***
We can close this report now. *** This bug has been marked as a duplicate of bug 28692 ***