Better logging

Lib/Configuration.php

@@ -37,10 +37,11 @@ class Configuration {
         ),
         'log' => array(
             'file' => 'C:\inetpub\wwwroot\WebService\logs\log.txt',
+            'format' => '%ip% - [%date%] - %status% %error% - %time% - %func%',
             // The greater the verbosity, the more is displayed
             // 0 : no log at all
-            // 1 : log function calls and errors
+            // 1 : log summary
-            // 2 : log parameters and sent data
+            // 2 : log response
             'verbosity' => 0,
         ),
         'session' => array(

Lib/Logger.php

@@ -0,0 +1,81 @@
+<?php
+
+namespace BSR\Lib;
+
+class Logger {
+    const QUIET = 0;
+    const NORMAL = 1;
+    const VERBOSE = 2;
+
+    private static $start;
+    private static $data = array();
+    private static $log = '';
+
+    private static function ip() {
+        if (isset($_SERVER['HTTP_X_FORWARDED_FOR'])) {
+            return array_shift(
+                array_map('trim', explode(',', $_SERVER['HTTP_X_FORWARDED_FOR']))
+            );
+        } else if (isset($_SERVER['REMOTE_ADDR'])) {
+            return $_SERVER['REMOTE_ADDR'];
+        }
+
+        return '(n-a)';
+    }
+
+    public static function start() {
+        self::$start = microtime(true);
+
+        self::$data = array(
+            'ip' => self::ip(),
+            'date' => date('d.m.Y H:m:s'),
+            'func' => '(none)',
+            'error' => ''
+        );
+    }
+
+    public static function info($info, $key = null) {
+        if(is_null($key)) {
+            self::$data = array_merge(self::$data, $info);
+        } else {
+            self::$data[$key] = $info;
+        }
+    }
+
+    /**
+     * Log a message that will be displayed in the logs if the configuration
+     * says so.
+     *
+     * @param string $message
+     * @param int $verbosity
+     */
+    public static function log($message, $verbosity = Logger::VERBOSE) {
+        if(Configuration::get('log.verbosity') < $verbosity) {
+            return;
+        }
+
+        self::$log .= $message."\n";
+    }
+
+    public static function stop($data = null) {
+        if(! is_null($data)) {
+            self::info($data);
+        }
+
+        if(Configuration::get('log.verbosity') > Logger::QUIET) {
+            $time = (microtime(true) - self::$start) * 1000;
+            self::$data['time'] = round($time, 2).'ms';
+
+            $format = Configuration::get('log.format');
+
+            $patterns = array_map(function($p) { return "%$p%"; }, array_keys(self::$data));
+            $msg = str_replace($patterns, array_values(self::$data), $format)."\n";
+
+            if(strlen(self::$log) > 0) {
+                $msg .= self::$log;
+            }
+
+            file_put_contents(Configuration::get('log.file'), $msg, FILE_APPEND | LOCK_EX);
+        }
+    }
+}

Lib/WebService.php

@@ -10,68 +10,40 @@ abstract class WebService
     private $func = null;
     private $status = 200;
 
-    private $log = '';
-
-    /**
-     * Log a message that will be displayed in the logs if the configuration
-     * says so.
-     *
-     * @param string $message
-     * @param int $verbosity
-     * @param bool $withTime
-     */
-    public function log($message, $verbosity = 1, $withTime = false) {
-        if(Configuration::get('log.verbosity') < $verbosity) {
-            return;
-        }
-
-        if($withTime) {
-            $message = date("d-m-Y h:m:s").' '.$message;
-        }
-
-        $this->log .= $message."\n";
-    }
-
     /**
      * Treat the current request and output the result. This is the only
      * method that should be called on the webservice directly !
      */
     public function Run()
     {
+        Logger::start();
+
         $renderer = new Renderer();
 
-        $this->log("------------------");
-        $this->log("Start request", 1, true);
         $data = array();
 
         try {
             $result = $this->Call();
             $data["result"][$this->func] = $result;
+
+            Logger::log(print_r($result, true));
         } catch (WebException $e) {
             $data["error"]["code"] = $e->getCode();
             $data["error"]["reason"] = $e->getMessage();
             $data["error"]["name"] = $e->getName();
             $this->status = 400;
 
-            $this->log(sprintf("Error : [%s] %s", $e->getCode(), $e->getName()));
+            Logger::info($e->getName(), 'error');
         } catch (\Exception $e) {
             $data["failure"]["code"] = $e->getCode();
             $data["failure"]["reason"] = $e->getMessage();
             $this->status = 500;
 
-            $this->log(sprintf("Failure : %s", $e->getMessage()));
+            Logger::info($e->getMessage(), 'error');
         }
 
-        $this->log("Data: ".print_r($data, true), 2);
+        Logger::stop(array('status' => $this->status));
-
         $renderer->render($this->status, $data);
-
-        $this->log("Request finished", 1, true);
-        $this->log("------------------\n\n");
-
-        if(Configuration::get('log.verbosity') > 0) {
-            file_put_contents(Configuration::get('log.file'), $this->log, FILE_APPEND | LOCK_EX);
-        }
     }
 
     /**
@@ -98,6 +70,10 @@ abstract class WebService
         $this->func = $params["func"];
         unset($params['func']);
 
+        Logger::info(array(
+            'func' => $this->func.'('.implode(', ', $params).')',
+        ));
+
         if (!is_callable(array($this, $this->func))) {
             throw new UsageException("BadMethod", "Method {$this->func} does not exists.", UsageException::BAD_METHOD);
         }
@@ -115,8 +91,6 @@ abstract class WebService
             throw new UsageException("TooManyArgs", "You must provide at most $nbArgs arguments.", UsageException::TOO_MANY_ARGS);
         }
 
-        $this->log("Calling '".$this->func."'");
-        $this->log("Params: ".print_r($params, true), 2);
         return call_user_func_array(array($this, $this->func), $params);
     }
 }