Custom logging system for cakePHP

I do love cakePHP, but sometimes it can get tricky to get it to do exactly what you want.

For our big app, we needed to stop using the builtin logging system to take advantage of the syslog and log analyzer tools we had.

At first I got confused by the various log files, but after reading the cake core code, it (kinda) makes sense. Let me explain it to you.

CakeLog and FileLog

CakeLogis the cake static class that handles all the log actions. You can call it yourself statically using CakeLog::write(), but cake also calls it itself when an error is reported.

CakeLoginternally write its content using the FileLog. This FileLogwrites its content to files located in app/tmp/logs.

Writing errors to the syslog instead

We didn't want our logs to be saved in app/tmp/logs for three mains reasons :

1. Those files gets deleted on every deploy we did (this was how our deployment system works)
2. Those files can get very big very fast
3. Our app was distributed accross several servers, meaning that each server had its own set of log files

Instead, we wanted them to be written to the syslog where they would be intercepted and stored in our main log analyzer.

To do so, we wrote a simple SysLogclass to use instead of the FileLog. Here it is :

class SysLog {
  /**
  *    Writes a log to the syslog
  *    \param    $type    Either a numerical constant or a string
  *    \param    $message    Message to log
  **/
  public function write($type, $message) {
    // We "fix" CakeLog that passes severity as a string
    if (is_string($type)) {
      // Mapping string to syslog priorities
      $priorities = array(
        'debug'    => LOG_DEBUG,
        'info'        => LOG_INFO,
        'notice'    => LOG_NOTICE,
        'warning'    => LOG_WARNING,
        'error'    => LOG_ERR,
        'default'    => LOG_NOTICE
      );
      $type = (array_key_exists($type, $priorities)) ? $priorities[$type] : $priorities['default'];
    }
    // Writing to syslog
    openlog(false, 0, LOG_LOCAL7);
    syslog($type, trim($message));
    closelog();
  }
}

Place this file in app/lib/log/sys_log.php. Then, in app/config/bootstrap.php, place the following code :

CakeLog::config('default', array('engine' => 'SysLog'));

It is important that you place the CakeLog::config() call inbootstrap.php and not in core.php because of the way cake actually loads its internal. I also manually defined the syslog facility as LOCAL7, but you can change it to whatever you want or even update the code so the actual facility can be passed as a parameter of the CakeLog::config() call (actually, that's how it's done in my real code, but I didn't want to overcomplicate the example).

Also, note that I added a special code to handle the way CakeLog passes parameters to the SysLog. CakeLog passes the severity as a string, so we convert it back to the PHP constants.

With this code, all your logs will now be routed to the syslog, and your app/tmp/logs directory will no longer grow in size (instead, that will be your /var/logs/syslog :) )

Where are my errors loggued now ?

Well, your errors are loggued to the syslog. But cake defines its own error handler that will reformat the error thrown by PHP, and reroute it to the CakeLog. In effect, it means that all errors with similar severity will be grouped (E_PARSE, E_ERROR, E_CORE_ERROR, etc will be loggued asLOG_ERROR). Also, cake will parse and reformat the message to log. It can be problematic if you rely on your PHP config to correctly parse your logs because you won't have the expected output.

Hopefully, cake provides a way to disable this error handler, but it was very tricky to find and even more tricky to correctly use. I won't spend too much time on all the details, but what you have to know is :

1. You have to define a define('DISABLE_DEFAULT_ERROR_HANDLING', true); in order to disable the cake error handler and use the default PHP one
2. This call MUST be done before your Configure::write('debug') call otherwise it won't work
3. You also have to define a Configure::write('log', E_ALL & ~E_DEPRECATED); for this to work but...
4. You can't define both the debug and the log value in the same call using an array, you have to define them in two different calls debugthen log

So, finally, here is the final working configuration :

In app/config/core.php :

Configure::write('log', E_ALL & ~E_DEPRECATED);
define('DISABLE_DEFAULT_ERROR_HANDLING', true);

And inapp/config/bootstrap.php :

CakeLog::config('default', array('engine' => 'SysLog'));

Final words

I wrote this blog post because I got hit by this problem. Twice. I didn't bloggued about it the first time, so a few weeks later when I had to change some config values in my bootstrap.php and core.php I forgot about the specific order of loading things. It took me a couple hours to figure it out again.

So, to avoid running into the same issue some months from now, I took some time to write it down, and hopefully I'll help some of you too.

Parsing error in cakePHP view for empty file

As a convention, I never write the closing PHP tag at the end of my php files. It helps in avoiding the "header already sent" error when dealing with cookie/sessions.

However, today cake complains about

Parse error: syntax error, unexpected $end in /var/www/website/app/views/players/default.ctp on line 1

My default.ctp file only contain the following content :

<?php

It took me a couple of minutes to fix it. I only added an empty line after the opening tag, so it now read :

<?php

The first statement was a perfectly valid php file, but somehow it makes cakePHP fail.

I didn't have time to investigate on it further, nor submit a bug report (because it may well be coming from my custom app, not cake itself) but I plan to.

Losing session on each request with cakePHP and Chrome

I finally found solution for one of the more tenacious bug I ever encountered. Share the joy !

I had a website working perfectly under Firefox but when browsing using Chrome, I noticed that my Session gets regenerated on each page load. Constantly. Creating hundred and hundred of useless session files.

And only with Chrome.

Since when using a browser should change the server behavior ? Well I don't exactly know what Chrome is doing with the referer but it seems that it is altering it in some ways.

And cakePHP forces the setting of session.referer_check to true, thus checking that multiple requests with the same PHPSESSID comes from the same url.

As one posted on php.net :

If you have a value specified for session.referercheck you may run into difficulty when someone accesses your site and attempts to log in with a mis- capitalized URL.  The logon will fail because any calls to sessionstart() will result in the existing session being trashed and a new one being created. This becomes a bigger problem when the logon is followed by a header("Location: ...") redirect, because the session_start() at the top of the page will fail.

Those two settings combined, and you got a hell of a mess. I first found a quick fix by forcing the setting of session_start() in app/webroot/index.php. But after more readingand debuggingI finally found the culprit.

Hacking your way through the fix

There is no easy way to prevent cake from setting this setting, but you can define your own session handler in the Session.save configure key.

Just create file named session_custom.php in app/config/ and set Configure::write('Session.save', 'session_custom'); in your core.php file.

And in that file, just drop the following lines (copy/paste from cake_session.php)

ini_set('session.referer_check', '');                    // Killing this f***ing config that was causing so much trouble with Chrome
ini_set('session.use_trans_sid', 0);                    // No session id in url
ini_set('session.name', Configure::read('Session.cookie'));    // Using custom cookie name instead of PHPSESSID
ini_set('session.cookie_lifetime', $this->cookieLifeTime);    // Cookie like time, depending on security level
ini_set('session.cookie_path', $this->path);                // Cookie path

Memcache keys not getting saved correctly

Update : We were initially blaming Memcache not correctly setting/getting keys. We should instead have blamed him for being over-zealous in clearing its list. See bottom of post for details.

Today we were having a bit of an issue with memcache. We had to write a thousand keys into it, reading them from a JSON file.

This code had been running happily on our server for the past two weeks. But as the number of keys increased, we came to spot that some keys seemed to be randomly cleared.

After further investigation (and a lot of hours), it appears that the keys were simply not set at all, or set to an empty/false value. This was really strange because it occured inside a loop on our JSON file, and never occurs for the same keys, nor everytime.

We took our server under high stress, forcing it to reload data very often, to trigger the bug once more. After a lot of test, we gather some more data, but nothing really came out. The missed keys were really random.

Finally, we decided to code a fast and dirty fix, until we found a better solution. Basically, we simply checks that the value is correctly saved after saving it, and if not, we retry. And we do so recursively.

function set($key, $val, $recursionLevel = 0) {
  Cache::write($key, $val);
  if (Cache::read($key)===false) {
    if ($recursionLevel>10) die('Possible infinite recursion);
    $this->set($key, $val, $recursionLevel);
  }
}

Note, that this will not work if one of your values is defined as false, otherwise you'll end up in an infinite loop.

Update

Well, the problem kept sporadically popping. And we finally found the REAL culprit.

Cake provides multiple Cacheconfig, using different settings. One would use a special config to set different cache duration. Each setting would use a different key prefix.

Unfortunatly, memcache has no way of finding keys starting with a special prefix. So when we do a Cache::clear(), it just wipes clear the whole memcache keys, no matter what config you specify.

We were running two different websites using the same memcache server, and when doing a clear on one website, it cleared keys on the second one as well.

We finally started one memcache server per site.

Multiple foreach() with references in php

It took me a couple of hours to debug : I had an array with values that shouldn't be here, values from another part of the application, and I couldn't figure out where that came from.

Well, it turns it was part of a documented feature of PHP :

Unless the array is referenced, foreach operates on a copy of the specified array and not the array itself. foreach has some side effects on the array pointer. Don't rely on the array pointer during or after the foreach without resetting it. Reference of a $value and the last array element remain even after the foreach loop. It is recommended to destroy it by unset().php.net

My code was as simple as :

$newArray = array();
$newArray2 = array();
foreach($list as $key => &$data) {
  $newArray[] = $data;
}
foreach($list2 as $key => &$data) {
  $newArray2[] = $data;
}

This resulted in the latest index of $newArray being set to one of $list2 values (didn't know exactly which). This is really counter intuitive.