Home

    Logging in php

    NOTE: I have updated my logging policy now - see here for details.

    Continuing my tirade against frameworks, I've been trying to work out the best way for reusable php libraries to log their actions.

    The typical approaches I've come across are:

    1. A specific logging API (eg Pear Log)
    2. A framework based logging API (eg kohana, cake, zend)
    3. Some custom basic debugging (if(defined('DEBUG')) echo "Hello World\n";)
    4. PHPs own error_log() function
    5. No logging

    All of these have significant problems. 1 and 2 both force the developer to use additional libraries and while I am sure that the pear logging is brilliant I equally do not want to be forced to use it throughout my app just because a single library requires it. 3 and 4 work without dependencies but lack any fine grained control or extendability. 5 sometimes ends up as the best choice!

    In an attempt to break these dependencies I'm trying to use the following convention in libraries I write from now on. For example in an authentication library:

    class MyAuthLib {
     
      public function doAuth(...) {
        // bring the callback into the current scope
        global $pac_logger;
        ...
        // and then wherever you want to log stuff
        isset($pac_logger) && $pac_logger('Doing auth', 'info');
        ....
      }
     
    }

    Because:

    • Its very fast - isset() kicks the pants off defined()
    • Its very fast - $pac_logger('Testing', 'info') beats call_user_func($pac_logger, 'Testing', 'info')
    • Its very fast - no function calls unless it is enabled
    • Its fairly readable
    • It can run with no configuration - if $pac_logger isn't set, nothing is logged.
    • It can be hooked up to any logging API the end developer wants
    • Did I mention its very fast?

    The end developer then only has to be informed via your excellent documentation of the variable [$pac_logger] and the function signature [($message, $level)] and they can write a mapper in a few lines of code if they require logging. If they don't the library runs with almost no overhead.

    // a mapper in the apps bootstrap code
    function pac_log_mapper($message, $level) {
      switch($level) {
        case 'error':
          return MyLogger::log($message, MyLogger::LOG_ERROR);
        default:
          return MyLogger::log($message, MyLogger::LOG_FINE);
      }
    }
    $pac_logger='pac_log_mapper';

    It does go against good OO practice by using global variables and requiring a function as opposed to a class method, but for this specific usage I think the benefits justify it. I try and limit this anyway by using the old variable prefix convention, rather grandly titled 'Pluggable Action Callback' - pac.

    In a quickly knocked up benchmark script over 1000 iterations where the object is created fresh on each iteration:

    • Baseline - 4.8ms
    • Single log call per iteration with no callback registered - 5.6ms (+0.8)
    • Single log call per iteration with callback registered - 8.7ms (+3.9)

    As always, everyone has their own way - but mine is best :)

    Comments

    Other uses

    This can be extended to anything where the underlying library is unaffected by the result of the operation, for example profiling and benchmarking where you want minimum overhead.

    Anything more complicated should probably be implemented as a Listener so you can fix the behaviour with interfaces and allow for multiple callbacks to be registered.