Logs refer wrong package name

[ambs]

In recent Dancer2 installations, logs when running in devel mode (bin/app.pl), show:

[WN:57425] core @2014-11-29 14:29:47> looking for get / in /opt/perl/lib/site_perl/5.20.1/Plack/Middleware/RemoveRedundantBody.pm l. 14

But it should report the module .pm file, not the Plack one :-) Or, if it is not relevant, just remove the module name :-)

[xsawyerx]

I wonder if this is due to providing a default package name in App.pm.

Can we bisect this please? :)

[ambs]

How can I help?

[xsawyerx]

@ambs try git bisect to find the commit that fucked it up. Writing a test would be excellent! :)

[veryrusty]

This sounds vaguely familiar.. like #333. We now add plack middleware as part of the apps psgi coderef which have their own callbacks so the hard-coded magic number to jump stack frames will now be wrong..

[xsawyerx]

Agreed. I wonder how to do this. We can go up the frames until we hit the right one. Question is, what's the right one?

[xsawyerx]

This seems okay for user code, but when called in core, the magic number changes from 6 to 8, then it shows it from the right place. However, if moved to 8 from user code it shows the wrong thing.

Any suggestions on how to fix this?

[ambs]

On 13/12/14 19:50, Sawyer X wrote:

This seems okay for user code, but when called in core, the magic number changes from |6| to |8|, then it shows it from the right place. However, if moved to |8| from user code it shows the wrong thing.

Any suggestions on how to fix this?

— Reply to this email directly or view it on GitHub https://github.com/PerlDancer/Dancer2/issues/791#issuecomment-66888709.

is there any way we can check "who" is calling the method, and adapt the magic number?

I confess I am not really aware of the details on Perl calling mechanisms.

[xsawyerx]

Maybe @veryrusty will have some idea.

[veryrusty]

Hmmm, I had a look (even through the source of Sub::Uplevel and Hook::LexWrap) and don't have any sane suggestions at the moment :(

[ambs]

:(

[sakshee3]

Can we use the idea of public and views directory, to find out who is calling the logger ? and then adapts the magic number ?

[sakshee3]

or we can do something like this , using while loop, which will solve our problem. http://docstore.mik.ua/orelly/perl/prog/ch03_010.htm

[ambs]

if we go while, then run it only once to compute the magical number :dancers:

[sakshee3]

so we can probably add that as a sub so that it stores that value and then we can get rid of computing while again and again

[ambs]

Or even, try the 'magic number' that is most common, and if it is wrong (can we find out if it is wrong?) compute it? No idea... just random ideas.

[xsawyerx]

I think computing it on compile is a valid idea. We had to adjust the "magic number" more than once in the past.

Perhaps something easier would be to have a magic number, but to write a test that verifies it is the correct number. If we change any of the stack and the number changes, the test fails, and we adjust the number to what the test says (since the test will compute it for us).

[ambs]

@xsawyerx , if I understood correctly the problem, depending on how Dancer2 is being used, the number is different, and if so, just the test will not be enough.

[sakshee3]

Isn't the following response correct:

when run with

#!/usr/bin/perl 
use Dancer2;
set show_errors => 1;
get '/'         => sub {
    return "Hello World!";
};
start;

we should get:

>> Dancer2 v0.159003 server 3649 listening on http://0.0.0.0:3000
[main:3649] core @2015-04-04 21:06:16> looking for get / in /usr/local/share/perl/5.18.2/Plack/Middleware/RemoveRedundantBody.pm l. 14
[main:3649] core @2015-04-04 21:06:16> Entering hook core.app.before_request in /usr/local/share/perl/5.18.2/Dancer2/Core/App.pm l. 1251
[main:3649] core @2015-04-04 21:06:16> Entering hook core.app.after_request in /usr/local/share/perl/5.18.2/Dancer2/Core/App.pm l. 1206

and when we run that in

#!/usr/bin/perl 

use Dancer2;
set logger      => 'console';
set log         => 'debug';
set show_errors => 1;
get '/'         => sub {
    debug 'Hello Log!';
    return "Hello World!";
};
start;

we should get

[main:3651] debug @2015-04-04 21:07:39> Hello Log! in ./app.pl l. 10

What is wrong in these outputs ?

[xsawyerx]

$ plackup bin/app.pl
HTTP::Server::PSGI: Accepting connections at http://0:5000/
[MyApp:29224] core @2015-04-04 18:50:23> looking for get / in /home/sawyer/perl5/lib/perl5/Plack/Middleware/RemoveRedundantBody.pm l. 14
[MyApp:29224] core @2015-04-04 18:50:23> Entering hook core.app.before_request in /.../Dancer2/lib/Dancer2/Core/App.pm l. 1251
[MyApp:29224] core @2015-04-04 18:50:23> Entering hook core.app.after_request in /.../Dancer2/lib/Dancer2/Core/App.pm l. 1206
127.0.0.1 - - [04/Apr/2015:18:50:23 +0200] "GET / HTTP/1.1" 200 5361 "-" "curl/7.35.0"

If you take a look at where the warning looking for ... is, it's not in Plack::Middleware::RemoveRedundantBody. It's reporting the wrong package.

[veryrusty]

Unfortunately we currently have four different calls to generate logs:

• Role::Hookable calls $self->engine('logger')->core(...) directly,
• Core::App provides the log method, which is the typical interface for core code to generate a log message. $app->log() calls $self->engine('logger')->$level(...).
• The DSL provides a log keyword. This calls $app->log(),
• The DSL logging keywords debug, info, warning, and error all call the DSL log method.

i.e. depending on what's called, we need to jump $n to $n+3 call frames (for some magic number $n) to report the caller correctly. Yuck!.

I've got a branch (which I'll push soon) that changes Role::Hookable and the DSL logging keywords to all call $app->log directly.. That should reduce the problem to needing either $n or $n+1, though I need to do a little further testing before I push that branch ;)

[xsawyerx]

@veryrusty++

Excellent research work! I hope I get to sit down today or tomorrow and review issues, PRs, and prepare a release.