TraceableEventDispatcher.php

<?php

/*
 * This file is part of the Symfony package.
 *
 * (c) Fabien Potencier <fabien@symfony.com>
 *
 * For the full copyright and license information, please view the LICENSE
 * file that was distributed with this source code.
 */

namespace Symfony\Component\HttpKernel\Debug;

use Symfony\Component\Stopwatch\Stopwatch;
use Symfony\Component\HttpKernel\KernelEvents;
use Psr\Log\LoggerInterface;
use Symfony\Component\HttpKernel\Profiler\Profile;
use Symfony\Component\HttpKernel\Profiler\Profiler;
use Symfony\Component\HttpKernel\HttpKernelInterface;
use Symfony\Component\EventDispatcher\Event;
use Symfony\Component\EventDispatcher\EventDispatcherInterface;
use Symfony\Component\EventDispatcher\EventSubscriberInterface;
use Symfony\Component\EventDispatcher\Debug\TraceableEventDispatcherInterface;

/**
 * Collects some data about event listeners.
 *
 * This event dispatcher delegates the dispatching to another one.
 *
 * @author Fabien Potencier <fabien@symfony.com>
 */
class TraceableEventDispatcher implements EventDispatcherInterface, TraceableEventDispatcherInterface
{
    private $logger;
    private $called;
    private $stopwatch;
    private $profiler;
    private $dispatcher;
    private $wrappedListeners;
    private $firstCalledEvent;
    private $id;

    /**
     * Constructor.
     *
     * @param EventDispatcherInterface $dispatcher An EventDispatcherInterface instance
     * @param Stopwatch                $stopwatch  A Stopwatch instance
     * @param LoggerInterface          $logger     A LoggerInterface instance
     */
    public function __construct(EventDispatcherInterface $dispatcher, Stopwatch $stopwatch, LoggerInterface $logger = null)
    {
        $this->dispatcher = $dispatcher;
        $this->stopwatch = $stopwatch;
        $this->logger = $logger;
        $this->called = array();
        $this->wrappedListeners = array();
        $this->firstCalledEvent = array();
    }

    /**
     * Sets the profiler.
     *
     * @param Profiler|null $profiler A Profiler instance
     */
    public function setProfiler(Profiler $profiler = null)
    {
        $this->profiler = $profiler;
    }

    /**
     * {@inheritDoc}
     */
    public function addListener($eventName, $listener, $priority = 0)
    {
        $this->dispatcher->addListener($eventName, $listener, $priority);
    }

    /**
     * {@inheritdoc}
     */
    public function addSubscriber(EventSubscriberInterface $subscriber)
    {
        $this->dispatcher->addSubscriber($subscriber);
    }

    /**
     * {@inheritdoc}
     */
    public function removeListener($eventName, $listener)
    {
        return $this->dispatcher->removeListener($eventName, $listener);
    }

    /**
     * {@inheritdoc}
     */
    public function removeSubscriber(EventSubscriberInterface $subscriber)
    {
        return $this->dispatcher->removeSubscriber($subscriber);
    }

    /**
     * {@inheritdoc}
     */
    public function getListeners($eventName = null)
    {
        return $this->dispatcher->getListeners($eventName);
    }

    /**
     * {@inheritdoc}
     */
    public function hasListeners($eventName = null)
    {
        return $this->dispatcher->hasListeners($eventName);
    }

    /**
     * {@inheritdoc}
     */
    public function dispatch($eventName, Event $event = null)
    {
        if (null === $event) {
            $event = new Event();
        }

        $this->id = spl_object_hash($event);

        $this->preDispatch($eventName, $event);

        $e = $this->stopwatch->start($eventName, 'section');

        $this->firstCalledEvent[$eventName] = $this->stopwatch->start($eventName.'.loading', 'event_listener_loading');

        if (!$this->dispatcher->hasListeners($eventName)) {
            $this->firstCalledEvent[$eventName]->stop();
        }

        $this->dispatcher->dispatch($eventName, $event);

        // reset the id as another event might have been dispatched during the dispatching of this event
        $this->id = spl_object_hash($event);

        unset($this->firstCalledEvent[$eventName]);

        $e->stop();

        $this->postDispatch($eventName, $event);

        return $event;
    }

    /**
     * {@inheritDoc}
     */
    public function getCalledListeners()
    {
        return $this->called;
    }

    /**
     * {@inheritDoc}
     */
    public function getNotCalledListeners()
    {
        $notCalled = array();

        foreach ($this->getListeners() as $name => $listeners) {
            foreach ($listeners as $listener) {
                $info = $this->getListenerInfo($listener, $name);
                if (!isset($this->called[$name.'.'.$info['pretty']])) {
                    $notCalled[$name.'.'.$info['pretty']] = $info;
                }
            }
        }

        return $notCalled;
    }

    /**
     * Proxies all method calls to the original event dispatcher.
     *
     * @param string $method    The method name
     * @param array  $arguments The method arguments
     *
     * @return mixed
     */
    public function __call($method, $arguments)
    {
        return call_user_func_array(array($this->dispatcher, $method), $arguments);
    }

    /**
     * This is a private method and must not be used.
     *
     * This method is public because it is used in a closure.
     * Whenever Symfony will require PHP 5.4, this could be changed
     * to a proper private method.
     */
    public function logSkippedListeners($eventName, Event $event, $listener)
    {
        if (null === $this->logger) {
            return;
        }

        $info = $this->getListenerInfo($listener, $eventName);

        $this->logger->debug(sprintf('Listener "%s" stopped propagation of the event "%s".', $info['pretty'], $eventName));

        $skippedListeners = $this->getListeners($eventName);
        $skipped = false;

        foreach ($skippedListeners as $skippedListener) {
            $skippedListener = $this->unwrapListener($skippedListener);

            if ($skipped) {
                $info = $this->getListenerInfo($skippedListener, $eventName);
                $this->logger->debug(sprintf('Listener "%s" was not called for event "%s".', $info['pretty'], $eventName));
            }

            if ($skippedListener === $listener) {
                $skipped = true;
            }
        }
    }

    /**
     * This is a private method.
     *
     * This method is public because it is used in a closure.
     * Whenever Symfony will require PHP 5.4, this could be changed
     * to a proper private method.
     */
    public function preListenerCall($eventName, $listener)
    {
        // is it the first called listener?
        if (isset($this->firstCalledEvent[$eventName])) {
            $this->firstCalledEvent[$eventName]->stop();

            unset($this->firstCalledEvent[$eventName]);
        }

        $info = $this->getListenerInfo($listener, $eventName);

        if (null !== $this->logger) {
            $this->logger->debug(sprintf('Notified event "%s" to listener "%s".', $eventName, $info['pretty']));
        }

        $this->called[$eventName.'.'.$info['pretty']] = $info;

        return $this->stopwatch->start(isset($info['class']) ? $info['class'] : $info['type'], 'event_listener');
    }

    /**
     * Returns information about the listener
     *
     * @param object $listener  The listener
     * @param string $eventName The event name
     *
     * @return array Informations about the listener
     */
    private function getListenerInfo($listener, $eventName)
    {
        $listener = $this->unwrapListener($listener);

        $info = array(
            'event' => $eventName,
        );
        if ($listener instanceof \Closure) {
            $info += array(
                'type' => 'Closure',
                'pretty' => 'closure'
            );
        } elseif (is_string($listener)) {
            try {
                $r = new \ReflectionFunction($listener);
                $file = $r->getFileName();
                $line = $r->getStartLine();
            } catch (\ReflectionException $e) {
                $file = null;
                $line = null;
            }
            $info += array(
                'type'  => 'Function',
                'function' => $listener,
                'file'  => $file,
                'line'  => $line,
                'pretty' => $listener,
            );
        } elseif (is_array($listener) || (is_object($listener) && is_callable($listener))) {
            if (!is_array($listener)) {
                $listener = array($listener, '__invoke');
            }
            $class = is_object($listener[0]) ? get_class($listener[0]) : $listener[0];
            try {
                $r = new \ReflectionMethod($class, $listener[1]);
                $file = $r->getFileName();
                $line = $r->getStartLine();
            } catch (\ReflectionException $e) {
                $file = null;
                $line = null;
            }
            $info += array(
                'type'  => 'Method',
                'class' => $class,
                'method' => $listener[1],
                'file'  => $file,
                'line'  => $line,
                'pretty' => $class.'::'.$listener[1],
            );
        }

        return $info;
    }

    /**
     * Updates the stopwatch data in the profile hierarchy.
     *
     * @param string  $token          Profile token
     * @param Boolean $updateChildren Whether to update the children altogether
     */
    private function updateProfiles($token, $updateChildren)
    {
        if (!$this->profiler || !$profile = $this->profiler->loadProfile($token)) {
            return;
        }

        $this->saveInfoInProfile($profile, $updateChildren);
    }

    /**
     * Update the profiles with the timing and events information and saves them.
     *
     * @param Profile $profile        The root profile
     * @param Boolean $updateChildren Whether to update the children altogether
     */
    private function saveInfoInProfile(Profile $profile, $updateChildren)
    {
        try {
            $collector = $profile->getCollector('memory');
            $collector->updateMemoryUsage();
        } catch (\InvalidArgumentException $e) {
        }

        try {
            $collector = $profile->getCollector('time');
            $collector->setEvents($this->stopwatch->getSectionEvents($profile->getToken()));
        } catch (\InvalidArgumentException $e) {
        }

        try {
            $collector = $profile->getCollector('events');
            $collector->setCalledListeners($this->getCalledListeners());
            $collector->setNotCalledListeners($this->getNotCalledListeners());
        } catch (\InvalidArgumentException $e) {
        }

        $this->profiler->saveProfile($profile);

        if ($updateChildren) {
            foreach ($profile->getChildren() as $child) {
                $this->saveInfoInProfile($child, true);
            }
        }
    }

    private function preDispatch($eventName, Event $event)
    {
        // wrap all listeners before they are called
        $this->wrappedListeners[$this->id] = new \SplObjectStorage();

        $listeners = $this->dispatcher->getListeners($eventName);

        foreach ($listeners as $listener) {
            $this->dispatcher->removeListener($eventName, $listener);
            $wrapped = $this->wrapListener($eventName, $listener);
            $this->wrappedListeners[$this->id][$wrapped] = $listener;
            $this->dispatcher->addListener($eventName, $wrapped);
        }

        switch ($eventName) {
            case KernelEvents::REQUEST:
                $this->stopwatch->openSection();
                break;
            case KernelEvents::VIEW:
            case KernelEvents::RESPONSE:
                // stop only if a controller has been executed
                if ($this->stopwatch->isStarted('controller')) {
                    $this->stopwatch->stop('controller');
                }
                break;
            case KernelEvents::TERMINATE:
                $token = $event->getResponse()->headers->get('X-Debug-Token');
                // There is a very special case when using builtin AppCache class as kernel wrapper, in the case
                // of an ESI request leading to a `stale` response [B]  inside a `fresh` cached response [A].
                // In this case, `$token` contains the [B] debug token, but the  open `stopwatch` section ID
                // is equal to the [A] debug token. Trying to reopen section with the [B] token throws an exception
                // which must be caught.
                try {
                    $this->stopwatch->openSection($token);
                } catch (\LogicException $e) {}
                break;
        }
    }

    private function postDispatch($eventName, Event $event)
    {
        switch ($eventName) {
            case KernelEvents::CONTROLLER:
                $this->stopwatch->start('controller', 'section');
                break;
            case KernelEvents::RESPONSE:
                $token = $event->getResponse()->headers->get('X-Debug-Token');
                $this->stopwatch->stopSection($token);
                if (HttpKernelInterface::MASTER_REQUEST === $event->getRequestType()) {
                    // The profiles can only be updated once they have been created
                    // that is after the 'kernel.response' event of the main request
                    $this->updateProfiles($token, true);
                }
                break;
            case KernelEvents::TERMINATE:
                $token = $event->getResponse()->headers->get('X-Debug-Token');
                // In the special case described in the `preDispatch` method above, the `$token` section
                // does not exist, then closing it throws an exception which must be caught.
                try {
                    $this->stopwatch->stopSection($token);
                } catch (\LogicException $e) {}
                // The children profiles have been updated by the previous 'kernel.response'
                // event. Only the root profile need to be updated with the 'kernel.terminate'
                // timing informations.
                $this->updateProfiles($token, false);
                break;
        }

        foreach ($this->wrappedListeners[$this->id] as $wrapped) {
            $this->dispatcher->removeListener($eventName, $wrapped);
            $this->dispatcher->addListener($eventName, $this->wrappedListeners[$this->id][$wrapped]);
        }

        unset($this->wrappedListeners[$this->id]);
    }

    private function wrapListener($eventName, $listener)
    {
        $self = $this;

        return function (Event $event) use ($self, $eventName, $listener) {
            $e = $self->preListenerCall($eventName, $listener);

            call_user_func($listener, $event);

            $e->stop();

            if ($event->isPropagationStopped()) {
                $self->logSkippedListeners($eventName, $event, $listener);
            }
        };
    }

    private function unwrapListener($listener)
    {
        // get the original listener
        if (is_object($listener) && isset($this->wrappedListeners[$this->id][$listener])) {
            return $this->wrappedListeners[$this->id][$listener];
        }

        return $listener;
    }
}