the future is unwritten

Archive for September, 2006

The daily PHP WTF

Monday, September 25th, 2006

A couple of days ago I succeeded in the daunting task of bringing a production server to a grinding halt. In fact the server was a sturdy linux box, and despite all my wrongdoings it kept chugging along, but all php services running on top of it where rendered useless (it was the company intranet server, and people where not happy).
Since this is quite an extraordinary event, I thought I might capitalize on the experience gained through this accident and share it for the benefit of future generations.
To make a long story short, here is the sequence of the events that lead to the catastrophe:

  1. I installed on the web server a shrink-wrapped php package, which I shall not name here, without taking the time to sift properly trough the code line by line, but following as carefully as I could the install instructions
  2. After toying around for a while, I decided to implement some new must-have feature, and within a couple of hours had on my hands code that looked good enough on my development box.
  3. So I promptly dumped the code to the production server, and fired up my browser to see the final result, but…
  4. …a nasty php error message greeted me. The code was trying to read from a file descriptor that was not open (in the fact the php variable delegated to hold the file descriptor was not even declared at the point it was used)
  5. The fix was really quick: a close look revealed an error in nesting code blocks, so that code was being executed where it was not supposed to. Hey presto, edit, save, redeploy and test!
  6. And this time, BINGO! the new functionality was fine and dandy. I dashed down the corridor to announce the new amazing functionality to fellow coders, and after discussing it and future evolutions for a while, I packed up and went home, happy and satisfied with my rapid-development skills and the incredibly apt platform that php had once again proved to be

But things are seldom as simple as they seem…
…and I was greeted by angry sysadmins and furious customers the next morning when returning to my cubicle.

The problem had been promptly identified: there was an error log file that kept growing at incredible speed, and it had saturated during the night the /home partition. Since the main website, based on a template engine and php opcode cache, was using the same partition to hold both the compiled templates and cached php scripts, it was having a hard time writing to disk its necessary files.
The sysadmins could not understand what was causing the log to grow indefinitely, but the mere fact that it was the php error log flashed a big nasty disaster sign in my mind. Sure enough, the culprit was to be found in my modifications of the previous day, but how on earth could the application, fixed and tested the day before, have kept running erroneously for the whole night, and still causing damage at early morning?
The worst part of it is the error log was reporting accesses to the web server from my very own development machine, which had been switched off during all that time.
Being well versed in php, I know for a fact that any php script is bound to end within a specified time limit (specified in php.ini that is), or be terminated by the php engine.
It is also very unusual for a script to keep running after the client that requested the web page terminates the http connection, such as when the user hits the STOP button or quits the application.
After a quick and dirty Apache restart, the error log finally showed a normal behaviour, everybody calmed down, and I was left alone with my dark train of toughts: was it possible that I had hit a bug of php, or, heaven forbids, Apache itself? Impossible! The j2ee goblins would have laughed at me for months to come.

As that old Jedi saying goes, use the source, Luke.

(more…)