Importance of event logging in server side scripting

Now a days script driven web applications are getting more and more complicated with background operations and triggered events. Debugging or event tracking is tough once the application is moved into production. Fresh and aspiring programmers are always too cautious to wade into deeper waters, and always go with line by line testing. Almost always in the course of debugging or code optimizations I see a lot of them using file_put_contents or echo to check variables at a particular point of execution.

I always gave the pressure to use a good logging system from the start itself, and to add level based message logging with debug_backtrace wherever needed. The most recent class abstraction for php programmers which is being used in our custom framework is attached to the downloads here. The file logging is being done after serializing, compressing and base64_encoding to keep logs in single lines, and to make sure they dont take up too much of the space.

Using the logger class, and calling the log method with complimentary log levels we can track the activity in a backend or unattended headless operations. Thus even if an unexpected condition happend in the production and only the approximate time is known, one could analyze from the logs what was happening. This could further assist in optimizing the code later.

    function doLog($msg){
        $l = time() . '::' . $msg;
        if(defined('LOG_TRACE'))
            $l .= '::'. serialize(debug_backtrace());
        file_put_contents($this->logFile, $l . "\n", FILE_APPEND);
    }

The above is a method for almost all class defenition when I write, and the logFile will be a private var, with the below code in the constructor, the class instance is self sufficient to handle a minimal logging system. Now if I need to increase verbose log, or have a detailed debugging, all I need to do in define(‘LOG_TRACE’, 1) in the calling script, which would trigger the if test on the second line in the doLog method. Any method of the class will invoke $this->doLog() several times through the course of flow of data, and this should be done while initially writing the code.

   $this->logFile  = '<PATH>/log-' . date("ymd") . '.log';

One would require the following snippet to read the log incase the backtrace is also added to the log, but most of the cases, just seeing the serialized form itself is enough to identify the bugs.

    $fp = fopen(<logfile>, 'r');
    while(!feof($fp)){
       $line = fgets($fp);
       $list = explode('::',$line);
       $log = array('time' => $list[0], 'message' => $list[1])
       if(isset($list[2])))
            $log['trace'] = unserialize($list[2]);
       print_r($log);
    }
    fclose($fp);