08-logging.markdown

layout	title
documentation	Logging And Debugging

Logging And Debugging

Propel provides tools to monitor and debug your model. Whether you need to check the SQL code of slow queries, or to look for error messages previously thrown, Propel is your best friend for finding and fixing problems.

Propel Logs

Propel uses the logging facility configured in runtime-conf.xml to record errors, warnings, and debug information.

By default Propel will attempt to use the Log framework that is distributed with PEAR. If you are not familiar with it, check its online documentation. It is also easy to configure Propel to use your own logging framework -- or none at all.

Logger Configuration

The Propel log handler is configured in the <log> section of your project's runtime-conf.xml file. Here is the accepted format for this section with the default values that Propel uses:

{% highlight xml %}

file ./propel.log propel 7 ... {% endhighlight %}

Tip
Remember to run propel-gen convert-conf after modifying the configuration files.

Using these parameters, Propel creates a file Log handler in the background, and keeps it for later use:

{% highlight php %}

` nested elements may vary, depending on which log handler you are using. Most common accepted logger types are `file`, `console`, `syslog`, `display`, `error_log`, `firebug`, and `sqlite`. Refer to the [PEAR::Log](http://www.indelible.org/php/Log/guide.html#standard-log-handlers) documentation for more details on log handlers configuration and options. Note that the `` tag needs to correspond to the integer represented by one of the `PEAR_LOG_*` constants: |Constant |Value |Description |-------------------|-------|------------------------- |PEAR_LOG_EMERG |0 |System is unusable |PEAR_LOG_ALERT |1 |Immediate action required |PEAR_LOG_CRIT |2 |Critical conditions |PEAR_LOG_ERR |3 |Error conditions |PEAR_LOG_WARNING |4 |Warning conditions |PEAR_LOG_NOTICE |5 |Normal but significant |PEAR_LOG_INFO |6 |Informational |PEAR_LOG_DEBUG |7 |Debug-level messages ### Logging Messages ### Use the static `Propel::log()` method to log a message using the configured log handler: {% highlight php %} setName('foo'); Propel::log('uh-oh, something went wrong with ' . $myObj->getName(), Propel::LOG_ERR); {% endhighlight %} You can log your own messages from the generated model objects by using their `log()` method, inherited from `BaseObject`: {% highlight php %} log('uh-oh, something went wrong', Propel::LOG_ERR); {% endhighlight %} The log messages will show up in the log handler defined in `runtime-conf.xml` (`propel.log` file by default) as follows: {% highlight text %} Oct 04 00:00:18 [error] uh-oh, something went wrong with foo Oct 04 00:00:18 [error] MyObj: uh-oh, something went wrong {% endhighlight %} >**Tip**
All serious errors coming from the Propel core do not only issue a log message, they are also thrown as `PropelException`. ### Using An Alternative PEAR Log Handler ### In many cases you may wish to integrate Propel's logging facility with the rest of your web application. In `runtime-conf.xml`, you can customize a different PEAR logger. Here are a few examples: _Example 1:_ Using `display` handler (for output to HTML) {% highlight xml %} display 6 {% endhighlight %} _Example 2:_ Using `syslog` handler {% highlight xml %} syslog 8 propel 6 {% endhighlight %} ### Using A Custom Logger ### If you omit the `` section of your `runtime-conf.xml`, then Propel will not setup _any_ logging for you. In this case, you can set a custom logging facility and pass it to Propel at runtime. Here's an example of how you could configure your own logger and then set Propel to use it: {% highlight php %} log($m, Propel::LOG_EMERG); } public function alert($m) { $this->log($m, Propel::LOG_ALERT); } public function crit($m) { $this->log($m, Propel::LOG_CRIT); } public function err($m) { $this->log($m, Propel::LOG_ERR); } public function warning($m) { $this->log($m, Propel::LOG_WARNING); } public function notice($m) { $this->log($m, Propel::LOG_NOTICE); } public function info($m) { $this->log($m, Propel::LOG_INFO); } public function debug($m) { $this->log($m, Propel::LOG_DEBUG); } public function log($message, $priority) { $color = $this->priorityToColor($priority); echo '

$message

'; } private function priorityToColor($priority) { switch($priority) { case Propel::LOG_EMERG: case Propel::LOG_ALERT: case Propel::LOG_CRIT: case Propel::LOG_ERR: return 'red'; break; case Propel::LOG_WARNING: return 'orange'; break; case Propel::LOG_NOTICE: return 'green'; break; case Propel::LOG_INFO: return 'blue'; break; case Propel::LOG_DEBUG: return 'grey'; break; } } } {% endhighlight %} >**Tip**
There is also a bundled `MojaviLogAdapter` class which allows you to use a Mojavi logger with Propel. ## Debugging Database Activity ## By default, Propel uses `PropelPDO` for database connections. This class, which extends PHP's `PDO`, offers a debug mode to keep track of all the database activity, including all the executed queries. ### Enabling The Debug Mode ### The debug mode is disabled by default, but you can enable it at runtime as follows: {% highlight php %} useDebug(true); {% endhighlight %} You can also disable the debug mode at runtime, by calling `PropelPDO::useDebug(false)`. Using this method, you can choose to enable the debug mode for only one particular query, or for all queries. Alternatively, you can ask Propel to always enable the debug mode for a particular connection by using the `DebugPDO` class instead of the default `PropelPDO` class. This is accomplished in the `runtime-conf.xml` file, in the `` tag of a given datasource connection (see the [runtime configuration reference]() for more details). {% highlight xml %} sqlite DebugPDO {% endhighlight %}

Tip
You can use your own connection class there, but make sure that it extends PropelPDO and not only PDO. Propel requires certain fixes to PDO API that are provided by PropelPDO.

Counting Queries

In debug mode, PropelPDO keeps track of the number of queries that are executed. Use PropelPDO::getQueryCount() to retrieve this number:

{% highlight php %}

getQueryCount(); // 1 {% endhighlight %} Tip: You cannot use persistent connections if you want the query count to work. Actually, the debug mode in general requires that you don't use persistent connections in order for it to correctly log bound values and count executed statements. ### Retrieving The Latest Executed Query ### For debugging purposes, you may need the SQL code of the latest executed query. It is available at runtime in debug mode using `PropelPDO::getLastExecutedQuery()`, as follows: {% highlight php %} getLastExecutedQuery(); // 'SELECT * FROM my_obj'; {% endhighlight %} Tip: You can also get a decent SQL representation of the criteria being used in a SELECT query by using the `Criteria->toString()` method. Propel also keeps track of the queries executed directly on the connection object, and displays the bound values correctly. {% highlight php %} prepare('SELECT * FROM my_obj WHERE name = :p1'); $stmt->bindValue(':p1', 'foo'); $stmt->execute(); echo $con->getLastExecutedQuery(); // 'SELECT * FROM my_obj where name = "foo"'; {% endhighlight %} >**Tip**
The debug mode is intended for development use only. Do not use it in production environment, it logs too much information for a production server, and adds a small overhead to the database queries. ## Full Query Logging ## The combination of the debug mode and a logging facility provides a powerful debugging tool named _full query logging_. If you have properly configured a log handler, enabling the debug mode (or using `DebugPDO`) automatically logs the executed queries into Propel's default log file: {% highlight text %} Oct 04 00:00:18 propel-bookstore [debug] INSERT INTO publisher (`ID`,`NAME`) VALUES (NULL,'William Morrow') Oct 04 00:00:18 propel-bookstore [debug] INSERT INTO author (`ID`,`FIRST_NAME`,`LAST_NAME`) VALUES (NULL,'J.K.','Rowling') Oct 04 00:00:18 propel-bookstore [debug] INSERT INTO book (`ID`,`TITLE`,`ISBN`,`PRICE`,`PUBLISHER_ID`,`AUTHOR_ID`) VALUES (NULL,'Harry Potter and the Order of the Phoenix','043935806X',10.99,53,58) Oct 04 00:00:18 propel-bookstore [debug] INSERT INTO review (`ID`,`REVIEWED_BY`,`REVIEW_DATE`,`RECOMMENDED`,`BOOK_ID`) VALUES (NULL,'Washington Post','2009-10-04',1,52) ... Oct 04 00:00:18 propel-bookstore [debug] SELECT bookstore_employee_account.EMPLOYEE_ID, bookstore_employee_account.LOGIN FROM `bookstore_employee_account` WHERE bookstore_employee_account.EMPLOYEE_ID=25 {% endhighlight %} By default, Propel logs all SQL queries, together with the date of the query and the name of the connection. ### Setting The Data To Log ### The full query logging feature can be configured either in the `runtime-conf.xml` configuration file, or using the runtime configuration API. In `runtime-conf.xml`, tweak the feature by adding a `` tag under ``: {% highlight xml %} ... ...

true true true

{% endhighlight %}

To accomplish the same configuration as above at runtime, change the settings in your main include file, after Propel::init(), as follows:

{% highlight php %}

setParameter('debugpdo.logging.details.method.enabled', true); $config->setParameter('debugpdo.logging.details.time.enabled', true); $config->setParameter('debugpdo.logging.details.mem.enabled', true); {% endhighlight %} Let's see a few of the provided parameters. ### Logging More Connection Messages ### `PropelPDO` can log queries, but also connection events (open and close), and transaction events (begin, commit and rollback). Since Propel can emulate nested transactions, you may need to know when an actual `COMMIT` or `ROLLBACK` is issued. To extend which methods of `PropelPDO` do log messages in debug mode, customize the `'debugpdo.logging.methods'` parameter, as follows: {% highlight php %} setParameter('debugpdo.logging.methods', $allMethods, false); {% endhighlight %} By default, only the messages coming from `PropelPDO::exec`, `PropelPDO::query`, and `DebugPDOStatement::execute` are logged. ### Logging Execution Time And Memory ### In debug mode, Propel counts the time and memory necessary for each database query. This very valuable data can be added to the log messages on demand, by adding the following configuration: {% highlight php %} setParameter('debugpdo.logging.details.time.enabled', true); $config->setParameter('debugpdo.logging.details.mem.enabled', true); {% endhighlight %} Enabling the options shown above, you get log output along the lines of: {% highlight text %} Feb 23 16:41:04 Propel [debug] time: 0.000 sec | mem: 1.4 MB | SET NAMES 'utf8' Feb 23 16:41:04 Propel [debug] time: 0.002 sec | mem: 1.6 MB | SELECT COUNT(tags.NAME) FROM tags WHERE tags.IMAGEID = 12 Feb 23 16:41:04 Propel [debug] time: 0.012 sec | mem: 2.4 MB | SELECT tags.NAME, image.FILENAME FROM tags LEFT JOIN image ON tags.IMAGEID = image.ID WHERE image.ID = 12 {% endhighlight %} The order in which the logging details are enabled is significant, since it determines the order in which they will appear in the log file. ### Complete List Of Logging Options ### The following settings can be customized at runtime or in the configuration file: |Parameter |Default |Meaning |-----------------------------------------------|-----------|--------------------------------------------------------------------------------- |`debugpdo.logging.innerglue` |":" |String to use for combining the title of a detail and its value |`debugpdo.logging.outerglue` |"|" |String to use for combining details together on a log line |`debugpdo.logging.realmemoryusage` |`false` |Parameter to [memory_get_usage()](http://www.php.net/manual/en/function.memory-get-usage.php) and [memory_get_peak_usage()](http://www.php.net/manual/en/function.memory-get-peak-usage.php) calls |`debugpdo.logging.methods` |`array` |An array of method names (`Class::method`) to be included in method call logging |`debugpdo.logging.details.slow.enabled` |`false` |Enables flagging of slow method calls |`debugpdo.logging.details.slow.threshold` |`0.1` |Method calls taking more seconds than this threshold are considered slow |`debugpdo.logging.details.time.enabled` |`false` |Enables logging of method execution times |`debugpdo.logging.details.time.precision` |`3` |Determines the precision of the execution time logging |`debugpdo.logging.details.time.pad` |`10` |How much horizontal space to reserve for the execution time on a log line |`debugpdo.logging.details.mem.enabled` |`false` |Enables logging of the instantaneous PHP memory consumption |`debugpdo.logging.details.mem.precision` |`1` |Determines the precision of the memory consumption logging |`debugpdo.logging.details.mem.pad` |`9` |How much horizontal space to reserve for the memory consumption on a log line |`debugpdo.logging.details.memdelta.enabled` |`false` |Enables logging differences in memory consumption before and after the method call |`debugpdo.logging.details.memdelta.precision` |`1` |Determines the precision of the memory difference logging |`debugpdo.logging.details.memdelta.pad` |`10` |How much horizontal space to reserve for the memory difference on a log line |`debugpdo.logging.details.mempeak.enabled` |`false` |Enables logging the peak memory consumption thus far by the currently executing PHP script |`debugpdo.logging.details.mempeak.precision` |`1` |Determines the precision of the memory peak logging |`debugpdo.logging.details.mempeak.pad` |`9` |How much horizontal space to reserve for the memory peak on a log line |`debugpdo.logging.details.querycount.enabled` |`false` |Enables logging of the number of queries performed by the DebugPDO instance thus far |`debugpdo.logging.details.querycount.pad` |`2` |How much horizontal space to reserve for the query count on a log line |`debugpdo.logging.details.method.enabled` |`false` |Enables logging of the name of the method call |`debugpdo.logging.details.method.pad` |`28` |How much horizontal space to reserve for the method name on a log line ### Changing the Log Level ### By default the connection log messages are logged at the `Propel::LOG_DEBUG` level. This can be changed by calling the `setLogLevel()` method on the connection object: {% highlight php %} setLogLevel(Propel::LOG_INFO); {% endhighlight %} Now all queries and bind param values will be logged at the INFO level. ### Configuring a Different Full Query Logger ### By default the `PropelPDO` connection logs queries and binds param values using the `Propel::log()` static method. As explained above, this method uses the log storage configured by the `` tag in the `runtime-conf.xml` file. If you would like the queries to be logged using a different logger (e.g. to a different file, or with different ident, etc.), you can set a logger explicitly on the connection at runtime, using `Propel::setLogger()`: {% highlight php %} setLogger($logger); {% endhighlight %} This will not affect the general Propel logging, but only the full query logging. That way you can log the Propel error and warnings in one file, and the SQL queries in another file.