Saturday 5 November 2011

Working directory at PHP shutdown

I'm working on an online bookstore website, where I decided I needed to use session_set_save_handler in order to consolidate all web state in the site's mysql database.

One of the first things I do in nearly any software development project is to set up a convenient debug logging facility. PHP has error_log, but a) it seems like it's full of magic behaviour, b) it needs a string, so you have to flatten any structured data yourself, first, and c) I didn't know about it when I wrote debug(). What better thing to log than one's ad-hoc session handlers?

It's a good habit to check Apache's error log once in a while. That's where debug() originally wrote to, but because I don't necessarily have access to Apache's logs, I taught debug() to log to a file nearby the DocumentRoot. But today I checked Apache's error log, and lo and behold, it was full of errors:

[Fri Nov 04 22:45:47 2011] [error] [client ::1] PHP Warning:  fopen(../logs/mph.log): failed to open stream: No such file or directory in /home/berndj/public_html/mph-adhoc/lib/debug.php on line 7, referer: http://localhost/~berndj/mph-adhoc/web/index.php

After much head-scratching and source-diving, and poring over strace's log of what Apache does when I hit the page, I figured it out: PHP resets the working directory back to where it was before it executes a script, and only then runs destructors and other shutdown functions - one of which I assume to call session_write_close [1].That left some of my session handlers running in a directory where I didn't expect them to. (The root directory, to be precise.) And that was why the attempts to fopen a relative path were failing - there is no ".." in the root directory, let alone a logs directory [2].

I guess I have to choose a place to call session_write_close - somewhere that guarantees it always gets called, yet before PHP starts cleaning up (is this possible?). Perhaps my compromise will be to add the call to my boilerplate file - the one I paste into every new file when I start writing it. There's an extra benefit to doing this, because it allows me to get rid of one XXX tricky-code marker:

# XXX Don't call mysql_close() as session handling depends on having a DB connection.

[1] To confirm my understanding of what was happening, I wrote a demonstration of what happens to the working directory in PHP's session handling. Install this simple file into a PHP-enabled web directory, and watch its output change as you toggle the call to session_write_close.

[2] For a flight of counterfactual fancy, imagine if my log file were "../log/messages" and the website were set up to run from /var/www! The error description would then not be "No such file or directory" (ENOENT) but "Permission denied" (EACCESS). I'm not sure whether that would have helped or hindered my search for an explanation. It may well have prompted me to reach for strace sooner.