[Catalyst] Warnings when upgrading Catalyst

Nobody has a clue on this one? I've no idea how the relative values get set and I'm not looking forward to a long slog through the guts of Catalyst to understand what's happening here :)


Cheers,
Ovid

I'm guessing that Catalyst is (incorrectly) trying to collect stats
for the private actions, or something similar.

I'd recommend you bisect backwards through the various CPAN releases
and find where it was introduced.

There is a detailed changelog, and I'd guess any releases mentioning
'stats' are worth testing either side of.

I guess you can get the issue down to a release, or maybe even a
specific revision (git bisect for the win!), without having to attack
the Catalyst code at all.

I'd also guess that you're seeing the warning due to something 'non-
standard' your app is doing with logging / stats collection in
general. If that stuff is easy to identify - try just extracting
that, one controller and a simple test out into a standalone test
app.. Or branch and start removing your application (shoot the model
and views, remove the code from the controllers leaving just the
stubs etc) - shouldn't take long to get down to a minimal app..

Either way, I'd recommend trying to narrow down your issue with one
or both of these techniques, rather than randomly trawling through
the cat-guts..

Cheers
t0m

I had to randomly trawl through the cat-guts. Paring down our rather large application is not easy and I wasn't aware of a git repository for git bisect. I *did* wind up downloading various CPAN releases and got it down to this:

5.7* distributions do not issue the warning.

5.8005_05 to 5.80002 were failing with:

(Could not load class (PIPs) because : Can't call method "reverse" on an undefined
value at /home/ovid/pips_dev/work/Pips3/branches/rights_modeling/Catalyst-Runtime-5.80001/ \
lib/Catalyst/DispatchType/Chained.pm line 115.)

Earlier 5.8* series were failing with various errors.

In short, it's been tough for me to nail down when the failure occurs because different versions of Catalyst have different dependencies and it's tough to grab all at once and set up a good environment.

In the meantime, the warning thrown by Catalyst->_stats_start_execute() still remains. You mentioned a guess that it was trying to collect stats on private attributes and the check for that is the first line:

return if ( ( $code->name =~ /^_.*/ )
&& ( !$c->config->{show_internal_actions} ) );

The $code->name when we get the warning is 'default', so I'm assuming it's not considered a private action. When we get to the actual section of code which issues the warning (line 1561 in the cpan distribution)

if ( my $parent = $c->stack->[-1] ) {
$c->stats->profile(
begin => $action,
parent => "$parent" . $c->counter->{"$parent"}, # 1561
uid => $uid,
);
}
else {

# forward with no caller may come from a plugin
$c->stats->profile(
begin => $action,
uid => $uid,
);
}

The $action is '-> /import/response/default' and we go to here from the sub Catalyst::Dispatcher::_do_forward() and it's the forwarding which triggers this bit of the stats profiling. I just don't know enough about what is supposed to happen here to give better information. Sorry for being so darned vague :(

Note that if we check to see if $c->counter->{"$parent"} is defined (again, $parent stringifies to "api/v1/promotion/_ACTION", in case it's relevant) and if not, switch to the else {}, this warning will go away. I don't know, however, if this is the right thing to do, particularly since I can't write a test for this. Phooey.

Cheers,
Ovid

git-svn will do bisect - just import, rafl also has a mirror of a git-
svn import on github :)
I think that you want r9803 applying to those releases.

Also, you're in debug mode.. Do you get the warnings when debug mode
is disabled?
Right, that sounds unsurprising - _05 and _06 is when much of the
backwards compatibility got sorted out :)
I'm now wildly stabbing in the dark, but can you try:

http://dev.catalyst.perl.org/repos/Catalyst/Catalyst-Runtime/5.80/
branches/index_default_fuckage/

which _may_ fix your issue, as the sub you're dealing with is called
'default' and that has some fixes for that... This is merely a guess,
I don't pretend to really understand what's going on for you, or why
you're getting this.

I'll try and have a think on it some more.

Cheers
t0m

Gah! I should really consider just giving up on Yahoo! Mail. Replying to HTML email is *painful* :( I hereby swallow the meme kool-aid and dub them Yahoo! FAIL.

--- On Wed, 24/6/09, Tomas Doran wrote:
No, that evaluates to undef. However, that doesn't apply because when the error occurs, $code->name is 'default', thus avoiding the second condition. I think the confusion stems from how the above code is written. This is clearer, I think:

return if (
$code->name =~ /^_/
and
not $c->config->{show_internal_actions}
);
I tried to grab that, but our socks proxy won't allow this. If anyone is kind enough to send me a tarball, I'll happily give it a try and report what I find :)

And no worries about stabs in the dark. I really appreciate the fact that you're taking the time to consider this.

Cheers,
Ovid

Not just your proxy, it's a 404 :)


-J

Heh, you're right.

This was folded into trunk late last night :).

Appropriate tarball was mailed offlist.

Cheers
t0m

So, looking back into your Dumper output, I guess that you're seeing
this as you're using Catalyst::Action::REST, and you're doing a
forward from an action_METHOD type sub?

If so, here's your fixes:

http://github.com/bobtfish/catalyst-action-rest/commit/
679978b1f8a1f309ff7c11ea0a744f8b1fe22d5a
http://github.com/bobtfish/catalyst-action-rest/tarball/
fixes_5_80_forward_stats_warnings

Please confirm if I'm right in my guessing and this works for you, or
if not - I think the next thing to do is get a stack trace so we can
better guess why we're getting there..

Can you do something cheesy like:

BEGIN: { $SIG{__WARN__} = Carp::cluck };

in MyApp.pm and give us the stack trace and debug output for a hit
which warns?

Cheers
t0m

Hi,

(my reply might be garbled, sorry)

I've got the same problem generated from a Controller that uses
Controller::REST as a base class.

And the warning being generated when I ->forward() to another Controller
(doing some data validation).

I've got around this warning by editing Catalyst.pm and adding this
piece of code

if ( not exists $c->counter->{"$parent"}
or not defined $c->counter->{"$parent"} )
{
$c->counter->{"$parent"} = 0;
}

right before the undefined value is used:

$c->stats->profile(
begin => $action,
parent => "$parent" . $c->counter->{"$parent"},
uid => $uid,
);

that worked for me, and now the debug output shows the profiling for the
methods I ->forward() to as well:

the methods from another Controller to which I forward to, where missing
from the profiling output, getting that warning instead.

http://dev.catalyst.perl.org/repos/Catalyst/Catalyst-Runtime/5.80/branches/index_default_fuckage/

Hmm, I can't replicate this in a simple case, from that description..



That looks like a prefect fix to me, but I'd _really_ like to get to
the bottom of what is causing the issue, so that we can write tests
of some form, and also because this could be hiding a bug at another
layer which should be fixed :/

Are you forwarding to a private path string, or an action object?

I guess extracting _just_ the structure of your controllers (without
any of the code, just the sub/attribute declerations), and ensuring
your doing the appropriate forwards that your app would be doing
would replicate the issue in a TestApp.

Don't suppose you could attempt that, so that we can find the root
cause, and get this fix integrated?

Cheers
t0m

my email was garbled as I wasn't subscribed to the list when the
original emails have been sent :P
Here: http://www.depechemode.ro/MyApp-0.1.tar.gz
a simple TestApp using Catalyst::Controller::REST to replicate the
problem, having Catalyst 5.80005 installed.

Please have a look at the included README.

that makes sense, what I did was just to shut off the warning, didn't
had the guts to look forward to search for the root of the problem.

Aha, this was very helpful, thank you.

The issue is inside Action::REST. Specifically, you could only
trigger it inside the 'action_GET' type methods.

I've had a fiddle with it so that the REST actions come up in stats,
and fixed the warning on the way:

http://github.com/bobtfish/catalyst-action-rest/commit/
679978b1f8a1f309ff7c11ea0a744f8b1fe22d5a

This isn't ready to integrate yet, I think I probably need to rewrite
it all to be less fugly when I've got a clear head, but it does the job.

Can you check it out and confirm that this fixes the warnings for you?

I guess I should also go fix the warning in Catalyst, and get the
stats to display properly without this patch - but that is at best
papering over the cracks :)

From your original mail, you said:
I can't see any methods missing from the stats table with / without
this patch when using your supplied testapp however.

Can you retry with the latest version of Catalyst so see if you can
replicate this behavior once again, before we kill the warning and
forget about this?

Cheers
t0m

Hello,

Tomas Doran wrote:
I've checked it out and indeed using the version of Controller::REST you
provided fixes the warning.

Not only that, but it seems it doesn't break the functionality for both
the test application I provided and another more complex one I'm using.

Indeed, the test application provided didn't show the behaviour I was
talking about. my bad :)
this replicates with Catalyst: 5.80005 Catalyst 5.80007
without the REST patch
the REST patch fixes the warning with both versions of Catalyst

Use of uninitialized value in concatenation (.) or string at
/usr/lib/perl5/site_perl/5.10.0/Catalyst.pm line 1573.

Great, thanks for testing.

I'll see if I can make the code any less gross and/or come up with a
neater way of doing it, then get it integrated and shipped.
heh, no worries.
Nono - I was _specifically_ talking about the lines missing from the
stats table behavior.

I'm still concerned about working out the root cause of that, before I
do something to 'just shut the warning up', as it were :)

Cheers
t0m

Tomas Doran wrote:

[...]
Running $ perl script/myapp_test.pl /rest/test
in several scenarios:

* Catalyst 5.80007 from CPAN, Catalyst::Controller::REST 0.73 from CPAN

.------------------------------------------------------------+-----------.
'------------------------------------------------------------+-----------'

* Catalyst 5.80007, with warning supressed, Catalyst::Controller::REST
0.73 from CPAN

.------------------------------------------------------------+-----------.
'------------------------------------------------------------+-----------'

* Catalyst 5.80007 from CPAN, Catalyst::Controller::REST 0.73 you provided

.------------------------------------------------------------+-----------.
'------------------------------------------------------------+-----------'

* Catalyst 5.80007, with warning supressed, Catalyst::Controller::REST
0.73 you provided

.------------------------------------------------------------+-----------.
'------------------------------------------------------------+-----------'

It looks like I was mistaken when talking about missing actions in the
stats output, in the sense that supressing the Catalyst warning didn't
automagically make more actions to be displayed in the stats.

However I see that using the REST controller you provided, test_GET pops up.

Yup. Getting that stuff in stats is also one of the benefits of that
patch :)

Thanks very much for all the effort testing various things out for me.

I'll have a poke with Catalyst 5.71 some time over the weekend, work
out why it didn't ever emit a warning, and work out the best way to
get this fixed in core.

I _MAY_ get time to get the patch on Action-REST into a shippable
state, but that is I'm afraid less likely - it will happen, but
probably not for a week or so.

Cheers
t0m

Thanks from me, too. This will make our test suite much quieter.


Cheers,
Ovid

I guess this means that was also your issue, and I can stop worrying
about that also then? ;_)

Cheers
t0m