How to debug a “Maximum execution time” fatal error?

Question

I'm trying to use Zend_acl in my application. I followed the "Zend Framework in action" book. I added this helper:

<?php
/**
* Zend Framework
*
* LICENSE "removed for clarity"
*

/** Zend_Controller_Action_Helper_Abstract */
require_once 'Zend/Controller/Action/Helper/Abstract.php';



class Bravo_Controller_Action_Helper_Acl extends Zend_Controller_Action_Helper_Abstract
{

    protected $_action;

    protected $_auth;

    protected $_acl;

    protected $_controllerName;

    public function __construct(Zend_View_Interface $view = null, array $options = array())
    {
        $this->_auth = Zend_Auth::getInstance();
        $this->_acl = $options['acl'];
        //var_dump($this->_acl);die();
    }

    public function init()
    {
        $this->_action = $this->getActionController();

        // add resource for this controller
        $controller = $this->_action->getRequest()->getControllerName();
        if(!$this->_acl->has($controller)) {
            $this->_acl->add(new Zend_Acl_Resource($controller));
        }

    }

    public function preDispatch()
    {
        $role = 'guest';
        if ($this->_auth->hasIdentity()) {
            $user = $this->_auth->getIdentity();
            if(is_object($user)) {
                $role = $this->_auth->getIdentity()->getUral()->getUralAccessNbr();
            }
        }

        $request = $this->_action->getRequest();
        $controller = $request->getControllerName();
        $action = $request->getActionName();
        $module = $request->getModuleName();
        $this->_controllerName = $controller;

        $resource = $controller;
        $privilege = $action;

        if (!$this->_acl->has($resource)) {
            $resource = null;
        }

        //** EDIT: During my test, the user isn't allowed. I'm now suspecting the 4 requests setting to be wrong.
        if (!$this->_acl->isAllowed($role, $resource, $privilege)) {
            $request->setModuleName('default');
            $request->setControllerName('login');
            $request->setActionName('login');
            $request->setDispatched(false);            
        }

    }


    public function allow($roles = null, $actions = null)
    {
        $resource = $this->_controllerName;
        $this->_acl->allow($roles, $resource, $actions);
        return $this;
    }

    public function deny($roles = null, $actions = null)
    {
        $resource = $this->_controllerName;
        $this->_acl->deny($roles, $resource, $actions);
       return $this;
    }

}

And bootstrap:

<?php

class Agenda_Bootstrap extends Zend_Application_Module_Bootstrap
{

    protected function _initAcl()
    {

        // acl action helper
        $acl = new Bravo_Acl_Acl();
        $aclHelper = new Bravo_Controller_Action_Helper_Acl(null, array('acl' => $acl));
        Zend_Controller_Action_HelperBroker::addHelper($aclHelper);
    }
}

The Helper isn't use in the controller. I tried my app to see if all was right and I got this error:

Fatal error: Maximum execution time of 30 seconds exceeded in /usr/share/php/ZendFramework-1.11.11/Zend/Filter/PregReplace.php on line 171

With this call stack:

Call Stack
#   Time    Memory  Function                                                Location
1   0.0001  314556  {main}( )                                               ../index.php:0
2   0.3275  2039356 Zend_Application->run( )                                ../index.php:29
3   0.3275  2039356 Zend_Application_Bootstrap_Bootstrap->run( )                ../Application.php:366
4   0.3276  2039412 Zend_Controller_Front->dispatch( )                      ../Bootstrap.php:97
5   31.7462 4813252 Zend_Controller_Dispatcher_Standard->dispatch( )        ../Front.php:954
6   31.7470 4813944 Zend_Controller_Action->__construct( )                      ../Standard.php:268
7   31.7470 4814144 Zend_Controller_Action_HelperBroker->__construct( )     ../Action.php:132
8   31.7472 4814924 Zend_Controller_Action_Helper_ViewRenderer->init( )     ../HelperBroker.php:253
9   31.7472 4814924 Zend_Controller_Action_Helper_ViewRenderer->initView( )     ../ViewRenderer.php:516
10  31.7473 4815260 Zend_Controller_Action_Helper_ViewRenderer->_getBasePath( ) ../ViewRenderer.php:469
11  31.7478 4815628 Zend_Filter_Inflector->filter( )                        ../ViewRenderer.php:393
12  31.7489 4816768 Zend_Filter_Word_CamelCaseToSeparator->filter( )        ../Inflector.php:473
13  31.7489 4816768 Zend_Filter_PregReplace->filter( )               ../CamelCaseToSeparator.php:46

I tried to increase the max_execution_time, but it's always the same: the first four stacks still unchanged and the fifth reflect the max_execution_time (30 sec => 31.7462, 40 sec => 42.6546 and so on)

So I suspect the Zend_Controller_Front->dispatch( ) to be my source of problem, but why it take always the max time? I'm a bit confused. Someone have some idea of where I should dig?

EDIT: I'm going further in my debug. I'm now suspecting the 4 requests setting to be wrong in my helper when the user isn't allowed. I edited the helper code too and added a comment.

EDIT2: Patrik, you're so right!!! I rechecked and I had fall in an infinite loop: don't-have-acces-to-login-page => go-to-login-page :-D What a waste of time today... anyway it ends well thanks everybody.

Answer 1

if (!$this->_acl->isAllowed($role, $resource, $privilege)) {
    $request->setModuleName('default');
    $request->setControllerName('login');
    $request->setActionName('login');
    $request->setDispatched(false);            
}

Are you sure that you always have permission to access the login-controller regardless of role?

Anyway, it sounds like you end up in an infinite loop, where the dispatch-loop of ZF is never completed.

Answer 2

In case a debugger isn't available, you could use pure PHP code. Here is an option, using a small helper class called CSysTracer.

Based on this interface:

abstract class CSTReportDelegate {

    abstract public function emitVariableChange( $variableName, $oldValue, $newValue );
    abstract public function emitVariableSetNew( $variableName, $newValue );

}

created this concrete instance

class CSTSimpleReportDelegate extends CSTReportDelegate {

    public function emitVariableChange( $variableName, $oldValue, $newValue ) {
        echo '<br />[global/change] '. $variableName . ' : ' . print_r( $oldValue, true ) . ' &rarr; ' . print_r( $newValue, true );
    }

    public function emitVariableSetNew( $variableName, $newValue ) {
        echo '<br />[global/init] '. $variableName . '   &rarr; ' . print_r( $newValue, TRUE );
    }

}

... pass it to CSysTracer:

CSysTracer::setReportDelegate( new CSTSimpleReportDelegate() );

... and enable statement tracing using this:

CSysTracer::start( 5 );

While CSTSimpleReportDelegate prints output, it could write stuff to a log file and and e.g. do selective writes on certain statements.

Note, that this version of CSysTracer tracks changes of global variable. Rewriting it to log each statement is quite simple.

CSysTracer does the trick using PHP's tick function:

class CSysTracer {

    static protected 
        $reportDelegate;

    static private 
        $globalState = array();

    static private  
        $traceableGlobals = array();

    static private 
        $globalTraceEnabled = FALSE;

    const 
        DEFAULT_TICK_AMOUNT = 1;

    static public 
    function setReportDelegate( CSTReportDelegate $aDelegate ) {
        self::$reportDelegate = $aDelegate;
    }


    static public 
    function start( $tickAmount = self::DEFAULT_TICK_AMOUNT ) {

        register_tick_function ( array( 'CSysTracer', 'handleTick' ) );

    }


    static public 
    function stop() {

        unregister_tick_function( array( 'CSysTracer', 'handleTick' ) );

    }

    static public 
    function evalAndTrace( $someStatement ) {

        declare( ticks = 1 ); {
            self::start();
            eval( $someStatement );
            self::stop();
        }
    }

    static public 
    function addTraceableGlobal( $varName ) {

        if ( is_array( $varName )) {
            foreach( $varName as $singleName ) {
                self::addTraceableGlobal( $singleName ); 
            }
            return;
        }

        self::$traceableGlobals[ $varName ] = $varName;

    }

    static public 
    function removeTraceableGlobal( $varName ) {
        unset( self::$traceableGlobals[ $varName ] );   
    }

    /**
     * Main function called at each tick. Calls those functions, which
     * really perform the checks.
     * 
     */
    static public 
    function handleTick( ) {

        if ( TRUE === self::$globalTraceEnabled ) { 
            self::traceGlobalVariable();
        }

    }

    static public 
    function enableGlobalsTrace() {
        self::$globalTraceEnabled = TRUE;   
    }


    static public 
    function disableGlobalsTrace() {
        self::$globalTraceEnabled = FALSE;  
    }

    static public 
    function traceGlobalVariable( ) {

        foreach( self::$traceableGlobals as $aVarname ) {

            if ( ! isset( $GLOBALS[ $aVarname ] )) {
                continue;
            }

            if ( ! isset( self::$globalState[ $aVarname ] ) ) {

                self::$reportDelegate->emitVariableSetNew( $aVarname, $GLOBALS[ $aVarname ] );
                self::$globalState[ $aVarname ] = $GLOBALS[ $aVarname ];
                continue;
            }

           if ( self::$globalState[ $aVarname ] !== $GLOBALS[ $aVarname ]) {

             self::$reportDelegate->emitVariableChange( $aVarname, self::$globalState[ $aVarname ], $GLOBALS[ $aVarname ] );

           }

           self::$globalState[ $aVarname ] = $GLOBALS[ $aVarname ];

        }

    }

}