Log variations

Supposing that we do not want to log to a file at all. Perhaps we want to print to the screen, write the messages to a socket or send them to the Unix(tm) syslog daemon for dispatching across the network. How do we incorporate this variation?

Simplest is to subclass the Log overriding the message() method with new versions. This will work in the short term, but there is actually something subtle, but deeply wrong with this. Suppose we do subclass and have loggers that write to files, the screen and the network. Three classes , but that is OK. Now suppose that we want a new logging class that adds message filtering by priority, letting only certain types of messages through according to some configuration file.

We are stuck. If we subclass again, we have to do it for all three classes, giving us six classes. The amount of duplication is horrible.

So are you now wishing that PHP had multiple inheritence? Well, here that would reduce the short term workload, but complicate what should be a very simple class. Multiple inheritance, even when supported, should be used extremely carefully as all sorts of complicated entanglements can result. Treat it as a loaded gun. In fact, our sudden need for it is telling us something else - perhaps that we have gone wrong on the conceptual level.

What does a logger do? Does it send messages to a file? Does it send messages to a network? Does it send messages to a screen? Nope. It just sends messages (full stop). The target of those messages can be chosen when setting up the log, but after that the logger should be left to combine and format the message elements as that is its real job. We restricted ourselves by assuming that target was a filename.

Abstracting a file to a writer

The solution to this plight is a real classic. First we encapsulate the variation in a class as this will add a level of indirection. Instead of passing in the file name as a string we will pass the "thing that we will write to" which we will call a Writer. Back to the tests...

<?php
require_once('../classes/log.php');
require_once('../classes/clock.php');
require_once('../classes/writer.php');
Mock::generate('Clock');

class TestOfLogging extends UnitTestCase {
    function TestOfLogging() {
        $this->UnitTestCase('Log class test');
    }
    function setUp() {
        @unlink('../temp/test.log');
    }
    function tearDown() {
        @unlink('../temp/test.log');
    }
    function getFileLine($filename, $index) {
        $messages = file($filename);
        return $messages[$index];
    }
    function testCreatingNewFile() {
        $log = new Log(new FileWriter('../temp/test.log'));
        $this->assertFalse(file_exists('../temp/test.log'), 'Created before message');
        $log->message('Should write this to a file');
        $this->assertTrue(file_exists('../temp/test.log'), 'File created');
    }
    function testAppendingToFile() {
        $log = new Log(new FileWriter('../temp/test.log'));
        $log->message('Test line 1');
        $this->assertWantedPattern(
                '/Test line 1/',
                $this->getFileLine('../temp/test.log', 0));
        $log->message('Test line 2');
        $this->assertWantedPattern(
                '/Test line 2/',
                $this->getFileLine('../temp/test.log', 1));
    }
    function testTimestamps() {
        $clock = &new MockClock($this);
        $clock->setReturnValue('now', 'Timestamp');
        $log = new Log(new FileWriter('../temp/test.log'));
        $log->message('Test line', &$clock);
        $this->assertWantedPattern(
                '/Timestamp/',
                $this->getFileLine('../temp/test.log', 0),
                'Found timestamp');
    }
}
?>

We could, but we don't have to. We do need to create the interface, though, or we won't be able to mock it. This makes classes/writer.php looks like...

<?php
class FileWriter {
        
    function FileWriter($file_path) {
    }
        
    function write($message) {
    }
}
?>

<?php
require_once('../classes/clock.php');
require_once('../classes/writer.php');
    
class Log {
    var $_writer;
        
    function Log(&$writer) {
        $this->_writer = &$writer;
    }
        
    function message($message, $clock = false) {
        if (! is_object($clock)) {
            $clock = new Clock();
        }
        $this->_writer->write("[" . $clock->now() . "] $message");
    }
}
?>

We could start writing tests and code the FileWriter class alongside, but while we were doing this our Log tests would be failing and disturbing our focus. In fact we do not have to.

Part of our plan is to free the logging class from the file system and there is a way to do this. First we add a tests/writer_test.php so that we have somewhere to place our test code from log_test.php that we are going to shuffle around. I won't yet add it to the all_tests.php file though as it is the logging aspect we are tackling right now.

Now I have done that (honest) we remove any tests from log_test.php that are not strictly logging related and move them to writer_test.php for later. We will also mock the writer so that it does not write out to real files...

<?php
require_once('../classes/log.php');
require_once('../classes/clock.php');
require_once('../classes/writer.php');
Mock::generate('Clock');
Mock::generate('FileWriter');

class TestOfLogging extends UnitTestCase {
    function TestOfLogging() {
        $this->UnitTestCase('Log class test');
    }
    function testWriting() {
        $clock = &new MockClock();
        $clock->setReturnValue('now', 'Timestamp');
        $writer = &new MockFileWriter($this);
        $writer->expectArguments('write', array('[Timestamp] Test line'));
        $writer->expectCallCount('write', 1);
        $log = &new Log(\$writer);
        $log->message('Test line', &$clock);
    }
}
?>

1. The requirement to create the file only when needed has moved to the FileWriter.
2. As we are dealing with mocks, no files are actually created and so I moved the setUp() and tearDown() off into the writing tests.
3. The test now consists of sending a sample message and testing the format.

The mock objects do much more than simply behave like other objects, they also run tests. The expectArguments() call told the mock to expect a single parameter of the string "[Timestamp] Test line" when the mock write() method is called. When that method is called the expected parameters are compared with this and either a pass or a fail is sent to the unit test as a result.

The other expectation is that write() will be called only once. Simply setting this up is not enough. We can see all this in action by running the tests...

We can actually shorten our test slightly more. The mock object expectation expectOnce() can actually combine the two seperate expectations...

function testWriting() {
    $clock = &new MockClock();
    $clock->setReturnValue('now', 'Timestamp');
    $writer = &new MockFileWriter($this);
    $writer->expectOnce('write', array('[Timestamp] Test line'));
    $log = &new Log($writer);
    $log->message('Test line', &$clock);
}

Boundary classes

Something very nice has happened to the logger besides merely getting smaller.

The only things it depends on now are classes that we have written ourselves and in the tests these are mocked and so there are no dependencies on anything other than our own PHP code. No writing to files or waiting for clocks to tick over. This means that the log_test.php test case will run as fast as the processor will carry it. By contrast the FileWriter and Clock classes are very close to the system. This makes them harder to test as real data must be moved around and painstakingly confirmed, often by ad hoc tricks.

Our last refactoring has helped a lot. The hard to test classes on the boundary of the application and the system are now smaller as the I/O code has been further separated from the application logic. They are direct mappings to PHP operations: FileWriter::write() maps to PHP fwrite() with the file opened for appending and Clock::now() maps to PHP time(). This makes debugging easier. It also means that these classes will change less often.