Dancer logging stringifies some data
Hi all, I don't have the time to fix this right now, but we had a very interesting issue. I had this line in my code: info "Bidding on auction $id", $bid; That turned out to be a massive bug! $bid is a hashref that gets serialized to JSON. Unfortunately, the act of printing out the data flipped one value from an NV (float) to a PV (string). That caused the JSON serializer render 1.2 as "1.2". Sadly, the system I was sending this data to reported a bizarre "Request throttled" error instead of a JSON validation error. The simple fix was to drop the $bid from the info() and add a test to ensure that I have a NV instead of a PV. If anyone wants to look into this, that would be great. Perhaps adding optional cloning of the data in the logger prior to printing it out? (Optional because it might be expensive) Cheers, Ovid -- Live and work overseas - http://www.overseas-exile.com/ Buy the book - http://www.oreilly.com/catalog/perlhks/ Tech blog - http://blogs.perl.org/users/ovid/ Twitter - http://twitter.com/OvidPerl/
On Thu, Jun 21, 2012 at 7:00 PM, Ovid <curtis_ovid_poe@yahoo.com> wrote:
Hi all,
Hi, :)
I don't have the time to fix this right now, but we had a very interesting issue. I had this line in my code:
info "Bidding on auction $id", $bid;
That turned out to be a massive bug!
$bid is a hashref that gets serialized to JSON. Unfortunately, the act of printing out the data flipped one value from an NV (float) to a PV (string).
My familiarity with Perl internals is *very* limited (i.e., I don't know nothing about it) but I think NV is simply a double, not necessarily a floating point. Am I right ? (not that it matters) Either way, it makes sense it would still stringify it.
That caused the JSON serializer render 1.2 as "1.2". Sadly, the system I was sending this data to reported a bizarre "Request throttled" error instead of a JSON validation error.
Ouch!
The simple fix was to drop the $bid from the info() and add a test to ensure that I have a NV instead of a PV.
Out of interest, how did you perform that test?
If anyone wants to look into this, that would be great. Perhaps adding optional cloning of the data in the logger prior to printing it out? (Optional because it might be expensive)
We can fix this in the format_message part of the abstract logging class. However, loggers are not required to actually make use of format_message. However, since loggers are not required to use it, it means that fixing it there won't necessarily fix it on every logger. We're open for any ideas on how to make it easier in Dancer 2, perhaps by having the format_message come before the log() or after it, instead of simply allowing the logger to use it and opt out of it if they don't want to use it. Either way, this seems like a stability bug and seems pretty important, so I think we should fix it in Dancer 1 and force a value cloning whether people want to or not. Right now it gives the value from the variable by reference, so that explains the problem, because it keeps using by reference onwards 'till the stringification.
From: sawyer x <xsawyerx@gmail.com>
The simple fix was to drop the $bid from the info() and add a test to ensure that I have a NV instead of a PV.
Out of interest, how did you perform that test?
Oh damn. I was afraid someone might ask that. Everyone who cares about testing, please turn away now :) use Devel::Peek 'Dump'; use Capture::Tiny 'capture_stderr'; like capture_stderr { Dump( $price ) } qr/^SV = [IN]V/, 'A valid bid request should have a numeric price'; Reini Urban suggested I use the B module and I might look to see if it's more robust. Cheers, Curtis -- Live and work overseas - http://www.overseas-exile.com/ Buy the book - http://www.oreilly.com/catalog/perlhks/ Tech blog - http://blogs.perl.org/users/ovid/ Twitter - http://twitter.com/OvidPerl/
On Fri, Jun 22, 2012 at 10:18 AM, Ovid <curtis_ovid_poe@yahoo.com> wrote:
From: sawyer x <xsawyerx@gmail.com>
The simple fix was to drop the $bid from the info() and add a test to ensure that I have a NV instead of a PV.
Out of interest, how did you perform that test?
Oh damn. I was afraid someone might ask that. Everyone who cares about testing, please turn away now :)
Actually, there's much to learn about this. As @chromatic showed in his YAPC::NA2012 talk, sometimes the "wrong" solution is indeed the best one.
use Devel::Peek 'Dump'; use Capture::Tiny 'capture_stderr';
like capture_stderr { Dump( $price ) } qr/^SV = [IN]V/, 'A valid bid request should have a numeric price';
I'm going to add such a test to make sure we aren't doing this again.
Reini Urban suggested I use the B module and I might look to see if it's more robust.
If you have a revision for it, I would appreciate it. Thanks.
On Jun 21, 2012, at 9:30 PM, Ovid wrote:
I don't have the time to fix this right now, but we had a very interesting issue. I had this line in my code:
info "Bidding on auction $id", $bid;
That turned out to be a massive bug!
$bid is a hashref that gets serialized to JSON. Unfortunately, the act of printing out the data flipped one value from an NV (float) to a PV (string). That caused the JSON serializer render 1.2 as "1.2".
I too would like to see this work correctly. For now, I simply traverse the entire data structure and multiply each numeric value by 1 to ensure it doesn't get stringified when converted to JSON. -- Puneet Kishor
On Fri, Jun 22, 2012 at 5:06 PM, Mr. Puneet Kishor <punk.kish@gmail.com>wrote:
On Jun 21, 2012, at 9:30 PM, Ovid wrote:
I don't have the time to fix this right now, but we had a very interesting issue. I had this line in my code:
info "Bidding on auction $id", $bid;
That turned out to be a massive bug!
$bid is a hashref that gets serialized to JSON. Unfortunately, the act of printing out the data flipped one value from an NV (float) to a PV (string). That caused the JSON serializer render 1.2 as "1.2".
I too would like to see this work correctly. For now, I simply traverse the entire data structure and multiply each numeric value by 1 to ensure it doesn't get stringified when converted to JSON.
That's not very efficient. You can either do what Ovid did (remove the info() line) or make a local copy of it and sending the local copy to info().
I've been trying to write a test case for this, but have so far failed. I can see that if I print the data, it will change it from NV to PV, but I can't get the abstract class's format_message() method to flip it, nor can I get the Console logger (whether catching the print using Capture::Tiny or simply printing it to screen) to do it either. Could you provide more info? Perhaps a bit more code? So far the following has failed to change it from NV to PV: - calling format_message() directly. - creating a Console logger and printing it inside Capture::Tiny. - creating a Console logger and printing it to screen without capturing. The only way I got it to flip was to simply do "print" manually. On Thu, Jun 21, 2012 at 7:00 PM, Ovid <curtis_ovid_poe@yahoo.com> wrote:
Hi all,
I don't have the time to fix this right now, but we had a very interesting issue. I had this line in my code:
info "Bidding on auction $id", $bid;
That turned out to be a massive bug!
$bid is a hashref that gets serialized to JSON. Unfortunately, the act of printing out the data flipped one value from an NV (float) to a PV (string). That caused the JSON serializer render 1.2 as "1.2". Sadly, the system I was sending this data to reported a bizarre "Request throttled" error instead of a JSON validation error.
The simple fix was to drop the $bid from the info() and add a test to ensure that I have a NV instead of a PV.
If anyone wants to look into this, that would be great. Perhaps adding optional cloning of the data in the logger prior to printing it out? (Optional because it might be expensive)
Cheers, Ovid -- Live and work overseas - http://www.overseas-exile.com/ Buy the book - http://www.oreilly.com/catalog/perlhks/ Tech blog - http://blogs.perl.org/users/ovid/ Twitter - http://twitter.com/OvidPerl/
_______________________________________________ Dancer-users mailing list Dancer-users@perldancer.org http://www.backup-manager.org/cgi-bin/listinfo/dancer-users
On Fri, Jun 22, 2012 at 9:50 PM, sawyer x <xsawyerx@gmail.com> wrote:
I've been trying to write a test case for this, but have so far failed.
Which made me wonder whether the problem is being approached from the wrong side. To make a long story short, I think that there should be a bug filed to the JSON serializer. But I won't spare you the long story :-) When I tried to see what the whole thing is about, I wrote this: use Devel::Peek 'Dump'; my $price = 100.55; Dump($price); print "$price\n"; Dump($price); and obtained this: $ perl test.pl SV = NV(0x81a9038) at 0x817afe0 REFCNT = 1 FLAGS = (PADMY,NOK,pNOK) NV = 100.55 100.55 SV = PVNV(0x816bcd8) at 0x817afe0 REFCNT = 1 FLAGS = (PADMY,NOK,POK,pNOK,pPOK) IV = 0 NV = 100.55 PV = 0x81a0e08 "100.55"\0 CUR = 6 LEN = 36 So it's not a matter of getting a NV turned into a PV, but of getting a NV turned into a NVPV whose NOK flag is still on - i.e. the contents is still "number". If this "evolution" can be obtained even through a single, simple print, it seems to me that Dancer logging has actually nothing to do with it and should not care. On the other hand, I think that the JSON serializer should try better to guess how to cope with these variables, going for the "number" when the contents are actually numbers (i.e. testing the IOK and NOK flags before going for the string). Of course this might be a big mistake from my side... my assumption is that what's actually happening is that a [IN]V is being turned into a PV[IN]V, which might not be the case reported by Ovid. Sorry for the noise in this case! Ciao, Flavio.
On Sat, Jun 23, 2012 at 1:14 PM, Flavio Poletti <polettix@gmail.com> wrote:
On Fri, Jun 22, 2012 at 9:50 PM, sawyer x <xsawyerx@gmail.com> wrote:
I've been trying to write a test case for this, but have so far failed.
Which made me wonder whether the problem is being approached from the wrong side. To make a long story short, I think that there should be a bug filed to the JSON serializer. But I won't spare you the long story :-)
When I tried to see what the whole thing is about, I wrote this:
use Devel::Peek 'Dump';
my $price = 100.55;
Dump($price); print "$price\n"; Dump($price);
That was actually very easy to do. But that's not what I wanted to do. What I tried to do was to get any functionality in the Dancer::Logger to do it. I tried the abstract, and the console (which explicitly prints), but none of them were able to turn the NV to PV in my code. In fact, they had not changed it at all. The returned the same exact results.
So it's not a matter of getting a NV turned into a PV, but of getting a NV turned into a NVPV whose NOK flag is still on - i.e. the contents is still "number".
If this "evolution" can be obtained even through a single, simple print, it seems to me that Dancer logging has actually nothing to do with it and should not care. On the other hand, I think that the JSON serializer should try better to guess how to cope with these variables, going for the "number" when the contents are actually numbers (i.e. testing the IOK and NOK flags before going for the string).
Of course this might be a big mistake from my side... my assumption is that what's actually happening is that a [IN]V is being turned into a PV[IN]V, which might not be the case reported by Ovid. Sorry for the noise in this case!
As usual, you out-researched us all. :)
participants (4)
-
Flavio Poletti -
Mr. Puneet Kishor -
Ovid -
sawyer x