Debugging with FirePHP

It's actually pretty easy to get this working, I did have to make one change to the Wildfire library though when I first started using it in order to get it behaving as I expected. I opened a bug which was resolved before 1.6 rolled out the door. In setting this up, I wanted the debugging to be as transparent as possible, one of the great things about Zend_Log is the ability to add filters to the individual writers so that the main log writer that writes things out to a file can ignore log messages with a priority of debug or info quite easily. This means that on production we can just not include the Firebug writer and we can rest assured that no sensitive information is being sent to the browser.

Okay, lets break down what I have done:

1. I changed the Error Controller so that it logs exceptions
2. I added a profiler to my Db class
3. I added a custom Memcached class so that I could ask it for stats
4. I modified my application environment so that it could know if was in production or development
5. I have the Workspace logging init add the Firebug logger if we are in dev
6. I added the Debug Front Controller plugin so that I could log stuff like action exec times etc
7. I installed the FirePHP extension for Firefox
8. I enabled console and net for my site in Firebug
9. I saw glorious debug info and went to get a beer to celebrate.

Although it's great for developers to have this look into your applications inner workings, in the wrong hands this kind of information can lead to your site getting seriously p0wned. In order to prevent this, I don't even add the FirePHP writer to Zend_Log if I am not in a development environment. Here's how I accomplish this in my Workspace logger init method:
public function initLogger() { if (! $this->logger instanceof Zend_Log) { $logConfig = $this->environment->config->log; $stdWriter = new Zend_Log_Writer_Stream($logConfig->path); // Don't bother to log anything with a log level lower than Notice $stdWriter->addFilter(new Zend_Log_Filter_Priority(Zend_Log::NOTICE)); $logger = new Zend_Log($stdWriter); // If we are not in production, send logging info to FirePHP if ($this->environment->isDevEnvironment() && ! $this->environment->isCLI()) { $debugWriter = new Zend_Log_Writer_Firebug(); // Add the logger style "table" so we can render tables of data $debugWriter->setPriorityStyle(8, 'TABLE'); $logger->addPriority('TABULAR', 8); $logger->addWriter($debugWriter); } $this->logger = $logger; } }
Here's what my controller plugin looks like:
class Naked_Controller_Plugin_Debug extends Zend_Controller_Plugin_Abstract { /** * @var float $dispatchStartTime */ protected $dispatchStartTime; /** * @var float $actionStartTime */ protected $actionStartTime; /** * @var array $initialMemcachedStats */ protected $initialMemcachedStats; /** * Record the start time for the dispatch loop startup * * @param Zend_Controller_Request_Abstract $request * @return null */ public function dispatchLoopStartup(Zend_Controller_Request_Abstract $request) { $this->dispatchStartTime = array_sum(explode(' ', microtime())); // Only try to get stats if caching is enabled if (Naked_App::getEnvironment()->isCacheEnabled()) { $this->initialMemcachedStats = Naked_App::getWorkspace()->getCache()->getStats(); } else { Naked_App::getWorkspace()->getLogger()->debug('Memcached is disabled'); } } /** * record the start time for the current action */ public function preDispatch(Zend_Controller_Request_Abstract $request) { $this->actionStartTime = array_sum(explode(' ', microtime())); } /** * Log the execution time for the current action */ public function postDispatch(Zend_Controller_Request_Abstract $request) { $execTime = array_sum(explode(' ', microtime())) - $this->actionStartTime; $action = $request->getModuleName() .'::'.$request->getControllerName().'::'.$request->getActionName(); Naked_App::getWorkspace()->getLogger()->debug("{$action} action took $execTime seconds to execute"); } /** * Log the total execution time for the dispatch loop and display all other * debug information */ public function dispatchLoopShutdown() { $this->debugSession(); $this->debugMemcached(); $this->debugDatabase(); $execTime = array_sum(explode(' ', microtime())) - $this->dispatchStartTime; Naked_App::getWorkspace()->getLogger()->debug("Script took $execTime seconds to execute"); } /** * Log the session contents */ protected function debugSession() { $table = array ( 'Session', array( array('Namespace', 'Values') ) ); foreach ($_SESSION as $namespace=>$values) { $table[1][] = array($namespace, $values); } Naked_App::getWorkspace()->getLogger()->tabular($table); } /** * Debug memcached */ protected function debugMemcached() { if (! Naked_App::getEnvironment()->isCacheEnabled()) { Naked_App::getWorkspace()->getLogger()->debug('Memcache is DISABLED'); return; } $table = array ( 'Memcached', array( array('Property', 'Value') ) ); $stats = Naked_App::getWorkspace()->getCache()->getStats(); foreach ($stats as $server => $data) { $table[1][] = array($server); $table[1][] = array('Items in cache', number_format($data['curr_items'])); $table[1][] = array('Memory usage', number_format($data['bytes']) . ' bytes'); $getsThisRequest = $data['cmd_get'] - $this->initialMemcachedStats[$server]['cmd_get']; $table[1][] = array('Gets', number_format($data['cmd_get']) . '(' . $getsThisRequest . ')'); $missesThisRequest = $data['get_misses'] - $this->initialMemcachedStats[$server]['get_misses']; $table[1][] = array('Get misses', number_format($data['get_misses']) . '(' . $missesThisRequest . ')'); $setsThisRequest = $data['cmd_set'] - $this->initialMemcachedStats[$server]['cmd_set']; $table[1][] = array('Sets', number_format($data['cmd_set']) . '(' . $setsThisRequest . ')'); } Naked_App::getWorkspace()->getLogger()->tabular($table); } /** * Using the Database profiler, output some helpful information concerning * database interaction. */ protected function debugDatabase() { $logger = Naked_App::getWorkspace()->getLogger(); $db = Naked_App::getWorkspace()->getDb(); $profiles = $db->getProfiler()->getProfiles(); foreach ($profiles as $queryId => $profile) { $logger->debug("Executed query $queryId : {$profile['sql']}"); $logger->debug("Query $queryId took {$profile['elapsed']} seconds and involved {$profile['num_rows']} rows"); $explain = array( 'Explanation of plan for query #' . $queryId, array( array('id', 'Select Type', 'Table ', 'Type', 'Possible Keys', 'Key Used', 'Key Length', 'Ref Type', '# Rows', 'Extra') ) ); // Some query types will throw exceptions when an explain is attempted try { foreach ($db->getProfiler()->getExplainPlan($queryId) as $explainRecord) { $explain[1][] = array_values(get_object_vars($explainRecord)); } $logger->tabular($explain); } catch (Naked_Db_Exception $e) { $logger->debug("An execution plan for query # {$queryId} could not be retrieved: {$e->getMessage()}"); } } } }
The items that are logged are as follows:

1. The full paths to all view scripts that have been rendered - including layouts
2. The Module::controller::actions performed as well as how long it took to perform each action
3. An expandable table with the contents of the current user session
4. An expandable table of the current memcached stats. If memached has been disabled, it will indicate such. Numbers in parenthesis indicates the number of each operation that occured during the current request. This is a great way to ensure that the cache is actually working properly.
5. A timing of the requests entire processing time. This is basically measured as the difference between the dispatchLoopStartup and dispatchLoopShutdown events.
6. Any exceptions that were encountered are sent to the debug console with an expandable tree for the traceback.
7. The last and perhaps most import part of the debug console is the SQL query profiling. For each query that is run, the debug console dumps the query itself as well as the execution time for that SQL query. it also includes an explain plan of that query in an expandable table format so that you can see what decisions the MySQL optimizer made when it processed your query. This can be a quick way to look for "using key: none" or "temporary table" inefficiencies in your queries.

The added visibility into your application's inner workings in such a non-intrusive way are indispensable to me when developing. Once you use it in your own applications I am sure you will feel the same way.