How to debug a project

Overview

No matter how good a coder you are, you will face errors one day or another - even if you use symfony. Detecting and understanding errors is one key of fast application development. Fortunately, symfony provides several debug tools for the developer.

Debug modes

Symfony debug mode

Symfony has a debug mode that facilitates the development and the debug. When it is on, the configuration is parsed at each request, so a change in the configuration has an immediate effect, without any need to clear the config cache folder. In order to prevent the production environment from being able to ignore any existing HTML cache this ability is only available in debug mode. (You can learn more about the cache feature in the related chapter). Eventually, the symfony debug mode activates the Propel debug mode, so any error in a call to a propel object will display a detailed chain of calls.

As the debug mode has to be set very early in the process of answering a request, it is not defined in a YAML configuration file but in the front controller. For instance, if your main application is called myapp, you probably have in the myproject/web two PHP scripts with a different debug mode configuration:

// in index.php, the production front controller,
// the debug mode is deactivated
define('SF_DEBUG', false);
//in myapp_dev.php, the development front controller,
// the debug mode is activated
define('SF_DEBUG', true);

With this configuration, not only will the production environment be faster, but it will also be protected from a few debug features (including the web debug toolbar, see below) that must not be given to end users for the sake of the application.

XDebug mode

The XDebug extension 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 it when you debug the application. Unfortunately, the extension installation - and configuration - depends very much on your platform, so you need to activate/deactivate it manually in your php.ini file after installation.

An example configuration for this extension could be (*nix platform):

;...
zend_extension="/usr/local/lib/php/extensions/no-debug-non-zts-20041030/xdebug.so"
;xdebug.profiler_enable=1
;xdebug.profiler_output_dir="/tmp/xdebug"
xdebug.auto_trace=On            ; enable tracing
xdebug.trace_format=0
;xdebug.show_mem_delta=0        ; memory difference
;xdebug.show_local_vars=1
;xdebug.max_nesting_level=100

In a Windows installation, you just need to add the following line to the Dynamic Extensions section:

extension=php_xdebug.dll

You have to restart you web server for the XDebug mode being activated.

Don't forget to deactivate the XDebug mode in your production platform.

Log files

The only way to understand what went wrong during the execution of a request is to have information about the various steps of the execution. Fortunately, your web server and symfony have the good habit of logging lots of data that can be used for debugging into files.

Web server log level configuration

First of all, a little reminder: PHP has a parameter error_reporting, defined in the php.ini, that defines which events are logged. Symfony allows you to override this value for each application by setting a specific error_reporting in the settings.yml file:

prod:
 .settings:
    error_reporting:  257

dev:
  settings:
    error_reporting:  4095

The numbers are a short way of writing error levels (refer to the PHP documentation on error reporting for more details about it). Basically, 4095 is a shortcut for E_ALL | E_STRICT, and 257 stands for E_ERROR | E_USER_ERROR (the default value for every new environment).

In the production environment to avoid execution slow-downs, only the critical PHP errors are logged by the server; but in the development environment, all the types of event are logged so that the developer can have all the necessary information to trace errors.

The location of the server log files depends on your installation, but they are often in a directory called logs in the web server tree structure.

Symfony log files

In addition to the classic PHP logs, symfony can trace a lot of custom events. These symfony logs can all be found under the myproject/log/ directory. There is one file per application and per environment; the development environment log file of the myapp application is named fo_dev.log, the production one is named myapp_prod.log, and so on.

If you have a symfony application running, take a look at its log files. The syntax is very simple: for every event, one line is added to the log file of the application, where the exact time of the event, the nature of the event, the object being processed and the details of the process are written. Here is an example:

Nov 15 16:30:25 symfony [info] {sfActions} call "barActions->executemessages()"
Nov 15 16:30:25 symfony [debug] SELECT bd_message.ID, bd_message.SENDER_ID, bd_message.RECIPIENT_ID, bd_message.SEND_DATE, bd_message.TITLE, bd_message.BODY, bd_message.IS_READ FROM bd_message WHERE bd_message.RECIPIENT_ID=? AND bd_message.IS_READ=? [LIMIT: 0, OFFSET: 0]
Nov 15 16:30:25 symfony [info] {sfCreole} executeQuery(): SELECT bd_message.ID, bd_message.SENDER_ID, bd_message.RECIPIENT_ID, bd_message.SEND_DATE, bd_message.TITLE, bd_message.BODY, bd_message.IS_READ FROM bd_message WHERE bd_message.RECIPIENT_ID=3 AND bd_message.IS_READ=0
Nov 15 16:30:25 symfony [info] {sfRenderView} set slot "leftbar" (bar/index)
Nov 15 16:30:25 symfony [info] {sfRenderView} set slot "messageblock" (bar/messages)
Nov 15 16:30:25 symfony [info] {sfRenderView} execute view for template "messagesSuccess.php"
Nov 15 16:30:25 symfony [info] {sfPHPView} render "/home/production/myproject/fo/modules/bar/templates/messagesSuccess.php"
Nov 15 16:30:25 symfony [info] {sfPHPView} render to client
Nov 15 16:30:25 symfony [error] {sfActionStopException}

Lots of information can be found in these files, including the actual SQL queries sent to the database, the templates called, the chain of calls between objects, and so on. You can easily add your own logs, as explained later in this chapter.

By the way, don't forget to periodically purge the log/ directory of your applications, because theses files have the strange habit of growing by several megabytes in a few days - depending, of course, on your traffic.

Symfony log level configuration

There are 8 levels of log messages: emerg, alert, crit, err, warning, notice, info and debug, which are the classical levels of the [PEAR_Log package][3]. You can configure the maximum level to be logged in each environment in the logging.yml configuration file of each application. Here is the content of the default configuration:

prod:
  level:  err

dev:

test:

all:
#  active: on
#  level:  debug

This means that the symfony logging mechanism is active by default in all environments (but can be deactivated). In all environments except the production one, all the messages are logged (up to the least important level - the debug level). In production, only the most important messages are logged. You can change the level in this file for each environment to limit the type of logged messages.

The value of these parameters is accessible during execution through sfConfig::get('sf_logging_active') and sfConfig::get('sf_logging_level').

Web debug

The log files contain interesting information, but are not very easy to read. The most basic task, which is to find the lines logged for a particular page, can be quite tricky if you have several users working with an application. That's when you start to need a web debug toolbar.

Main configuration

To activate the web debug toolbar for an application, open the settings.yml and look for the web_debug key. Its default value is off, so you need to activate it manually if you want it - except in the dev environment where the default configuration has it set to on:

dev:
  .settings:
    web_debug:              on

Next time you display a page in an environment with web debug toolbar enabled, you will see a semi-transparent box on the top right corner of the window, showing the value of a few important settings:

To hide it, press the red cross button on the top right corner.

You can deactivate the web debug toolbar manually from within an action by simply changing this setting:

sfConfig::set('sf_web_debug', false);

Log messages

All the messages logged in the symfony log file for the current request are accessible with the web debug toolbar: just press the information bubble to display a list of the messages:

The top bar contains filter links that allow you to toggle the visibility of messages of a certain type. By default, all the messages are visible, so clicking on the 'sfActions' link will hide the sfActions-labeled messages.

The 'ms' column displays the time elapsed between each message, which is roughly equivalent to the execution time of the related method call. This should help you to find the longest sequences of each request - and optimize it.

The red cross closes the log messages table.

Log messages in XDebug mode

In XDebug mode, the log messages are much richer. Each line of the log messages table has a double-arrow button which, when pressed, reveals further details about the related request:

All the PHP script files and the functions that are called are logged in XDebug mode, and symfony knows how to link this information with its internal log. If something goes wrong, the XDebug mode gives you the maximum detail to find out why.

Manual debugging

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

Adding a log message

You can manually add a message in the log file (and, consequently, to the log messages table):

// in an action
$this->logMessage($message, $level);
// in a template
<?php echo log_message($message, $level) ?>

If you use the template version, don't forget to declare the Debug helper with use_helper('Debug'). The $level can have the same values as in the log messages (emerg, alert, crit, err, warning, notice, info and debug). For instance, if your indexSuccess.php template of the main module looks like:

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

...then if you have a $problem the web debug toolbar will show:

The red color of the header shows that at least one message of err level was raised. Click on the information bubble icon to display the messages. The list will contain:

Alternatively, to write a message in the log from anywhere in your application, use the following syntax:

sfContext::getInstance()->getLogger()->info($message);
sfContext::getInstance()->getLogger()->err($message);
...

Debug short message

If you don't want to add a line to the debug log, but just trace an short message or a value, you should use debug_message instead of log_message. The message will appear directly at the bottom of the web debug toolbar.

// in an action
$this->debugMessage($message);
// in a template
<?php echo debug_message($message) ?>

For instance, for a template call:

<?php use_helper('Debug') ?>
...
<?php if ($problem): ?>
  <?php echo debug_message('been there') ?>
  ...
<?php endif ?>

...will display:

[3]: http://pear.php.net/package/Log/ "PEAR Log package'