[Summary view] [Print] [Text view]

   1  <?php
   2  
   3  /*
   4   * This file is part of the Symfony package.
   5   *
   6   * (c) Fabien Potencier <fabien@symfony.com>
   7   *
   8   * For the full copyright and license information, please view the LICENSE
   9   * file that was distributed with this source code.
  10   */
  11  
  12  namespace Symfony\Component\HttpKernel\Debug;
  13  
  14  use Symfony\Component\Stopwatch\Stopwatch;
  15  use Symfony\Component\HttpKernel\KernelEvents;
  16  use Psr\Log\LoggerInterface;
  17  use Symfony\Component\HttpKernel\Profiler\Profile;
  18  use Symfony\Component\HttpKernel\Profiler\Profiler;
  19  use Symfony\Component\HttpKernel\HttpKernelInterface;
  20  use Symfony\Component\EventDispatcher\Event;
  21  use Symfony\Component\EventDispatcher\EventDispatcherInterface;
  22  use Symfony\Component\EventDispatcher\EventSubscriberInterface;
  23  use Symfony\Component\EventDispatcher\Debug\TraceableEventDispatcherInterface;
  24  
  25  /**
  26   * Collects some data about event listeners.
  27   *
  28   * This event dispatcher delegates the dispatching to another one.
  29   *
  30   * @author Fabien Potencier <fabien@symfony.com>
  31   */
  32  class TraceableEventDispatcher implements EventDispatcherInterface, TraceableEventDispatcherInterface
  33  {
  34      private $logger;
  35      private $called;
  36      private $stopwatch;
  37      private $profiler;
  38      private $dispatcher;
  39      private $wrappedListeners;
  40      private $firstCalledEvent;
  41      private $lastEventId = 0;
  42  
  43      /**
  44       * Constructor.
  45       *
  46       * @param EventDispatcherInterface $dispatcher An EventDispatcherInterface instance
  47       * @param Stopwatch                $stopwatch  A Stopwatch instance
  48       * @param LoggerInterface          $logger     A LoggerInterface instance
  49       */
  50      public function __construct(EventDispatcherInterface $dispatcher, Stopwatch $stopwatch, LoggerInterface $logger = null)
  51      {
  52          $this->dispatcher = $dispatcher;
  53          $this->stopwatch = $stopwatch;
  54          $this->logger = $logger;
  55          $this->called = array();
  56          $this->wrappedListeners = array();
  57          $this->firstCalledEvent = array();
  58      }
  59  
  60      /**
  61       * Sets the profiler.
  62       *
  63       * @param Profiler|null $profiler A Profiler instance
  64       */
  65      public function setProfiler(Profiler $profiler = null)
  66      {
  67          $this->profiler = $profiler;
  68      }
  69  
  70      /**
  71       * {@inheritdoc}
  72       */
  73      public function addListener($eventName, $listener, $priority = 0)
  74      {
  75          $this->dispatcher->addListener($eventName, $listener, $priority);
  76      }
  77  
  78      /**
  79       * {@inheritdoc}
  80       */
  81      public function addSubscriber(EventSubscriberInterface $subscriber)
  82      {
  83          $this->dispatcher->addSubscriber($subscriber);
  84      }
  85  
  86      /**
  87       * {@inheritdoc}
  88       */
  89      public function removeListener($eventName, $listener)
  90      {
  91          if (isset($this->wrappedListeners[$this->lastEventId])) {
  92              foreach ($this->wrappedListeners[$this->lastEventId] as $wrappedListener) {
  93                  $originalListener = $this->wrappedListeners[$this->lastEventId][$wrappedListener];
  94  
  95                  if ($originalListener === $listener) {
  96                      unset($this->wrappedListeners[$this->lastEventId][$wrappedListener]);
  97  
  98                      return $this->dispatcher->removeListener($eventName, $wrappedListener);
  99                  }
 100              }
 101          }
 102  
 103          return $this->dispatcher->removeListener($eventName, $listener);
 104      }
 105  
 106      /**
 107       * {@inheritdoc}
 108       */
 109      public function removeSubscriber(EventSubscriberInterface $subscriber)
 110      {
 111          return $this->dispatcher->removeSubscriber($subscriber);
 112      }
 113  
 114      /**
 115       * {@inheritdoc}
 116       */
 117      public function getListeners($eventName = null)
 118      {
 119          return $this->dispatcher->getListeners($eventName);
 120      }
 121  
 122      /**
 123       * {@inheritdoc}
 124       */
 125      public function hasListeners($eventName = null)
 126      {
 127          return $this->dispatcher->hasListeners($eventName);
 128      }
 129  
 130      /**
 131       * {@inheritdoc}
 132       */
 133      public function dispatch($eventName, Event $event = null)
 134      {
 135          if (null === $event) {
 136              $event = new Event();
 137          }
 138  
 139          if (null !== $this->logger && $event->isPropagationStopped()) {
 140              $this->logger->debug(sprintf('The "%s" event is already stopped. No listeners have been called.', $eventName));
 141          }
 142  
 143          $eventId = ++$this->lastEventId;
 144  
 145          $this->preDispatch($eventName, $eventId, $event);
 146  
 147          $e = $this->stopwatch->start($eventName, 'section');
 148  
 149          $this->firstCalledEvent[$eventName] = $this->stopwatch->start($eventName.'.loading', 'event_listener_loading');
 150  
 151          if (!$this->dispatcher->hasListeners($eventName)) {
 152              $this->firstCalledEvent[$eventName]->stop();
 153          }
 154  
 155          $this->dispatcher->dispatch($eventName, $event);
 156  
 157          unset($this->firstCalledEvent[$eventName]);
 158  
 159          $e->stop();
 160  
 161          $this->postDispatch($eventName, $eventId, $event);
 162  
 163          return $event;
 164      }
 165  
 166      /**
 167       * {@inheritdoc}
 168       */
 169      public function getCalledListeners()
 170      {
 171          return $this->called;
 172      }
 173  
 174      /**
 175       * {@inheritdoc}
 176       */
 177      public function getNotCalledListeners()
 178      {
 179          try {
 180              $allListeners = $this->getListeners();
 181          } catch (\Exception $e) {
 182              if (null !== $this->logger) {
 183                  $this->logger->info(sprintf('An exception was thrown while getting the uncalled listeners (%s)', $e->getMessage()), array('exception' => $e));
 184              }
 185  
 186              // unable to retrieve the uncalled listeners
 187              return array();
 188          }
 189  
 190          $notCalled = array();
 191          foreach ($allListeners as $name => $listeners) {
 192              foreach ($listeners as $listener) {
 193                  $info = $this->getListenerInfo($listener, null, $name);
 194                  if (!isset($this->called[$name.'.'.$info['pretty']])) {
 195                      $notCalled[$name.'.'.$info['pretty']] = $info;
 196                  }
 197              }
 198          }
 199  
 200          return $notCalled;
 201      }
 202  
 203      /**
 204       * Proxies all method calls to the original event dispatcher.
 205       *
 206       * @param string $method    The method name
 207       * @param array  $arguments The method arguments
 208       *
 209       * @return mixed
 210       */
 211      public function __call($method, $arguments)
 212      {
 213          return call_user_func_array(array($this->dispatcher, $method), $arguments);
 214      }
 215  
 216      /**
 217       * This is a private method and must not be used.
 218       *
 219       * This method is public because it is used in a closure.
 220       * Whenever Symfony will require PHP 5.4, this could be changed
 221       * to a proper private method.
 222       */
 223      public function logSkippedListeners($eventName, $eventId, Event $event, $listener)
 224      {
 225          if (null === $this->logger) {
 226              return;
 227          }
 228  
 229          $info = $this->getListenerInfo($listener, $eventId, $eventName);
 230  
 231          $this->logger->debug(sprintf('Listener "%s" stopped propagation of the event "%s".', $info['pretty'], $eventName));
 232  
 233          $skippedListeners = $this->getListeners($eventName);
 234          $skipped = false;
 235  
 236          foreach ($skippedListeners as $skippedListener) {
 237              $skippedListener = $this->unwrapListener($skippedListener, $eventId);
 238  
 239              if ($skipped) {
 240                  $info = $this->getListenerInfo($skippedListener, $eventId, $eventName);
 241                  $this->logger->debug(sprintf('Listener "%s" was not called for event "%s".', $info['pretty'], $eventName));
 242              }
 243  
 244              if ($skippedListener === $listener) {
 245                  $skipped = true;
 246              }
 247          }
 248      }
 249  
 250      /**
 251       * This is a private method.
 252       *
 253       * This method is public because it is used in a closure.
 254       * Whenever Symfony will require PHP 5.4, this could be changed
 255       * to a proper private method.
 256       */
 257      public function preListenerCall($eventName, $eventId, $listener)
 258      {
 259          // is it the first called listener?
 260          if (isset($this->firstCalledEvent[$eventName])) {
 261              $this->firstCalledEvent[$eventName]->stop();
 262  
 263              unset($this->firstCalledEvent[$eventName]);
 264          }
 265  
 266          $info = $this->getListenerInfo($listener, $eventId, $eventName);
 267  
 268          if (null !== $this->logger) {
 269              $this->logger->debug(sprintf('Notified event "%s" to listener "%s".', $eventName, $info['pretty']));
 270          }
 271  
 272          $this->called[$eventName.'.'.$info['pretty']] = $info;
 273  
 274          return $this->stopwatch->start(isset($info['class']) ? $info['class'] : $info['type'], 'event_listener');
 275      }
 276  
 277      /**
 278       * Returns information about the listener.
 279       *
 280       * @param object   $listener  The listener
 281       * @param int|null $eventId   The event id
 282       * @param string   $eventName The event name
 283       *
 284       * @return array Information about the listener
 285       */
 286      private function getListenerInfo($listener, $eventId, $eventName)
 287      {
 288          $listener = $this->unwrapListener($listener, $eventId);
 289  
 290          $info = array(
 291              'event' => $eventName,
 292          );
 293          if ($listener instanceof \Closure) {
 294              $info += array(
 295                  'type' => 'Closure',
 296                  'pretty' => 'closure',
 297              );
 298          } elseif (is_string($listener)) {
 299              try {
 300                  $r = new \ReflectionFunction($listener);
 301                  $file = $r->getFileName();
 302                  $line = $r->getStartLine();
 303              } catch (\ReflectionException $e) {
 304                  $file = null;
 305                  $line = null;
 306              }
 307              $info += array(
 308                  'type' => 'Function',
 309                  'function' => $listener,
 310                  'file' => $file,
 311                  'line' => $line,
 312                  'pretty' => $listener,
 313              );
 314          } elseif (is_array($listener) || (is_object($listener) && is_callable($listener))) {
 315              if (!is_array($listener)) {
 316                  $listener = array($listener, '__invoke');
 317              }
 318              $class = is_object($listener[0]) ? get_class($listener[0]) : $listener[0];
 319              try {
 320                  $r = new \ReflectionMethod($class, $listener[1]);
 321                  $file = $r->getFileName();
 322                  $line = $r->getStartLine();
 323              } catch (\ReflectionException $e) {
 324                  $file = null;
 325                  $line = null;
 326              }
 327              $info += array(
 328                  'type' => 'Method',
 329                  'class' => $class,
 330                  'method' => $listener[1],
 331                  'file' => $file,
 332                  'line' => $line,
 333                  'pretty' => $class.'::'.$listener[1],
 334              );
 335          }
 336  
 337          return $info;
 338      }
 339  
 340      /**
 341       * Updates the stopwatch data in the profile hierarchy.
 342       *
 343       * @param string $token          Profile token
 344       * @param bool   $updateChildren Whether to update the children altogether
 345       */
 346      private function updateProfiles($token, $updateChildren)
 347      {
 348          if (!$this->profiler || !$profile = $this->profiler->loadProfile($token)) {
 349              return;
 350          }
 351  
 352          $this->saveInfoInProfile($profile, $updateChildren);
 353      }
 354  
 355      /**
 356       * Update the profiles with the timing and events information and saves them.
 357       *
 358       * @param Profile $profile        The root profile
 359       * @param bool    $updateChildren Whether to update the children altogether
 360       */
 361      private function saveInfoInProfile(Profile $profile, $updateChildren)
 362      {
 363          try {
 364              $collector = $profile->getCollector('memory');
 365              $collector->updateMemoryUsage();
 366          } catch (\InvalidArgumentException $e) {
 367          }
 368  
 369          try {
 370              $collector = $profile->getCollector('time');
 371              $collector->setEvents($this->stopwatch->getSectionEvents($profile->getToken()));
 372          } catch (\InvalidArgumentException $e) {
 373          }
 374  
 375          try {
 376              $collector = $profile->getCollector('events');
 377              $collector->setCalledListeners($this->getCalledListeners());
 378              $collector->setNotCalledListeners($this->getNotCalledListeners());
 379          } catch (\InvalidArgumentException $e) {
 380          }
 381  
 382          $this->profiler->saveProfile($profile);
 383  
 384          if ($updateChildren) {
 385              foreach ($profile->getChildren() as $child) {
 386                  $this->saveInfoInProfile($child, true);
 387              }
 388          }
 389      }
 390  
 391      private function preDispatch($eventName, $eventId, Event $event)
 392      {
 393          // wrap all listeners before they are called
 394          $this->wrappedListeners[$eventId] = new \SplObjectStorage();
 395  
 396          $listeners = $this->dispatcher->getListeners($eventName);
 397  
 398          foreach ($listeners as $listener) {
 399              $this->dispatcher->removeListener($eventName, $listener);
 400              $wrapped = $this->wrapListener($eventName, $eventId, $listener);
 401              $this->wrappedListeners[$eventId][$wrapped] = $listener;
 402              $this->dispatcher->addListener($eventName, $wrapped);
 403          }
 404  
 405          switch ($eventName) {
 406              case KernelEvents::REQUEST:
 407                  $this->stopwatch->openSection();
 408                  break;
 409              case KernelEvents::VIEW:
 410              case KernelEvents::RESPONSE:
 411                  // stop only if a controller has been executed
 412                  if ($this->stopwatch->isStarted('controller')) {
 413                      $this->stopwatch->stop('controller');
 414                  }
 415                  break;
 416              case KernelEvents::TERMINATE:
 417                  $token = $event->getResponse()->headers->get('X-Debug-Token');
 418                  // There is a very special case when using builtin AppCache class as kernel wrapper, in the case
 419                  // of an ESI request leading to a `stale` response [B]  inside a `fresh` cached response [A].
 420                  // In this case, `$token` contains the [B] debug token, but the  open `stopwatch` section ID
 421                  // is equal to the [A] debug token. Trying to reopen section with the [B] token throws an exception
 422                  // which must be caught.
 423                  try {
 424                      $this->stopwatch->openSection($token);
 425                  } catch (\LogicException $e) {
 426                  }
 427                  break;
 428          }
 429      }
 430  
 431      private function postDispatch($eventName, $eventId, Event $event)
 432      {
 433          switch ($eventName) {
 434              case KernelEvents::CONTROLLER:
 435                  $this->stopwatch->start('controller', 'section');
 436                  break;
 437              case KernelEvents::RESPONSE:
 438                  $token = $event->getResponse()->headers->get('X-Debug-Token');
 439                  $this->stopwatch->stopSection($token);
 440                  if (HttpKernelInterface::MASTER_REQUEST === $event->getRequestType()) {
 441                      // The profiles can only be updated once they have been created
 442                      // that is after the 'kernel.response' event of the main request
 443                      $this->updateProfiles($token, true);
 444                  }
 445                  break;
 446              case KernelEvents::TERMINATE:
 447                  $token = $event->getResponse()->headers->get('X-Debug-Token');
 448                  // In the special case described in the `preDispatch` method above, the `$token` section
 449                  // does not exist, then closing it throws an exception which must be caught.
 450                  try {
 451                      $this->stopwatch->stopSection($token);
 452                  } catch (\LogicException $e) {
 453                  }
 454                  // The children profiles have been updated by the previous 'kernel.response'
 455                  // event. Only the root profile need to be updated with the 'kernel.terminate'
 456                  // timing information.
 457                  $this->updateProfiles($token, false);
 458                  break;
 459          }
 460  
 461          foreach ($this->wrappedListeners[$eventId] as $wrapped) {
 462              $this->dispatcher->removeListener($eventName, $wrapped);
 463              $this->dispatcher->addListener($eventName, $this->wrappedListeners[$eventId][$wrapped]);
 464          }
 465  
 466          unset($this->wrappedListeners[$eventId]);
 467      }
 468  
 469      private function wrapListener($eventName, $eventId, $listener)
 470      {
 471          $self = $this;
 472  
 473          return function (Event $event) use ($self, $eventName, $eventId, $listener) {
 474              $e = $self->preListenerCall($eventName, $eventId, $listener);
 475  
 476              call_user_func($listener, $event);
 477  
 478              $e->stop();
 479  
 480              if ($event->isPropagationStopped()) {
 481                  $self->logSkippedListeners($eventName, $eventId, $event, $listener);
 482              }
 483          };
 484      }
 485  
 486      private function unwrapListener($listener, $eventId)
 487      {
 488          // get the original listener
 489          if (is_object($listener)) {
 490              if (null === $eventId) {
 491                  foreach ($this->wrappedListeners as $eventId => $eventListeners) {
 492                      if (isset($eventListeners[$listener])) {
 493                          return $eventListeners[$listener];
 494                      }
 495                  }
 496              } elseif (isset($this->wrappedListeners[$eventId][$listener])) {
 497                  return $this->wrappedListeners[$eventId][$listener];
 498              }
 499          }
 500  
 501          return $listener;
 502      }
 503  }