Archive for the ‘Debugging’ Category

Unwanted end of session

Friday, October 2nd, 2009

During development of a new web application that required users to log in, we had problems with users being logged out too soon. The cookies were configured to end when the sessions did, but the max life time given to sessions turned out to be completely ignored.

The application had a standard LAMP environment, the key element as we will see, being the OS: the Debian based distro Ubuntu Hardy.

How PHPs garbage collection handles sessions

The main issue behind our problem turned out to be garbage collection. PHPs garbage collection also handles sessions. This is necessary because sessions are usually stored as flat files at a given location, and since each session has a unique id they will accumulate into quite a large amount over time.

During the start up over every session, there is a chance the session garbage collection will run as well. Session garbage collection deletes all session files if they are older than the set session max life time. The default probability for a new session also running session garbage collection is one in a hundred, this probability is configurable in php.ini, along with the location of the session files.

The problem

The Ubuntu server running our web application was also running an additional application which did not always have the same PHP configuration. Apache is fully capable of this when using virtual hosts – the point is, the max life time changes were not done in any of the php.ini files. Despite of this, that is exactly were there is a clue to what was happening. The PHP version we are using is an Ubuntu/Debian package, which has some changes to the original PHP default setup. In all of the php.ini files, in the SESSION section just above the garbage collection probability setting, we found that the session garbage collection by default  was actually turned off. The reason given is Debians strict permissions on the default session save path. Furthermore, the section informs that PHPs garbage collection has been replaced by a cron job.

A closer inspection of the cron job revealed this to be true, every half hour, it will look for a maxlifetime setting in all php.ini files it can find, see if it has found a value larger than its default of 24 minutes, and go on to delete all session files in the default session save path older than this value. In our case our maxlifetime settings were not in either of the ini files, which means the default value of 24 minutes was effective.

The solution

The cron job calls /usr/lib/php5/maxlifetime to determine how old sessions can be before they can be deleted, and in this file it is possible to set a new default max life time corresponding to the highest value set in either your web app or in an Apache virtual host configuration.

If you are uneasy with the OS entering territory on what arguably should be PHPs business, you can of course also remove or comment the cron job and activate PHPs session garbage collector instead.

MySQL autocommit pains

Thursday, May 7th, 2009

Last night I nailed an annoying bug in my bug tracker that has been tricky to locate, and was related to MySQL, transactions and apparently only certain MySQL versions which behaved correctly.

To ensure consistency in the bug tracker, I use a transaction to commit several changes. In this case, after an issue was created, it wouldn’t save stuff being inserted after the transaction->commit(). However – the id fields which were auto_inc – would all increment by one for each row that was never inserted. This would only happen on a select few MySQL versions, which lead me to believe it was actually a bug in those specific MySQL versions, and not in my code (it’s never me, of course :P ). This was also based on the assumption that doing a commit() would stop “transaction mode” and turn “autocommit” back on. One glance at the PHP manual proved me wrong.

It all did come down to the fact that in the class file that was creating an issue, the “autocommit” parameter for mysqli was never set back to “true” after committing a transaction. According to the manual, this should mean that all subsequent queries for that connection would “fail” unless a new “commit()” has been made. However, this obviously didn’t happen, as I have most of my bug tracker installations running properly, without this problem happening at all.

Under no circumstance was a commit() called after that point – which should mean that any queries being executed after that point were being rolled back. However, that only happed on a specific few MySQL versions, and none of the ones I tested on (confirmed at least 5.0.61 and 5.1.3). To make matters worse, the auto_inc id field did increment by one, even though the row was never saved!

The solution was simple – either do a second commit() at the end of the function to make sure all the queries after the initial transaction were commited, or make sure that the transaction turns on autocommit when it was done. In this case, I created a second function in the transaction class to commitAndEnd(), which turned autocommit back on after committing.

Lesson learned: Read manuals, don’t make assumptions. And don’t blindly trust MySQL.

Revisiting old memories

Tuesday, April 21st, 2009

In the last few days (evenings) I have been revisiting several games that I found amusing when I was younger. Some of these games I spent endless hours playing – both single- and multiplayer. I also convinced a friend of mine to try playing some of these games with me – apparantly he also enjoyed playing some of them in the past.

As it turns out – these games aren’t as good as they once were. Or – our perceptions, expectations and gaming habits have changed. We want more. The graphical standard – which were breathtaking at the time – now makes the game look old, outdated, boring and uninteresting. The intense gameplay we experienced back then has now turned into boring tasks, repetitive assignments and uninvolving gameplay. The AI is still stunning – although now it is not because it is so good, rather that it is mindnumbingly bad.

Truth be told – I didn’t have as much fun revisiting some of these games as I thought I would.

What on earth does that have to do with PHP? Well, by coincidence, this weekend I also found a backup CD I had lying around – and it had some of my older PHP projects on it. I think you know where I’m going with this now ;)

Yes, you are right – I was amazed by how badly coded these projects were. They are riddled with amateurish mistakes, shortcuts, half-assed solutions and just in general messy code. Functionality that I still remember spending endless hours implementing turns out to be nothing more than semi-intelligent calculations written in poorly designed PHP code.

Notices are being thrown all over the place, short open tags everywhere (and completely at random), $_GLOBALS variables used inconsistently, naming confusion, duplicate functionality in different functions, no classes (well, actually there was one, with one function in it but it wasn’t even used), and no concept of how an application is structured.

Suffice to say I wasn’t as impressed looking at it now, as I was when I was writing it. However – this is a good thing! Spotting obvious mistakes in old code shows that you’ve learnt. I have learnt a tremendous amount of new stuff over the past two, three years, it’s hard to even think about it all!

So – if for nothing else than to give you a good laugh – dig up some old code and have a look at it. Try to remember the good times you had writing it – the challenges you faced and how good you felt when you finally found the ultimate solution. Which turns out was probably not so much the universal ultimate solution, but rather “the best you could come up with, at the time”.

PHP isset() fail

Tuesday, April 14th, 2009

I was working on one of my php free software projects this weekend, and found an interesting bug on one of my pages, resulting in a massive number of database lookups (203 for one page) where ~180 of them was the same “kind” of lookup. Investigating further, I found out that one of my functions which was using isset() was returning a different result than what I would’ve expected.

PHP isset()  has (to me) a very strange behaviour – not only does it check to see if your variable is set (defined), it also wants it to have a specific value. Or, not so much a specific value, but it doesn’t want it to be null. Which means that running:

echo isset($variable) ? 'yes' : 'no';
$variable = null;
echo isset($variable) ? 'yes' : 'no';
$variable = 'anything';
echo isset($variable) ? 'yes' : 'no';

will return “no” in the two first cases, while “yes” only on the third attempt.

This is apparently intended behaviour, according to php.net/isset:

Determine whether a variable is set.
If a variable has been unset with unset(), it will no longer be set. isset() will return FALSE if testing a variable that has been set to NULL.

In my case, I was maintaining a $settings array with keys that matched the setting. Instead of loading all settings at startup, I would load the general settings, and only load the user-specific settings on demand. This meant that I would populate the array with keys for the settings that were loaded, as they were loaded. If the key didn’t exist, it would need to look it up from the database. However, a setting can of course be null – in this case that just means that it is not specified for that user (or the general setting was null).

To determine whether a setting was loaded, I then used

if (!isset($settings[$key]))
{
$settings[$key] = doLookupSettingFromDatabase($key);
}

and then return the corresponding setting. This of course works whenever the setting is loaded – unless the setting is null. However, in this case, the array key was actually set – and the value of the key was set, just set to null. The isset() call in this case is a major fail.

In this setting it was a “simple” matter of replacing the isset()-call in the if-test with an array_key_exists()-call, which made the whole thing work as intended. You might also argue the case that I shouldn’t be using isset() in this case, and that array_key_exists() would be the intended function call (as the php docs suggests), but I don’t think that is correct.

I actually like to initialise variables that are later to be used, by assigning them an initial null value – and then if I want to see if I’ve set it to something meaningful, simply call

$variable = null;

{ ... snippet of code that might change $variable ... }

if ($variable !== null)
{
doSomething();
}

This has worked perfectly for me. I suspect the current isset() behaviour was implemented by someone that thought it was a great idea to implement the same logic in the isset() function. However – there are several situations where a variable would be assigned a null value, and calling isset() on that variable would then return false. In my opinion, a variable is only not isset() if unset() has been called on it. In all other cases, it is set, even if it is set to a null value.

There is of course no fix for this intended behaviour – as changing this isset() behaviour would cause a complete backwards compatibility break – so watch out for those isset() statements.

PS: This flawed logic is not applied to property_exists(). AFAIK, there is no “variable_exists” – this is what isset() is for, and the documentation for property_exists() actually mentions this. Fail x 2, but props for pointing it out in the manual.

PS2: This would probably be a good case to argue the undef data type.

FirePHP and symfony

Thursday, February 5th, 2009

FirePHP is a plugin for the Firebug Firefox extension. Similar to Y!Slow, the plugin hooks into Firebug and provides extra functionality.

Unlike Y!Slow, FirePHP does not create a “new tab” in Firebug. All it does is parse custom HTTP headers and print them out in the Firebug “console” tab. Since the messages have to be sent out as HTTP headers I have never been a great fan of FirePHP, simply because most of the time I would want to inject something to the console tab is looong after I have sent out the initial headers.

After few months of “ignoring the hype” I had to give it a try. My initial testing was just as I expected: This sucks. I had to reorganize all my code so I could send out the FirePHP headers – however doing so had a major impact on when the user got anything back from the page he requested, something I really do not want to do. Bye bye FirePHP.

Here at Redpill Linpro we use Symfony for most of our projects, which uses Output Buffering a lot. Hello FirePHP.

The benefits of using output buffering, among other things, is you can send out headers at any time in the script. That means, we can throw FirePHP messages even in the footers of pages.

So, what is it good for and how do we use it?

AJAX responses have always been a PITA to debug. In some cases we simply do not have any way to print out debug information without destroying the response it self, so we have to turn to flat-file-logging.. which symfony fills up with tons of useless information making it hard to browse. Using FirePHP however you can “print out” whatever information you want, directly to the Firebug console!

Other things like rendering timers, sql queries, backtraces and background info on error pages is great to throw into FirePHP.

To use FirePHP with Symfony you will have to install the Firefox extension itself (duhh) and then the PHP “client library”.
Note: To see the FirePHP messages you will have to enable the “Console”, “Script” and “Net” panels in Firebug!


$ symfony plugin:install sfFirePHPPlugin

The client library is oddly complicated but does do the job. It offers several “importance levels”, which get color coded, such as warnings, info and error. Furthermore you can group messages for easier access.

To, for instance, show the “Symfony Debug toolbar” timers for _all_ requests (including error pages and AJAX responses) you can add to the ProjectConfiguration class:

public function setup()
{
/* [snip] */
if ($this->environment === "dev")
{
$this->getEventDispatcher()->connect("response.filter_content", array($this, "responseFilterContent"));
$this->getEventDispatcher()->connect("application.throw_exception", array($this, "responseFilterContent"));
}

public function responseFilterContent(sfEvent $event, $content = null)
{
$fp = sfFirePHP::getInstance(true);

$fp->group("Debug timers");
foreach(sfTimerManager::getTimers() as $nfo => $timer)
{
$fp->info(sprintf("%s: %.2fms (%d calls)", $nfo, $timer->getElapsedTime() * 1000, $timer->getCalls()));
}
$fp->groupEnd();

return $content;
}

That should give you a nice little groupped “Debug timers” in the Firebug Console using the “dev” frontend \o/.

FirePHP screenshot

You always have FirePHP at your fingertips, to log to it just add

FirePHP::getInstance(true)->info("Hello world! :D ");

Happy debugging!.