Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

Show original stacktraces for rethrown exceptions #438

Open
wants to merge 4 commits into from

4 participants

@nanto

It's good if Plack::Middleware::StackTrace can handle stacktraces for rethrown exceptions as developers expect.

This is a successor of https://github.com/plack/Plack/compare/original-stacktrace reducing "false cache hit".

doy and others added some commits
@doy doy try to get a more helpful stacktrace even when exceptions are rethrown
this happens frequently with StackTrace + HTTPExceptions, among other
things
7ed1202
@nanto nanto Keep original stacktaraces only when the key is the same as the last …
…key.

To determine if the exception is rethrown, we just compare it to the last
thrown exception. This way covers most rethrow usages and reduces false
cache hits.
78d5692
@nanto nanto Show stacktraces if it is surely for the last thrown exception. 21b86d6
@coveralls

Coverage Status

Coverage decreased (-0.05%) when pulling 21b86d6 on nanto:original-stacktrace-retry into 7dafe51 on plack:master.

@miyagawa

This looks too complicated to fit in one line. Could we extract it out as a method or function to be more maintainable?

@miyagawa
Owner

@doy thoughts?

@coveralls

Coverage Status

Coverage decreased (-0.02%) when pulling a7a3463 on nanto:original-stacktrace-retry into 7dafe51 on plack:master.

@doy
Owner

I feel like there was a reason I didn't merge this originally, let me see if I can remember what it was.

@doy
Owner

Yeah:

09:47 < doy> miyagawa: what are your thoughts on https://github.com/plack/Plack/commit/8b9811214475cd1df75e8c3fe87ee294ca5fa209
09:48 < doy> it's not great, but i think it'll probably get things right more often than it does now at least?
09:48 < miyagawa> it looks good, but i am not sure what problem this solves?
09:49 < doy> any time you have something that catches and rethrows an exception, stacktrace ends up giving you the stack trace from the rethrow point
09:49 < doy> which is almost always fairly useless
09:49 < miyagawa> yeah
09:49 < miyagawa> i think there was a discussion/pull request like that a year ago
09:49 < doy> so this tries to suppress that
09:49 < miyagawa> i think it was with/from theory 
09:50 < miyagawa> and i guess the patch was similar but i don't remember very well
09:50 < doy> the only issue is that it'll give you the wrong result if you throw an error and catch and handle it, and then throw the same error later and don't catch it
09:50 < miyagawa> right.
09:51 < doy> but i think that's fairly uncommon, and right now it's giving the wrong result basically all the time in some circumstances (for instance, if you regularly use Plack::Middleware::HTTPExceptions)
09:51 < miyagawa> https://github.com/plack/Plack/issues/169
09:51 < doy> yeah, the issue is that there's no way to track rethrowing
09:52 < miyagawa> https://github.com/plack/Plack/issues/134
09:52 < miyagawa> guess the code with theory was on the mailing list then? I don't remember
09:52 < miyagawa> there were some attempts to cache the last caught errors etc
09:53 < miyagawa> https://github.com/plack/Plack/pull/145
09:53 < miyagawa> ah, i think the patch was to support calling stacktrace *from* the exception 
09:54 < doy> yeah, txn_do is the context where i first ran into this problem
09:54 < miyagawa> with duck typing
09:54 < miyagawa> i think at that time we couldn't agree with and told theory to implement his own stacktrace middleware that does what he wants
09:55 < miyagawa> 2 years ago, so it's kind of vague :)
09:56 < doy> yeah, that's an alternate solution to the problem, but requires that you use exception objects everywhere
09:56 < doy> which isn't always under your control
09:56 < miyagawa> yeah
09:57 < miyagawa> not require though, I guess the idea is that you can optionally rethrow with rethrowable classes with stacktrace support
09:57 < miyagawa> I'm worried about the wrong information this could give 
09:58 < miyagawa> I understand that it would probably be rare but it still doesn't feel completely right.
09:59 < miyagawa> is there a reason to have a hash rather than just tracking the previous exception thrown?
10:00 < doy> exception handlers might do something that throws and catches an exception
10:00 < doy> before rethrowing
10:00 < doy> try { ... } catch { eval { close $fh }; die $@ }
10:00 < doy> or something
10:01 < doy> that's not a very reasonable example, but
10:01 < miyagawa> isn't that highly discouraged?
10:01 < doy> throwing exceptions from destructors is highly discouraged
10:02 < doy> from things you do in exception handlers, i don't think it is
10:02 < doy> i don't see why it would be anyway
10:02 < doy> a more common example actually would be something like rollbacks in a db transaction
10:02 < doy> which might also throw
10:02 < doy> but you don't want that to override the original error
10:02 < doy> or something
10:02 < doy> shrug
10:03 < doy> it's a bit of a judgement call i guess
10:03 < miyagawa> yeah
10:03 < doy> not entirely sure which version would give fewer incorrect results
10:04 < miyagawa> A/B testing!
10:04 < doy> (:
10:05 < miyagawa> iirc what i was trying to wish was a XS/perl CORE stuff to  get stacktrace out of $@
10:05 < miyagawa> without that ->trace convention 
10:06 < miyagawa> also ...
10:07 < miyagawa> i don't remember why it's not checking $^S
10:07 < miyagawa> i think you can only accumulate to the cache if $^S is set 
10:07 < miyagawa> or something like that?
10:07 < haarg> when would $^S not be set for this case?
10:08 < miyagawa> oh shit, it's always in eval anyway?
10:08 < miyagawa> that's true heh
10:08 < haarg> yeah
10:09 < doy> yeah, $^S is unfortunately basically always useless
10:12 < miyagawa> right. 
10:12 < doy> and while $@ tracking its own stacktrace would be great, it's also not going to be possible without actual core changes, which means it'll only work on like 5.20+ if that
10:13 < miyagawa> yeah
10:17 < miyagawa> python has a 3-arg raise
10:17 < miyagawa> that can attach  the trace information
10:18 < miyagawa> and zero-arg raise, which does that by default in except clause
10:19 < doy> yup
10:19 < doy> perl's exception handling is pretty awflu
10:21 < Trelane> So any solutions?
10:21 < Trelane> We've got the same problem in our app
10:22 < Trelane> if a non-exception object is thrown (e.g. third party cpan lib) we lose our stacktrace
10:24 < Trelane> Ideally I'd like to be able to create a Devel::StrackTrace with the stacktrace from $@
10:24 < miyagawa> well that isn't what we're trying to address 
10:24 < doy> no, it is
10:25 < Trelane> (we lose the stacktrace when we re-throw it)
10:25 < miyagawa> is it?
10:25 < miyagawa> yeah
10:25 < miyagawa> if so then yes
10:26 < miyagawa> theory's patch 2 y ago was to add a convention in $@ to access trace via ->trace method
10:26 < doy> this would be doable if perl had a way to attach data to scalars that didn't disappear on copy
10:27 < doy> we could stick some magic on $@ in __DIE__, but that would break if you used something like Try::Tiny
10:27 < doy> which copies $@ around to avoid messing with it
10:28 < miyagawa> https://github.com/plack/Plack/commit/b1546d53ffc83aa2c2d45f4916e313a599055fd2
10:30 < doy> yeah, i don't think the ->trace thing is a good fix just because so many of these problems come from code outside of your control
10:30 < doy> and outside of the context of plack in general

The "only track the previous exception" was my original attempt, but would lead to false positives in some cases. Anything that works along these lines though still does have the potentially to give actually incorrect information, as opposed to the current situation where the information is just useless rather than actively misleading. I don't think that opening up the possibility of providing actively misleading information is something we want to do.

@nanto nanto commented on the diff
lib/Plack/Middleware/StackTrace.pm
@@ -55,6 +63,15 @@ sub call {
return $res;
}
+sub should_show_trace {
+ my ($self, $err, $key, $res) = @_;
+ if ($err) {
+ return _make_key($err) eq $key;
@nanto
nanto added a note

I think confirming the key just before showing the trace prevents false positives including one that happens currently (e.g. $twice_died_app in t/Plack-Middleware/stacktrace/sigdie.t). What situations do you think to provide actively misleading?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Commits on Dec 7, 2013
  1. @doy @nanto

    try to get a more helpful stacktrace even when exceptions are rethrown

    doy authored nanto committed
    this happens frequently with StackTrace + HTTPExceptions, among other
    things
  2. @nanto

    Keep original stacktaraces only when the key is the same as the last …

    nanto authored
    …key.
    
    To determine if the exception is rethrown, we just compare it to the last
    thrown exception. This way covers most rethrow usages and reduces false
    cache hits.
  3. @nanto
Commits on Dec 10, 2013
  1. @nanto
This page is out of date. Refresh to see the latest.
View
40 lib/Plack/Middleware/StackTrace.pm
@@ -6,6 +6,7 @@ use Devel::StackTrace;
use Devel::StackTrace::AsHTML;
use Try::Tiny;
use Plack::Util::Accessor qw( force no_print_errors );
+use Scalar::Util 'refaddr';
our $StackTraceClass = "Devel::StackTrace";
@@ -18,11 +19,18 @@ sub call {
my($self, $env) = @_;
my $trace;
+ my $last_key = '';
local $SIG{__DIE__} = sub {
- $trace = $StackTraceClass->new(
- indent => 1, message => munge_error($_[0], [ caller ]),
- ignore_package => __PACKAGE__,
- );
+ my $key = _make_key($_[0]);
+ # If we get the same keys, the exception may be rethrown and
+ # we keep the original stacktrace.
+ if ($key ne $last_key) {
+ $trace = $StackTraceClass->new(
+ indent => 1, message => munge_error($_[0], [ caller ]),
+ ignore_package => __PACKAGE__,
+ );
+ $last_key = $key;
+ }
die @_;
};
@@ -34,7 +42,7 @@ sub call {
[ 500, [ "Content-Type", "text/plain; charset=utf-8" ], [ no_trace_error(utf8_safe($caught)) ] ];
};
- if ($trace && ($caught || ($self->force && ref $res eq 'ARRAY' && $res->[0] == 500)) ) {
+ if ($trace && $self->should_show_trace($caught, $last_key, $res)) {
my $text = $trace->as_string;
my $html = $trace->as_html;
$env->{'plack.stacktrace.text'} = $text;
@@ -55,6 +63,15 @@ sub call {
return $res;
}
+sub should_show_trace {
+ my ($self, $err, $key, $res) = @_;
+ if ($err) {
+ return _make_key($err) eq $key;
@nanto
nanto added a note

I think confirming the key just before showing the trace prevents false positives including one that happens currently (e.g. $twice_died_app in t/Plack-Middleware/stacktrace/sigdie.t). What situations do you think to provide actively misleading?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
+ } else {
+ return $self->force && ref $res eq 'ARRAY' && $res->[0] == 500;
+ }
+}
+
sub no_trace_error {
my $msg = shift;
chomp($msg);
@@ -95,6 +112,19 @@ sub utf8_safe {
$str;
}
+sub _make_key {
+ my ($val) = @_;
+ if (!defined($val)) {
+ return 'undef';
+ }
+ elsif (ref($val)) {
+ return 'ref:' . refaddr($val);
+ }
+ else {
+ return "str:$val";
+ }
+}
+
1;
__END__
View
33 t/Plack-Middleware/stacktrace/rethrow.t
@@ -0,0 +1,33 @@
+use strict;
+use warnings;
+use Test::More;
+use Plack::Middleware::StackTrace;
+use Plack::Test;
+use HTTP::Request::Common;
+
+$Plack::Test::Impl = "Server";
+local $ENV{PLACK_SERVER} = "HTTP::Server::PSGI";
+
+my $app = sub {
+ eval { challenge() };
+ die $@ if $@;
+};
+
+sub challenge {
+ die "oops";
+}
+
+my $wrapped = Plack::Middleware::StackTrace->wrap($app, no_print_errors => 1);
+
+test_psgi $wrapped, sub {
+ my $cb = shift;
+
+ my $req = GET "/";
+ my $res = $cb->($req);
+
+ is $res->code, 500;
+ like $res->content, qr/main::challenge/;
+};
+
+done_testing;
+
View
18 t/Plack-Middleware/stacktrace/sigdie.t
@@ -25,5 +25,23 @@ test_psgi $wrapped, sub {
like $res->content, qr/The application raised/;
};
+my $twice_died_app = sub {
+ eval { die "hmm" };
+ $SIG{__DIE__} = sub {};
+ die "meh";
+};
+
+my $twice_died_wrapped = Plack::Middleware::StackTrace->wrap($twice_died_app, no_print_errors => 1);
+
+test_psgi $twice_died_wrapped, sub {
+ my $cb = shift;
+
+ my $req = GET "/";
+ my $res = $cb->($req);
+
+ is $res->code, 500;
+ like $res->content, qr/The application raised/;
+};
+
done_testing;
Something went wrong with that request. Please try again.