[Dancer-users] Runtime error having to do with hooks (which I don't use)

[Brian E. Lozier]

On Fri, Jun 10, 2011 at 7:49 AM, Brian E. Lozier <brian at massassi.com> wrote:
> On Fri, Jun 10, 2011 at 2:29 AM, David Precious <davidp at preshweb.co.uk> wrote:
>> On Friday 10 June 2011 00:30:57 Brian E. Lozier wrote:
>>> Well I tracked down one bug that turns out may be a documentation bug.
>>>  I haven't had time to look really really carefully but I was able to
>>> reproduce a crash when just starting app.pl if the "hook" syntax is
>>> wrong.  The docs say you can do this:
>>>
>>> hook before_template sub {
>>>  # do something
>>> };
>>>
>>> But you really need to do it like this:
>>> 8d50158
>>> hook before_template => sub {
>>>  # do something
>>> };
>>>
>>> A bunch of the hook documentation is broken, [...]
>>
>> You're absolutely right, thanks!  Documentation fixed in 8d50158 which will be
>> in the next release.
>>
>> hook before_template sub {...} is of course wrong, as there's no comma (fat or
>> otherwise) between two params to hook() (and without the fat comma,
>> 'before_template' doesn't get auto-quoted, so it's an unknown bareword, too).
>>
>>> I'm still trying to
>>> find out the root cause of my original issue (which is why I tried
>>> using the "hook" syntax instead of declaring the before_template
>>> directly).
>>
>> Hopefully I'll get a chance to dig further after $work; so far, I've not been
>> able to reproduce the issue you're having.  I think the machine I tested on is
>> still on 1.3050, though, so it may be something that changed in 1.3051.  I'll
>> try 1.3051 and/or devel and see what happens.
>
> I haven't been able to get this to reproduce outside the app I'm
> working on.  However, I think I traced down the problem.  In
> Dancer/Factory/Hook.pm there's a line that looks like this:
>
> $_->(@args) foreach @{$self->get_hooks_for($hook_name)};
>
> I did this before and after that line:
>
>  warn Dumper($self->get_hooks_for($hook_name));
>
> And I noticed that the arrayref of hooks before it was executed the
> first time looked like this:
>
> $VAR1 = [
>          sub { "DUMMY" }
>        ];
>
> But after it ran the first time it returned this:
>
> $VAR1 = [
>          undef
>        ];
>
> So somehow the subroutine ref held for my before_template_render hook
> would be turned to undef with no warnings or anything on the console.
> I haven't been able to figure out why this is but I found if I changed
> the line to be a foreach with a localized var instead of using $_ the
> crash completely went away:
>
>   foreach my $hook (@{ $self->get_hooks_for($hook_name) }) {
>       $hook->(@args);
>   }
>
> It seems like a scoping issue with $_ or @_ or something.  I only have
> an hour or so a day to work on this project so I don't have time to
> dig much deeper today but maybe this will help you reproduce it
> somehow.  I tried explicitly calling "die" inside a hook to try to
> reproduce this and I noticed that nothing dies, no errors get printed
> to the logs, no errors are shown in the browser either.  This is
> really, really dangerous that something can completely swallow death
> and pretend nothing happened.  I suspect this behavior is contributing
> to making this specific bug difficult to reproduce.
>
> I tried to find somewhere in Dancer where die was being trapped but
> came up with nothing so far.

In Dancer/Hook.pm:

        eval { $code->(@_) };

        if ($@) {
            my $err = Dancer::Error->new(
                code    => 500,
                title   => $hook_name . ' filter error',
                message => "An error occured while executing the
filter named $hook_name: $@"
            );
            return Dancer::halt( $err->render );
        }
};

Returning Dancer::halt from here doesn't result in the app actually
returning an error or exiting.  I reproduced this on a simple test app
by creating a before_template_render hook and just dying inside of it.
 The page renders normally but in the logs I see this:

[761]  core @0.013301> [hit #3]response: 500 in
/usr/local/lib/perl5/site_perl/5.12.2/Dancer/Handler.pm l. 159
127.0.0.1 - - [10/Jun/2011 07:58:41] "GET / HTTP/1.0" 500 4885 "-"
"Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US; rv:1.9.2.17)
Gecko/20110420 Firefox/3.6.17"


I don't know how I can get a 500 (server error) in the logs but the
page renders normally.  This part at least should be easy to repro.
Still can't figure out how the code ref can become undef after a
single view but my previous message fixed that.  I'm not totally
comfortable because I don't understand WHY it fixed it.

>
>>
>> Cheers
>>
>> Dave P
>>
>> --
>> David Precious  ("bigpresh")
>> http://www.preshweb.co.uk/
>>
>>   "Programming is like sex. One mistake and you have to support
>>   it for the rest of your life". (Michael Sinz)
>>
>