cakephp: Log event triggers and listeners for debugging

I’m not sure if there is already another way of doing this but I’ve modified the EventManager to create a log of the triggered events and the listeners that listened to them.

This is not a final implementation but a draft. You can simply copy and paste it and it will start logging if you configured a logger for the events scope.

This would allow you to log the events at runtime to a console for example. This is useful for development, especially if you have people in your team who have a hard time understanding and debugging events.

    use LogTrait;

    /**
     * {@inheritDoc}
     */
    public function dispatch($event)
    {
        if (is_string($event)) {
            $event = new Event($event);
        }

        $this->_logTrigger($event);
        $listeners = $this->listeners($event->getName());

        if ($this->_trackEvents) {
            $this->addEventToList($event);
        }

        if (!$this->_isGlobal && static::instance()->isTrackingEvents()) {
            static::instance()->addEventToList($event);
        }

        if (empty($listeners)) {
            return $event;
        }

        foreach ($listeners as $listener) {
            if ($event->isStopped()) {
                break;
            }
            $result = $this->_callListener($listener['callable'], $event);
            $this->_logListener($listener);

            if ($result === false) {
                $event->stopPropagation();
            }
            if ($result !== null) {
                $event->setResult($result);
            }
        }

        return $event;
    }

    protected function _logTrigger($event)
    {
        $trace = debug_backtrace(DEBUG_BACKTRACE_PROVIDE_OBJECT, 3);
        $this->log(sprintf(
            'Event `%s` triggered, subject is `%s`',
            $event->getName(),
            get_class($event->getSubject())
        ), LogLevel::INFO, ['events']);
        $this->log(sprintf(
            'Triggered in `%s` on line %d',
            $trace[2]['file'],
            $trace[2]['line']
        ), LogLevel::INFO, ['events']);
    }

    protected function _logListener($listener)
    {
        $logMsgString = ' - Listener `%s` listened to it';

        if ($listener['callable'] instanceof \Closure) {
            $reflection = new \ReflectionFunction($listener['callable']);
            $logMsg = sprintf(
                ' - A Closure in `%s` on line %d was listening to it',
                $reflection->getFileName(),
                $reflection->getStartLine()
            );
            $this->log($logMsg, LogLevel::INFO, ['events']);
        } elseif (is_array($listener['callable']) && count($listener['callable']) === 2) {
            $logMsg = sprintf($logMsgString, get_class($listener['callable'][0]) . '::' . $listener['callable'][1] . '()');
            $this->log($logMsg, LogLevel::INFO, ['events']);
        } else {
            $logMsg = sprintf($logMsgString, get_class($listener['callable']));
            $this->log($logMsg, LogLevel::INFO, ['events']);
        }
    }

This will produce a log like this (just an excerpt of it):

2019-01-17 12:01:35 Info: Event `Server.buildMiddleware` triggered, subject is `Cake\Http\Server`
2019-01-17 12:01:35 Info: Triggered in `\vendor\cakephp\cakephp\src\Http\Server.php` on line 95
2019-01-17 12:01:35 Info:  - A Closure in `\vendor\ozee31\cakephp-cors\config\bootstrap.php` on line 27 was listening to it
2019-01-17 12:01:35 Info:  - A Closure in `\vendor\cakephp\debug_kit\config\bootstrap.php` on line 56 was listening to it
2019-01-17 12:01:35 Info: Event `Model.initialize` triggered, subject is `App\Model\Table\DomainsTable`
2019-01-17 12:01:35 Info: Triggered in `\vendor\cakephp\cakephp\src\ORM\Table.php` on line 300
2019-01-17 12:01:35 Info:  - A Closure in `\config\bootstrap.php` on line 467 was listening to it
2019-01-17 12:01:35 Info: Event `Model.initialize` triggered, subject is `App\Model\Table\LanguagesTable`
2019-01-17 12:01:35 Info: Triggered in `\vendor\cakephp\cakephp\src\ORM\Table.php` on line 300
2019-01-17 12:01:35 Info:  - A Closure in `\config\bootstrap.php` on line 467 was listening to it
2019-01-17 12:01:36 Info: Event `Dispatcher.beforeDispatch` triggered, subject is `Cake\Http\ActionDispatcher`
2019-01-17 12:01:36 Info: Triggered in `\vendor\cakephp\cakephp\src\Http\ActionDispatcher.php` on line 79
2019-01-17 12:01:36 Info: Event `Dispatcher.invokeController` triggered, subject is `Cake\Http\ActionDispatcher`
2019-01-17 12:01:36 Info: Triggered in `\vendor\cakephp\cakephp\src\Http\ActionDispatcher.php` on line 113
2019-01-17 12:01:36 Info: Event `Controller.initialize` triggered, subject is `App\Controller\LandingPageController`
2019-01-17 12:01:36 Info: Triggered in `\vendor\cakephp\cakephp\src\Controller\Controller.php` on line 671
2019-01-17 12:01:36 Info:  - A Closure in `\vendor\cakephp\debug_kit\src\Panel\TimerPanel.php` on line 52 was listening to it
2019-01-17 12:01:36 Info:  - A Closure in `\vendor\cakephp\debug_kit\src\Panel\TimerPanel.php` on line 34 was listening to it