[2.2.x] Webprofiler - Some called listeners are not shown #6686

Closed
hhamon opened this Issue Jan 10, 2013 · 30 comments

Comments

Projects
None yet
8 participants
Contributor

hhamon commented Jan 10, 2013

In Symfony 2.2.0-BETA1, I've created a listener that listens to the security.authentication.success and it's perfectly triggered.

But when I look at the Events panel in the profiler application, it's still listed in the Not Called Events section of the panel.

Contributor

catchamonkey commented Feb 28, 2013

Yes I can confirm this but in 2.2.0-RC3.

I have an initial listener on kernel.request that is triggered and shown in the profiler.
This method then dispatches another event (in some cases) and I listen to that event.
This second event is also triggered, but is under the Not Called section.

Contributor

catchamonkey commented Feb 28, 2013

I could setup a basic project repo to demo this if it helps?

Owner

fabpot commented Feb 28, 2013

A fork of the Symfony Standard Edition would definitely help. Thanks.

Contributor

catchamonkey commented Feb 28, 2013

No problem, will do that today and come back to you.

Contributor

catchamonkey commented Feb 28, 2013

Hey @fabpot
I've forked and created a branch to show the issue here https://github.com/catchamonkey/symfony-standard/tree/listener_issue

See the diff as a comparison against the 2.2 branch here catchamonkey/symfony-standard@symfony:2.2...catchamonkey:listener_issue

You can pull down, install the deps and run the demo page, app_dev.php/demo/hello/World then look at the events in the profiler, you will see the secondary one i created is in the Not Called Listeners section, but it is being called (uncomment the die within).

Contributor

catchamonkey commented Feb 28, 2013

Actually i've changed it so the secondary method logs an error when called.
There you can see that is logged in the profiler, but the listener is shown as not called.

Contributor

catchamonkey commented Feb 28, 2013

And one more thing, if you can give me a starting point as to where you think the issue may be, i'd be happy to have a look and see if I can solve it.

Member

stof commented Feb 28, 2013

@fabpot This is probably because the dispatcher being passed in the event is the inner dispatcher, not the wrapping one (it is always the issue when using composition and the inner object passes $this to another place)

Owner

fabpot commented Feb 28, 2013

@stof is right and it was done on purpose. Not sure what to do here.

Contributor

catchamonkey commented Feb 28, 2013

Obviously it has knowledge of all the services tagged as kernel.event_listener, but the EventsDataCollector is only aware of the main dispatcher instance in terms of what it knows has happened to those events?

Contributor

catchamonkey commented Feb 28, 2013

I've used the sams approach in a long standing 2.0 project which doesn't have this issue.
Is there possibly another way to approach what i'm trying to do that bypasses the issue?

Contributor

kriswallsmith commented Mar 20, 2013

When in debug mode, debug.event_dispatcher is injected into http_kernel, but event_dispatcher still returns the unwrapped dispatcher. Any events dispatched by services that use event_dispatcher will not be logged.

Why don't we rename event_dispatcher to event_dispatcher.inner and rename debug.event_dispatcher to event_dispatcher? Otherwise I don't see an easy way for user-land services to use the right dispatcher per debug mode…

Owner

fabpot commented Mar 20, 2013

I did that to avoid too much overhead and I did not anticipated the possible issues. So, I guess we should always inject that debug event dispatcher (don't remember if there were any other reasons for not doing it).

Member

stof commented Mar 20, 2013

@fabpot What should be done is aliasing the debug dispatcher as event_dispatcher and keeping the original one in a private service (using the pattern described in #5920 btw, so we will maybe finally get a decision on it for next releases). 👍 for keeping the debug dispatcher each time (the remaining issue would be a listener aessing the dispatcher in the event object)

Contributor

kriswallsmith commented Mar 20, 2013

For the issue @stof raised about the call to $event->setDispatcher($this) … we could add an optional 3rd argument to ->dispatch($eventName, Event $event = null, self $dispatcher = null) and call $event->setDispatcher($dispatcher ?: $this). It's ugly, but is a good workaround for the flaw in this design.

Contributor

catchamonkey commented Apr 8, 2013

Any other thoughts on this?

@mpdude mpdude added a commit to webfactory/symfony that referenced this issue Apr 14, 2013

@mpdude mpdude The most simple fix that could possibly work for #6686? e1d88c7
Contributor

mpdude commented Apr 25, 2013

I have part of a fix over at #7673, but what @catchamonkey demonstrates is that when you use the event_dispatcher service to dispatch an event, the debug.event_dispatcher does not notice it.

The example happens to dispatch the second event that's missed from an event listener, but that is irrelevant. My fix would help there only if he used $event->getDispatcher() to dispatch the second one.

So what's the best practise to re-define/alias the service?

Contributor

mpdude commented Apr 26, 2013

Probably we need a decision in the first place whether we want to

  • pass listeners the Dispatcher that was initially used to set off the `Event``
  • or the Dispatcher that actually notifies the listener.

And while we're at it, it is allowed to re-dispatch() an existing Event object, possibly even from a listener in mid-propagation?

@ghost

ghost commented Sep 11, 2013

@fabpot have you thought about this anymore? It seems the way we use events they never get logged for the reasons pointed out by @mpdude

Contributor

liuggio commented Sep 18, 2013

👍 we have the same issue, this is a little bit annoying because upgrading from 2.1 to 2.3 a lot of functional test fails :(

thanks guys.

@fabpot fabpot added a commit that referenced this issue Sep 19, 2013

@fabpot fabpot merged branch fabpot/event-dispatcher-debug (PR #9068)
This PR was merged into the 2.2 branch.

Discussion
----------

[FrameworkBundle] made sure that the debug event dispatcher is used everywhere

| Q             | A
| ------------- | ---
| Bug fix?      | yes
| New feature?  | no
| BC breaks?    | no
| Deprecations? | no
| Tests pass?   | yes
| Fixed tickets | #6686, #7673
| License       | MIT
| Doc PR        | n/a

Commits
-------

f65a526 [FrameworkBundle] made sure that the debug event dispatcher is used everywhere
1843b82

fabpot closed this Sep 19, 2013

Owner

fabpot commented Sep 23, 2013

And now I do remember why I haven't replaced the event dispatcher service with the traceable one. That's because the traceable event dispatcher needs the profiler, which creates a bunch of data collectors that need many services. The same goes for the twig service which needs a bunch of services for its extensions. But, as some of these deps are required by both the profiler and twig, we have some circular references. The easiest way to reproduce is the run the assetic:dump or twig:lint commands on the CLI.

I'm going to revert the referenced PR for now and we are back to the drawing board.

fabpot reopened this Sep 23, 2013

Member

stof commented Sep 23, 2013

@fabpot should the traceable dispatcher really receive the full profiler ? This is the real issue IMO.

IIRC, this was done to be able to track events triggered late in the process, by registering them manually in the profiler instead of relying on collect(). A better fix IMO would be to make the profiler collect late data for all collectors. Currently, the profiler misses DB queries, log messages, emails, etc.. which are sent during a late kernel.response listener or during a kernel.terminate event (I thought there was an issue for this opened a long time ago, but I can't find it anymore). This way, the traceable dispatcher would not need to depend on the profiler anymore to update the profile during kernel.terminate.

Owner

fabpot commented Sep 30, 2013

#9168 is another attempt to fix this issue. Unfortunately, as this is a rather large patch and a new interface for data collectors, it's going to be only applied on master.

The regression from the previous patch does not exist as I have decoupled the traceable dispatcher from the profiler, but if someone can confirm that there are no other regression with other standard bundles, that would help us a lot.

@ghost

ghost commented Sep 30, 2013

I have the same problems, referenced in the PR.

@fabpot fabpot added a commit that referenced this issue Oct 28, 2013

@fabpot fabpot bug #9168 [FrameworkBundle] made sure that the debug event dispatcher…
… is used everywhere (fabpot)

This PR was merged into the master branch.

Discussion
----------

[FrameworkBundle] made sure that the debug event dispatcher is used everywhere

| Q             | A
| ------------- | ---
| Bug fix?      | yes
| New feature?  | no
| BC breaks?    | no
| Deprecations? | no
| Tests pass?   | yes
| Fixed tickets | #6686, #7673
| License       | MIT
| Doc PR        | n/a

The removal of the Profiler dependency on the TraceableEventDispatcher (#9170) allows to remerge the patch from #9068 that fixes #6686.

This PR also cleans up how profiles are stored. A Profile is now always stored only once.

The fix will only be available on 2.4+ as the changes are too deep to be backported to 2.2 and 2.3.

Commits
-------

1e1835e [FrameworkBundle] made sure that the debug event dispatcher is used everywhere
d866a5a

fabpot closed this in d866a5a Oct 28, 2013

craigh commented Nov 5, 2013

@fabpot - I am having trouble with this now also within the context of Zikula and a module called Dizkus. The problem appeared in the last 10 days or so and was tested and working previous to that.

Zikula uses an extended version of Events called hooks. The typehinting is breaking because we've expected EventDispatcher but now are getting TraceableEventDispatcher. and so everything is broken:

ContextErrorException: Catchable Fatal Error: Argument 1 passed to Zikula_Hook_AbstractHandler::__construct() must be an instance of Zikula_EventManager, instance of Symfony\Component\HttpKernel\Debug\TraceableEventDispatcher given in /Applications/MAMP/htdocs/core.git/src/lib/legacy/Zikula/Hook/AbstractHandler.php line 24

Member

stof commented Nov 6, 2013

@craigh Your typehint should use the interface, not the implementation

craigh referenced this issue in zikula/core Nov 6, 2013

Closed

fix core at Symfony 2.3.* #1370

craigh commented Nov 6, 2013

thank you @stof - I changed the typehints (you can see here: zikula/core#1372)

and now I get a new error 😦
full trace: https://gist.github.com/craigh/20085c868349b3446f91#file-zhookissuetrace2

any ideas?

craigh commented Nov 6, 2013

surely, this is a Symfony error - even my IDE identifies Symfony/Component/HttpKernel/Debug/TraceableEventDispatcher @ line 330 - the $wrapped array key as "Illegal array key type callable"

Member

stof commented Nov 7, 2013

@craigh wrapListener returns a Closure object, which can be used as key in a SplObjectStorage.

It is not a Symfony bug but an IDE bug which does not take into account that closures are objects in PHP.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment