12.5. Logging

If an attacker successfully obtains the necessary information to log in to someone else's account, then any actions they perform look like they are legitimate even though they are not. At best with careful logging and monitoring you may be able to identify and stop some of these attacks in their tracks. At worst, hopefully you have enough information in your logs to roll back any changes an attacker made. Logging is important. It doesn't have to be complex to be effective, either.

The following code can be used to record database updates to a log file:

<?php
// specify log file
define('LOGFILE', '/srv/apache/example.com/logs/database.log'),

// define group and record separator characters
define('GS', chr(0x1D));
define('RS', chr(0x1E));

// begin or continue session

session_start();

// write the provided message to the log file
function write_log($message)
{
    $fp = fopen(LOGFILE, 'a'),
    fwrite($fp, date('YmdTHis') . $_SESSION['username'] . GS . $message . RS);
    fclose($fp);
}
?>

Log entries are separated by an end of record character (RS, character code 0x1E). Each entry starts with a fixed-width character string, which represents a timestamp in ISO-8601 format followed by the username of the person who issued the call. The timestamp will always be 15 characters in length but the length of the username can vary so the group separator (GS, character code 0x1D) is used to terminate it. The final entry of the record is the log message (which will be the SQL statement executed by the user).

Depending on the complexity of the SQL statement I may break it up onto separate lines. My style is to write simple queries that have one or two conditions in its WHERE clause as one line but more complex ones that use JOINS or several Boolean comparisons in the WHERE clause spanning multiple lines. Consequently, a new line or carriage return would not be a suitable record delimiter and is why I chose character code 0x1F.

To use the function, include it in your project's lib/functions.php file or another file that is included into the script that makes INSERT, UPDATE, and DELETE queries. Then pass the query string to the function before issuing it to the database. Here's an example:

<?php
include "../lib/common.php";
include "../lib/db.php";
include "../lib/functions.php";

session_start();

$query = sprintf('DELETE FROM %sUSER WHERE USER_ID = %d',
    $_POST['userid']);

write_log($query);
mysql_query($query, $GLOBALS['DB']);
?>

A resulting log entry might look like this:

20071220T153217tboronczyk↔DELETE FROM WROX_USER WHERE USER_ID = 1▴

It can sometimes be difficult to find the right balance between speed, readability, and space requirements as log files can fill up quite fast on busy sites. Representing the log in this type of format preserves all the important information while saving space. The same entry in XML, for example, which is often touted for its readability, is actually slower and bloated:

<entry>
<datetime encoding="iso-8601">200712201<datetime>
<username>tboronczyk</username>
<message>DELETE FROM WROX_USER WHERE USER_ID = 1</message>
</entry>

The first entry is comprised of 66 characters and the XML representation is 157. That's over a 237 percent increase in required disk space just to store the XML entry!

It is not that difficult to parse the log file. The file can be read in one character at a time until the record separator character is encountered which acts as a signal that the entire record has been read into memory. Then the record is split on the group separator into two pieces—the first is the timestamp and username and the second is the log message or SQL. The first piece is split further using substring() into the 15-character timestamp and the username. The whole processed until the end of the file has been reached.

Here is some example code, which I have saved as view_log.php. Figure 12-6 shows the processed log file.

Figure 12-6. Figure 12-6

<?php
// specify log file
define('LOGFILE', '/srv/apache/example.com/logs/database.log'),

// define group and record separator characters
define('GS', chr(0x1D));
define('RS', chr(0x1E));

echo '<pre>';
$fp = fopen(LOGFILE, 'r'),

// read in record until the record separator is encountered
while (!feof($fp))
{
    $c = '';
    $line = '';
    while ($c != RS && !feof($fp))
    {
        $line .= $c = fgetc($fp);
    }

    // split the line on the group separator
    $tmp = explode(GS, $line);

    $record = array();

    // timestamp is 15-characters long, the remaining is the username
    $record['timestamp'] = substr($tmp[0], 0, 15);
    $record['username'] = htmlspecialchars(substr($tmp[0], 15));

    $record['message'] = htmlspecialchars($tmp[1]);

    print_r($record);
}
fclose($fp);

echo '</pre>';
?>

Alternatively, the logic discussed here to write to and read from the log file can be encapsulated into a custom stream wrapper. Such a wrapper is nothing more than a class that abstracts the logic behind a scheme name. For more information writing a stream wrapper see the PHP documentation at www.php.net/stream_wrapper_register.