16.2. Debugging (The definitive guide of Symfony 1.2)

No matter how proficient a coder you are, you will eventually make mistakes, even if you use symfony. Detecting and understanding errors is one of the keys of fast application development. Fortunately, symfony provides several debug tools for the developer.

16.2.1. Symfony Debug Mode

Symfony has a debug mode that facilitates application development and debugging. When it is on, the following happens:

The configuration is checked at each request, so a change in any of the configuration files has an immediate effect, without any need to clear the configuration cache.
The error messages display the full stack trace in a clear and useful way, so that you can more efficiently find the faulty element.
More debug tools are available (such as the detail of database queries).
The Propel debug mode is also activated, so any error in a call to a Propel object will display a detailed chain of calls through the Propel architecture.

On the other hand, when the debug mode is off, processing is handled as follows:

The YAML configuration files are parsed only once, then transformed into PHP files stored in the cache/config/ folder. Every request after the first one ignores the YAML files and uses the cached configuration instead. As a consequence, the processing of requests is much faster.
To allow a reprocessing of the configuration, you must manually clear the configuration cache.
An error during the processing of the request returns a response with code 500 (Internal Server Error), without any explanation of the internal cause of the problem.

The debug mode is activated per application in the front controller. It is controlled by the value of the third argument passed to the getApplicationConfiguration() method call, as shown in Listing 16-8.

Listing 16-8 - Sample Front Controller with Debug Mode On, in web/frontend_dev.php

<?php

require_once(dirname(__FILE__).'/../config/ProjectConfiguration.class.php');

$configuration = ProjectConfiguration::getApplicationConfiguration('frontend', 'dev', true);
sfContext::createInstance($configuration)->dispatch();

Caution In your production server, you should not activate the debug mode nor leave any front controller with debug mode on available. Not only will the debug mode slow down the page delivery, but it may also reveal the internals of your application. Even though the debug tools never reveal database connection information, the stack trace of exceptions is full of dangerous information for any ill-intentioned visitor.

16.2.2. Symfony Exceptions

When an exception occurs in the debug mode, symfony displays a useful exception notice that contains everything you need to find the cause of the problem.

The exception messages are clearly written and refer to the most probable cause of the problem. They often provide possible solutions to fix the problem, and for most common problems, the exception pages even contain a link to a symfony website page with more details about the exception. The exception page shows where the error occurred in the PHP code (with syntax highlighting), together with the full stack of method calls, as shown in Figure 16-1. You can follow the trace to the first call that caused the problem. The arguments that were passed to the methods are also shown.

Note Symfony really relies on PHP exceptions for error reporting, which is much better than the way PHP 4 applications work. For instance, the 404 error can be triggered by an sfError404Exception.

Figure 16.1 Sample exception message for a symfony application

During the development phase, the symfony exceptions will be of great use as you debug your application.

16.2.3. Xdebug Extension

The Xdebug PHP extension (http://xdebug.org/) allows you to extend the amount of information that is logged by the web server. Symfony integrates the Xdebug messages in its own debug feedback, so it is a good idea to activate this extension when you debug the application. The extension installation depends very much on your platform; refer to the Xdebug website for detailed installation guidelines. Once Xdebug is installed, you need to activate it manually in your php.ini file after installation. For *nix platforms, this is done by adding the following line:

zend_extension="/usr/local/lib/php/extensions/no-debug-non-zts-20041030/xdebug.so"

For Windows platforms, the Xdebug activation is triggered by this line:

extension=php_xdebug.dll

Listing 16-9 gives an example of Xdebug configuration, which must also be added to the php.ini file.

Listing 16-9 - Sample Xdebug Configuration

;xdebug.profiler_enable=1
;xdebug.profiler_output_dir="/tmp/xdebug"
xdebug.auto_trace=1             ; enable tracing
xdebug.trace_format=0
;xdebug.show_mem_delta=0        ; memory difference
;xdebug.show_local_vars=1
;xdebug.max_nesting_level=100

You must restart your web server for the Xdebug mode to be activated.

Caution Don't forget to deactivate Xdebug mode in your production platform. Not doing so will slow down the execution of every page a lot.

The log files contain interesting information, but they are not very easy to read. The most basic task, which is to find the lines logged for a particular request, can be quite tricky if you have several users simultaneously using an application and a long history of events. That's when you start to need a web debug toolbar.

This toolbar appears as a semitransparent box superimposed over the normal content in the browser, in the top-right corner of the window, as shown in Figure 16-2. It gives access to the symfony log events, the current configuration, the properties of the request and response objects, the details of the database queries issued by the request, and a chart of processing times related to the request.

Figure 16.2 The web debug toolbar appears in the top-right corner of the window

The color of the debug toolbar background depends on the highest level of log message issued during the request. If no message passes the debug level, the toolbar has a gray background. If a single message reaches the err level, the toolbar has a red background.

Note Don't confuse the debug mode with the web debug toolbar. The debug toolbar can be displayed even when the debug mode if off, although, in that case, it displays much less information.

To activate the web debug toolbar for an application, open the settings.yml file and look for the web_debug key. In the prod and test environments, the default value for web_debug is off, so you need to activate it manually if you want it. In the dev environment, the default configuration has it set to on, as shown in Listing 16-10.

Listing 16-10 - Web Debug Toolbar Activation, in frontend/config/settings.yml

dev:
  .settings:
    web_debug:              on

When displayed, the web debug toolbar offers a lot of information/interaction:

Click the symfony logo to toggle the visibility of the toolbar. When reduced, the toolbar doesn't hide the elements located at the top of the page.
Click the vars & config section to show the details of the request, response, settings, globals, and PHP properties, as shown in Figure 16-3. The top line sums up the important configuration settings, such as the debug mode, the cache, and the presence of a PHP accelerator (they appear in red if they are deactivated and in green if they are activated).

Figure 16.3 The vars & config section shows all the variables and constants of the request

When the cache is enabled, a green arrow appears in the toolbar. Click this arrow to reprocess the page, regardless of what is stored in the cache (but the cache is not cleared).
Click the logs & msgs section to reveal the log messages for the current request, as shown in Figure 16-4. According to the importance of the events, they are displayed in gray, yellow, or red lines. You can filter the events that are displayed by category using the links displayed at the top of the list.

Figure 16.4 The logs & msgs section shows the log messages for the current request

Note When the current action results from a redirect, only the logs of the latest request are present in the logs & msgs pane, so the log files are still indispensable for good debugging.

For requests executing SQL queries, a database icon appears in the toolbar. Click it to see the detail of the queries, as shown in Figure 16-5.
To the right of a clock icon is the total time necessary to process the request. Be aware that the web debug toolbar and the debug mode slow down the request execution, so try to refrain from considering the timings per se, and pay attention to only the differences between the execution time of two pages. Click the clock icon to see details of the processing time category by category, as shown in Figure 16-6. Symfony displays the time spent on specific parts of the request processing. Only the times related to the current request make sense for an optimization, so the time spent in the symfony core is not displayed. That's why these times don't sum up to the total time.
Click the red x at the right end of the toolbar to hide the toolbar.

Figure 16.5 The database queries section shows queries executed for the current request

Figure 16.6 The clock icon shows execution time by category

Adding your own timer Symfony uses the sfTimer class to calculate the time spent on the configuration, the model, the action, and the view. Using the same object, you can time a custom process and display the result with the other timers in the web debug toolbar. This can be very useful when you work on performance optimizations.

To initialize timing on a specific fragment of code, call the getTimer() method. It will return an sfTimer object and start the timing. Call the addTime() method on this object to stop the timing. The elapsed time is available through the getElapsedTime() method, and displayed in the web debug toolbar with the others.

// Initialize the timer and start timing
$timer = sfTimerManager::getTimer('myTimer');

// Do things
...

// Stop the timer and add the elapsed time
$timer->addTime();

// Get the result (and stop the timer if not already stopped)
$elapsedTime = $timer->getElapsedTime();

The benefit of giving a name to each timer is that you can call it several times to accumulate timings. For instance, if the myTimer timer is used in a utility method that is called twice per request, the second call to the getTimer('myTimer') method will restart the timing from the point calculated when addTime() was last called, so the timing will add up to the previous one. Calling getCalls() on the timer object will give you the number of times the timer was launched, and this data is also displayed in the web debug toolbar.

// Get the number of calls to the timer
$nbCalls = $timer->getCalls();

In Xdebug mode, the log messages are much richer. All the PHP script files and the functions that are called are logged, and symfony knows how to link this information with its internal log. Each line of the log messages table has a double-arrow button, which you can click to see further details about the related request. If something goes wrong, the Xdebug mode gives you the maximum amount of detail to find out why.

Note The web debug toolbar is not included by default in Ajax responses and documents that have a non-HTML content-type. For the other pages, you can disable the web debug toolbar manually from within an action by simply calling sfConfig::set('sf_web_debug', false).

16.2.5. Manual Debugging

Getting access to the framework debug messages is nice, but being able to log your own messages is better. Symfony provides shortcuts, accessible from both actions and templates, to help you trace events and/or values during request execution.

Your custom log messages appear in the symfony log file as well as in the web debug toolbar, just like regular events. (Listing 16-5 gave an example of the custom log message syntax.) A custom message is a good way to check the value of a variable from a template, for instance. Listing 16-11 shows how to use the web debug toolbar for developer's feedback from a template (you can also use $this->logMessage() from an action).

Listing 16-11 - Inserting a Message in the Log for Debugging Purposes

<?php use_helper('Debug') ?>
...
<?php if ($problem): ?>
  <?php log_message('{sfAction} been there', 'err') ?>
  ...
<?php endif ?>

The use of the err level guarantees that the event will be clearly visible in the list of messages, as shown in Figure 16-7.

Figure 16.7 A custom log message appears in the logs & msgs section of the web debug toolbar

If you don't want to add a line to the log, but just trace a short message or a value, you should use debug_message instead of log_message. This action method (a helper with the same name also exists) displays a message in the web debug toolbar, on top of the logs & msgs section. Check Listing 16-12 for an example of using the debug message writer.

Listing 16-12 - Inserting a Message in the Debug Toolbar

// From an action
$this->debugMessage($message);

// From a template
<?php use_helper('Debug') ?>
<?php debug_message($message) ?>

16.2. Debugging

16.2.1. Symfony Debug Mode

16.2.2. Symfony Exceptions

16.2.3. Xdebug Extension

16.2.4. Web Debug Toolbar

16.2.5. Manual Debugging