Oro, Symfony, Logging, and Debugging

PHP developers used to var_dump debugging will be slightly disappointed by the early pre-alpha release of OroCRM. Oro’s CRM application uses an ajax-with-history style navigation that requests chunks of HTML directly from the server. The javascript code seems to require well formed HTML with no top level text node, which means echoing things out in the “business logic” section of the application will break the navigation.

Fear not though. Oro, backed by Symfony, has a full suite of industrial grade logging tools at your disposal. Today we’ll cover using these logging tools, as well as the inevitable bits of the Oro/Symfony configuration this logging system interacts with.

Remember, the Oro platform is currently pre-alpha software. It’s not done yet. I guarantee specific details will change by the first official release. However, the general Symfony principles described here should still apply.

Log Messages in Oro

Developers familiar with Magento will be well acquainted with the static Mage::log method. Oro has no analogous method. Instead, debugging Oro will require a developer to get cozy with Symfony’s Monologger bundle. Fortunately, this bundle is already well documented online. This is one of the advantages of keeping Oro’s patterns close to Symfony’s — any Symfony developer will be able to get up to speed on this new business application framework quickly.

We’re going to start in the account controller. Specifically, we’ll edit the AccountBundle in the oro/crm vendor package at

vendor/oro/crm/src/OroCRM/Bundle/AccountBundle/Controller/AccountController.php

Normally, you’d never edit this file directly, but sometimes a bit of temporarily logging added to vendor files is the quickest way to get the answer you’re after. This is especially true when you’re learning a new platform. Just remember to remove the logging code when we finish — or better yet, develop a development/deployment methodology where developers never make a check-in on third party vendor code.

To start, add the following lines to the indexAction method. If you’re not familiar with MVC applications, this is the main code entry point for the Account listing page.

#File: vendor/oro/crm/src/OroCRM/Bundle/AccountBundle/Controller/AccountController.php
//...
public function indexAction(Request $request)
{
    $logger = $this->get('logger');
    $logger->crit("Hello logger!");        
    //...
}
//...

With the above in place, navigate to the Accounts List page by clicking on the “List” link.

The page should load without issue, and your URL should now look something like this

http://oro.example.com/#url=/account

If you look at end of the production log file at

app/logs/prod.log

You should see your log message interspersed with several others.

[2013-06-02 04:12:42] app.CRITICAL: Hello Logger! [] []

We used the crit method of the logger object. This logs a message at the CRITICAL level. There are eight log levels in total. Each has a ranking assigned related to its seriousness.

DEBUG
INFO
NOTICE
WARNING
ERROR
CRITICAL
ALERT
EMERGENCY

If you take a look at the vendor/monolog/monolog/src/Monolog/Logger.php file

#File: vendor/monolog/monolog/src/Monolog/Logger.php
/**
 * Critical conditions
 *
 * Example: Application component unavailable, unexpected exception.
 */
const CRITICAL = 500;

you’ll see each log level is a constant. The comments will give you an idea of what each level is used for — but in practice it’s one of those subtle things which is going to vary from team to team. One team’s CRITICAL errors are another team’s NOTICEs.

Symfony Deployment Environments

Our log file is named prod.log because we’re running Symfony in the production deployment environment. This environment is set in the PHP kernel bootstrap file

$File: web/app.php
//...
$kernel = new AppKernel('prod', false);    
//...

This is the file which .htaccess routes all our PHP requests through, (it’s analogous to index.php in many other frameworks). If you haven’t used a Symfony application before, most come with several different app files, each for bootstrapping a specific environment. For example, the app_dev.php file

#File: web/app_dev.php
//...
$kernel = new AppKernel('dev', true);
//...

bootstraps Symfony into the dev deployment environment. What this means, practically, is that Symfony loads a different set of configuration variables which will change the behavior of the application. For example, in the dev environment, the main log file is named

app/logs/dev.log

You can load any Symfony URL in another deployment environment by hardcoding the base URL. That means if you had loaded your page with the following URL

http://oro.example.com/app_dev.php/#url=/account

the logger would have written to dev.log instead of prod.log.

This concept of deployment environment is very important in Symfony development, which means it will be very important in Oro development. While the Zend Framework offeres similar functionality, its Zend_Application component loading framework was never heavily emphasized, which means many Zend projects developed their own methods of tying components together (See Magento). Symfony, on the other hand, has heavily promoted their Kernel bundle as the right way to build applications with Symfony components. We’ll come back to this concept in future articles.

Important: I’ve noticed that browsing OroCRM applications with the app_dev.php URL will often end up caching HTML links with app_dev.php in the URL, even if your browsing in another environment. This bug will likely be fixed before the actual release, but if you’re seeing unexpected behavior be sure you’re browsing the environment you think you are.

Monitoring Log Files

If you’re anything like me, you’re probably thinking that opening up a log file and sifting through its contents sounds like a giant pain in the behind. Using the *nix tail command, or a dedicated log viewer like OS X’s Console.app, can help alleviate this burden. Both will show changes to a log file as they happen, allowing us to see what log messages are created by what specific actions in the browser.

To use tail, just type

$ tail -f app/logs/prod.log
[2013-06-02 04:23:16] security.DEBUG: Reloading user from user provider. [] []
[2013-06-02 04:23:16] security.DEBUG: Username "admin" was reloaded from user provider. [] []
[2013-06-02 04:23:16] app.INFO: User invoked class: "OroCRM\Bundle\AccountBundle\Controller\AccountController", Method: "indexAction". [] []
[2013-06-02 04:23:16] app.CRITICAL: Hello Logger! [] []
[2013-06-02 04:23:17] security.DEBUG: Write SecurityContext in the session [] []

You’ll see the last few lines of logger output, and the the program will appear to hang. However, if you reload your account page, new information will be logged to the terminal window.

The tail command shows the last few lines of a file (in other words, its “tail”) without loading the entire file into memory. The -f flag puts tail in interactive mode, which will allow us to monitor any file in near real time. This makes finding out which actions created which log messages a breeze.

Important: You may need to fully re-navigate to the account section to see this information logged, as your browser may cache the ajax request that populated the account screen. Keep this in mind whenever we call for a reload or refresh of the account page.

Log Levels and Deployment Environments

Earlier we talked about logging levels. Our Hello Logger! message doesn’t sound like the CRITICAL message we made it — let’s change it to a message whose level is INFO.

#File: vendor/oro/crm/src/OroCRM/Bundle/AccountBundle/Controller/AccountController.php
//...
$logger->info("Hello Logger!");
//...

The logger object has a method for each individual log level. Here we’ve used the info method. Checkout the source of vendor/monolog/monolog/src/Monolog/Logger.php for all the available methods, (search for the comment * Adds a log record).

#File: vendor/monolog/monolog/src/Monolog/Logger.php
/**
 * Adds a log record at the INFO level.
 *
 * This method allows for compatibility with common interfaces.
 *
 * @param  string  $message The log message
 * @param  array   $context The log context
 * @return Boolean Whether the record has been processed
 */
public function info($message, array $context = array())
{
    return $this->addRecord(self::INFO, $message, $context);
}

With the above call to info in place, reload the account page and watch the log window.

Nothing happened.

Not only was out Hello Logger! message not logged, none of the other log messages we saw before were logged. What happened?

Don’t worry. Nothing is broken, and you’re not going crazy. Symfony’s prod environment is configured to only log messages whose level is ERROR or higher. That’s why we didn’t see our message, which we logged at the INFO level. As for the other log messages, that requires a bit more of an explanation. Symfony’s logger service is built around one central logging class which receives all the messages. Client programmers then create multiple handlers to handle the details of logging those messages.

Keep your panic in check — you don’t need to write a logging handler. Symfony’s prod environment is preconfigured with the FingersCrossedHandler. This handler will accept log messages of all levels, but won’t report any until it receives a message above or equal to the configured action level, (the previously mentioned ERROR). So, when our previous log message with a CRITICAL level was sent, this told the fingers crossed logger to start logging all its messages. When we changed this to a level of INFO, it was no longer high enough to trigger logging, so no messages were shown.

The name fingers crossed comes from the sentiment of

Let’s keep out fingers crossed that we don’t need log messages, but if we do we’ll be able to see them all

Most logging systems only let you say “show me logs of value X or higher”. With FingerCrossed, we can see all the log messages if there’s a problem. This gives us a better chance of debugging an issue without exploratory code, which is a win for everyone.

Seeing Low Log Levels

So, that leaves us with an unanswered question.

How do we view logs with lower levels?

There’s two answers. The first, and preferred, way is to always use the development deployment environment when working on or debugging features. If you load the account page with the app_dev URL (or start browsing with the app_dev URL which will generate app_dev links)

http://oro.example.com/app_dev.php/#url=/account

You’ll be able to see your message logged at the INFO level in app/logs/dev.log.

[2013-06-02 04:58:00] app.INFO: Hello Logger! [] []

This works because the dev deployment environment’s action_level is configured to show messages at the DEBUG level or higher. You also probably noticed there was a lot more information to wade through because of this.

This leads us into the second way to solve our logging problem. If it’s not possible to use the dev deployment environment, or the error is only happening in the production environment, then the best way to get your lower level error message logging is to temporarily change the action_level for the production deployment environment.

Environmental Configuration

Symfony’s environmental configuration files can be found in the app/config folder

$ ls -l app/config/config*.yml
-rw-rw-rw-  1 alanstorm  staff  5348 May 28 10:41 app/config/config.yml
-rw-rw-rw-  1 alanstorm  staff   502 May 28 10:41 app/config/config_dev.yml
-rw-rw-rw-  1 alanstorm  staff   594 May 28 10:41 app/config/config_devjs.yml
-rw-rw-rw-  1 alanstorm  staff   118 May 28 10:41 app/config/config_perf.yml
-rw-rw-rw-  1 alanstorm  staff   441 May 28 10:41 app/config/config_prod.yml
-rw-rw-rw-  1 alanstorm  staff   691 May 28 10:41 app/config/config_test.yml    

Each config_ file represents an environment’s specific configuration. The config.yml file contains configuration values shared across environments. Theses configuration files are written in the YAML format. If you’re unfamiliar with it, YAML is a basic way to represent a nested configuration tree in plain ASCII text. If that sounded intimidating, it isn’t. Just keep you indentation identical to what you find in the files, and you should be all set. It’s like XML, but without the tags.

We’ll cover the full syntax of these files in a later article — for now we’ll just guide you towards the specific values you want to change.

If you take a look at config_prod.yml, you’ll see the following under the monolog hierarchy.

#File: config_prod.yml
#...
monolog:
    handlers:
        main:
            type:         fingers_crossed
            action_level: error
#...

Here, the main: error handler, whose type is fingers_crossed, has an action level set to error. It’s this action level that determines what does, or does not get logged. If we change this value to debug, we should be able to see our messages.

# File: config_prod.yml
#...    
            action_level: debug
#...                

Save your file with the above changes. However, before we try reloading the URL, we’ll need to do one more thing. Clear your Symfony application cache.

You and Me Together, Caching Forever

Symfony, and by proxy Oro, relies heavily on its caching engine. This is common for almost all web programming frameworks in 2013. Values from the various configurations yml files are stored in cache, which means changing one requires a clearing of the cache for Symfony to see that change.

Fortunately, Symfony comes with a command line application that, among other tasks, can clear the cache for you. From the root folder, just run the clear:cache command

$ php app/console cache:clear --env=prod
Clearing the cache for the prod environment with debug false

Notice we’ve indicated --env=prod. This tells the console application to clear the production environment’s cache. After clearing the cache, this command will also re-warm Symfony’s cache — meaning many of the configuration options will be built back up and restored in cache. This means clearing the cache may make some time.

You may run into permission problems. Normally, the cache is built up by the web server user, but when you run the console app you’re creating files owned by your user. If you’re running into permissions problems clearing the cache, or problems with the web-server creating new cache entries, you can also just delete the entire

app/cache/prod

directory which will clear most cache entries, and then reload a webpage and the cache will be rebuilt as per normal. We’ll talk more about the cache and best practices in another article, for now just know you’ll need to clear it before seeing configuration changes.

Assuming you’ve successfully cleared the cache, reload/re-navigate to your account page.

http://oro.example.com/#url=/account    

and your prod environment should now display every log message of DEBUG level or higher. Be sure to change the action_level back to error when you’re done

# File: config_prod.yml
#...
action_level: error
#...    

Old Standbys

Of course, all this new logging may take you some time to get used to. Also, as Oro is still alpha software, there may be bugs related to logging that logging won’t be able to uncover. Fortunately, this is still just PHP, so tried and true logging and debugging methods will still work fine.

First, using file_put_contents like this

file_put_contents('/tmp/test.log',"My Message Here\n",FILE_APPEND);

is a quick method for adding temporary “poor man’s logging” to a system. Here we’re just appending a string to a file in our system’s temporary directory (/tmp/test.log). We won’t get the nice auto expansion of types but it is, as they say, good enough for government work.

Second, despite how we started this article, there is a way to use var_dump debugging with OroCRM. While Oro uses ajax to change the page content and jiggers with the browser URL to provide proper forward/back functionality, the framework is smart enough to also allow you direct access to a URL. So, ajax URL

http://oro.example.com/#url=/account

translates into a “real” URL of

http://oro.example.com/account

Loading the real URL in the browser will load the page without ajax, meaning you can var_dump and echo to your heart’s content without worrying about Oro’s ajax behavior.

While the old ways are, sometimes, the best ways, it’s still worth your time to learn how Symfony and Oro’s loggers work.

Logger Instance

There’s one thing we’ve glossed over in this article. To get an instance of a logger object, we used the following code.

$logger = $this->get('logger');

However, this will only work from a controller object. Without getting too deep into Symfony’s architecture — the controller has a get shortcut method for accessing any service from the server container object. Each section/component (controller, templates, etc.) of Symfony has its own way to accessing the logger object. If you’re unsure what the preferred way of accessing it is, you can always grab an instance with the following code.

$logger = $GLOBALS['kernel']->getContainer()->get('logger');

We’ll cover what this means in a future article. For now, know that while it’s not the most elegant of solutions (the global variable), that it will work from any component that’s part of a fully bootstrapped Symfony environment.

Wrap Up

Oro’s Symfony 2 roots may seem intimidating at first, and well, they are. Symfony is a mature product, with its own culture and own philosophy on what it means to use object oriented code to develop web applications.

That said, the intimidating isn’t because it’s necessarily impossible to learn, but because it’s new. It’s different than the environment you’re used to programming in. Putting in the time up-front to learn Symfony’s conventions, and to speak this tribe’s language, will not only allow you to work more effectively with the system, it will also put you on equal footing with the Oro core developers.

Oro is a young project, and it’s sure to change over the course of its early lifetime. Being able to understand why something was implemented in a particular way gives you the leverage to have a productive conversation with the Oro community about a better way to implement something. That’s the vital skill needed to succeed with a young platform, and help shape into something greater.