Merge pull request #33 from stof/rich_logging

Rich logging

src/Monolog/Formatter/FormatterInterface.php

@@ -22,15 +22,15 @@ interface FormatterInterface
      * Formats a log record.
      *
      * @param array $record A record to format
-     * @return string The formatted message
+     * @return mixed The formatted record
      */
     function format(array $record);
 
     /**
      * Formats a set of log records.
      *
-     * @param array $record A record to format
+     * @param array $records A set of records to format
-     * @return string The formatted batch message
+     * @return mixed The formatted set of records
      */
     function formatBatch(array $records);
 }

src/Monolog/Formatter/LineFormatter.php

@@ -19,10 +19,11 @@ use Monolog\Logger;
  * This is especially useful for logging to files
  *
  * @author Jordi Boggiano <j.boggiano@seld.be>
+ * @author Christophe Coevoet <stof@notk.org>
  */
 class LineFormatter implements FormatterInterface
 {
-    const SIMPLE_FORMAT = "[%datetime%] %channel%.%level_name%: %message% %extra%\n";
+    const SIMPLE_FORMAT = "[%datetime%] %channel%.%level_name%: %message% %context% %extra%\n";
     const SIMPLE_DATE = "Y-m-d H:i:s";
 
     protected $format;
@@ -47,20 +48,14 @@ class LineFormatter implements FormatterInterface
         $vars['datetime'] = $vars['datetime']->format($this->dateFormat);
 
         $output = $this->format;
-        foreach ($vars as $var => $val) {
+        foreach ($vars['extra'] as $var => $val) {
-            if (is_array($val)) {
+            if (false !== strpos($output, '%extra.'.$var.'%')) {
-                $strval = array();
+                $output = str_replace('%extra.'.$var.'%', $this->convertToString($val), $output);
-                foreach ($val as $subvar => $subval) {
+                unset($vars['extra'][$var]);
-                    $strval[] = $subvar.': '.$this->convertToString($subval);
-                }
-                $replacement = $strval ? $var.'('.implode(', ', $strval).')' : '';
-                $output = str_replace('%'.$var.'%', $replacement, $output);
-            } else {
-                $output = str_replace('%'.$var.'%', $this->convertToString($val), $output);
             }
         }
-        foreach ($vars['extra'] as $var => $val) {
+        foreach ($vars as $var => $val) {
-            $output = str_replace('%extra.'.$var.'%', $this->convertToString($val), $output);
+            $output = str_replace('%'.$var.'%', $this->convertToString($val), $output);
         }
 
         return $output;
@@ -76,12 +71,31 @@ class LineFormatter implements FormatterInterface
         return $message;
     }
 
-    private function convertToString($data)
+    protected function convertToString($data)
     {
-        if (is_scalar($data) || (is_object($data) && method_exists($data, '__toString'))) {
+        if (null === $data || is_scalar($data)) {
             return (string) $data;
         }
 
-        return serialize($data);
+        return stripslashes(json_encode($this->normalize($data)));
+    }
+
+    protected function normalize($data)
+    {
+        if (null === $data || is_scalar($data)) {
+            return $data;
+        }
+
+        if (is_array($data) || $data instanceof \Traversable) {
+            $normalized = array();
+
+            foreach ($data as $key => $value) {
+                $normalized[$key] = $this->normalize($value);
+            }
+
+            return $normalized;
+        }
+
+        return sprintf("[object] (%s: %s)", get_class($data), json_encode($data));
     }
 }

src/Monolog/Formatter/WildfireFormatter.php

@@ -23,7 +23,7 @@ class WildfireFormatter extends LineFormatter
     /**
      * Similar to LineFormatter::SIMPLE_FORMAT, except without the "[%datetime%]"
      */
-    const SIMPLE_FORMAT = "%channel%: %message% %extra%";
+    const SIMPLE_FORMAT = "%message% %context% %extra%";
 
     /**
      * Translates Monolog log levels to Wildfire levels.
@@ -51,6 +51,7 @@ class WildfireFormatter extends LineFormatter
                 'Type'  =>  $this->logLevels[$record['level']],
                 'File'  =>  '',
                 'Line'  =>  '',
+                'Label' => $record['channel'],
             ),
             $message,
         ));

src/Monolog/Handler/AbstractProcessingHandler.php

@@ -36,7 +36,7 @@ abstract class AbstractProcessingHandler extends AbstractHandler
 
         $record = $this->processRecord($record);
 
-        $record['message'] = $this->getFormatter()->format($record);
+        $record['formatted'] = $this->getFormatter()->format($record);
 
         $this->write($record);
 

src/Monolog/Handler/FirePHPHandler.php

@@ -79,7 +79,7 @@ class FirePHPHandler extends AbstractProcessingHandler
         // but we're not taking advantage of that (yet), so we're using "1" for simplicity's sake.
         return $this->createHeader(
             array(1, 1, 1, self::$messageIndex++),
-            $record['message']
+            $record['formatted']
         );
     }
 

src/Monolog/Handler/MailHandler.php

@@ -33,7 +33,7 @@ abstract class MailHandler extends AbstractProcessingHandler
         }
 
         if (!empty($messages)) {
-            $this->send($this->getFormatter()->formatBatch($messages));
+            $this->send((string) $this->getFormatter()->formatBatch($messages));
         }
     }
 
@@ -49,8 +49,6 @@ abstract class MailHandler extends AbstractProcessingHandler
      */
     protected function write(array $record)
     {
-        $content = $record['message'];
+        $this->send((string) $record['formatted']);
-
-        $this->send($content);
     }
 }

src/Monolog/Handler/StreamHandler.php

@@ -67,6 +67,6 @@ class StreamHandler extends AbstractProcessingHandler
                 throw new \UnexpectedValueException(sprintf('The stream or file "%s" could not be opened; it may be invalid or not writable.', $this->url));
             }
         }
-        fwrite($this->stream, (string) $record['message']);
+        fwrite($this->stream, (string) $record['formatted']);
     }
 }

src/Monolog/Handler/SyslogHandler.php

@@ -104,6 +104,6 @@ class SyslogHandler extends AbstractProcessingHandler
      */
     protected function write(array $record)
     {
-        syslog($this->logLevels[$record['level']], (string) $record['message']);
+        syslog($this->logLevels[$record['level']], (string) $record['formatted']);
     }
 }

src/Monolog/Logger.php

@@ -137,15 +137,17 @@ class Logger
      *
      * @param integer $level The logging level
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function addRecord($level, $message)
+    public function addRecord($level, $message, array $context = array())
     {
         if (!$this->handlers) {
             $this->pushHandler(new StreamHandler('php://stderr', self::DEBUG));
         }
         $record = array(
-            'message' => $message,
+            'message' => (string) $message,
+            'context' => $context,
             'level' => $level,
             'level_name' => self::getLevelName($level),
             'channel' => $this->name,
@@ -180,66 +182,72 @@ class Logger
      * Adds a log record at the DEBUG level.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function addDebug($message)
+    public function addDebug($message, array $context = array())
     {
-        return $this->addRecord(self::DEBUG, $message);
+        return $this->addRecord(self::DEBUG, $message, $context);
     }
 
     /**
      * Adds a log record at the INFO level.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function addInfo($message)
+    public function addInfo($message, array $context = array())
     {
-        return $this->addRecord(self::INFO, $message);
+        return $this->addRecord(self::INFO, $message, $context);
     }
 
     /**
      * Adds a log record at the WARNING level.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function addWarning($message)
+    public function addWarning($message, array $context = array())
     {
-        return $this->addRecord(self::WARNING, $message);
+        return $this->addRecord(self::WARNING, $message, $context);
     }
 
     /**
      * Adds a log record at the ERROR level.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function addError($message)
+    public function addError($message, array $context = array())
     {
-        return $this->addRecord(self::ERROR, $message);
+        return $this->addRecord(self::ERROR, $message, $context);
     }
 
     /**
      * Adds a log record at the CRITICAL level.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function addCritical($message)
+    public function addCritical($message, array $context = array())
     {
-        return $this->addRecord(self::CRITICAL, $message);
+        return $this->addRecord(self::CRITICAL, $message, $context);
     }
 
     /**
      * Adds a log record at the ALERT level.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function addAlert($message)
+    public function addAlert($message, array $context = array())
     {
-        return $this->addRecord(self::ALERT, $message);
+        return $this->addRecord(self::ALERT, $message, $context);
     }
 
     /**
@@ -261,11 +269,12 @@ class Logger
      * This method allows to have an easy ZF compatibility.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function debug($message)
+    public function debug($message, array $context = array())
     {
-        return $this->addRecord(self::DEBUG, $message);
+        return $this->addRecord(self::DEBUG, $message, $context);
     }
 
     /**
@@ -274,11 +283,12 @@ class Logger
      * This method allows to have an easy ZF compatibility.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function info($message)
+    public function info($message, array $context = array())
     {
-        return $this->addRecord(self::INFO, $message);
+        return $this->addRecord(self::INFO, $message, $context);
     }
 
     /**
@@ -287,11 +297,12 @@ class Logger
      * This method allows to have an easy ZF compatibility.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function notice($message)
+    public function notice($message, array $context = array())
     {
-        return $this->addRecord(self::INFO, $message);
+        return $this->addRecord(self::INFO, $message, $context);
     }
 
     /**
@@ -300,11 +311,12 @@ class Logger
      * This method allows to have an easy ZF compatibility.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function warn($message)
+    public function warn($message, array $context = array())
     {
-        return $this->addRecord(self::WARNING, $message);
+        return $this->addRecord(self::WARNING, $message, $context);
     }
 
     /**
@@ -313,11 +325,12 @@ class Logger
      * This method allows to have an easy ZF compatibility.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function err($message)
+    public function err($message, array $context = array())
     {
-        return $this->addRecord(self::ERROR, $message);
+        return $this->addRecord(self::ERROR, $message, $context);
     }
 
     /**
@@ -326,11 +339,12 @@ class Logger
      * This method allows to have an easy ZF compatibility.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function crit($message)
+    public function crit($message, array $context = array())
     {
-        return $this->addRecord(self::CRITICAL, $message);
+        return $this->addRecord(self::CRITICAL, $message, $context);
     }
 
     /**
@@ -339,11 +353,12 @@ class Logger
      * This method allows to have an easy ZF compatibility.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function alert($message)
+    public function alert($message, array $context = array())
     {
-        return $this->addRecord(self::ALERT, $message);
+        return $this->addRecord(self::ALERT, $message, $context);
     }
 
     /**
@@ -352,10 +367,11 @@ class Logger
      * This method allows to have an easy ZF compatibility.
      *
      * @param string $message The log message
+     * @param array $context The log context
      * @return Boolean Whether the record has been processed
      */
-    public function emerg($message)
+    public function emerg($message, array $context = array())
     {
-        return $this->addRecord(self::ALERT, $message);
+        return $this->addRecord(self::ALERT, $message, $context);
     }
 }

tests/Monolog/Formatter/JsonFormatterTest.php

@@ -21,6 +21,7 @@ class JsonFormatterTest extends \PHPUnit_Framework_TestCase
         $message = $formatter->format($msg = array(
             'level_name' => 'WARNING',
             'channel' => 'log',
+            'context' => array(),
             'message' => array('foo'),
             'datetime' => new \DateTime,
             'extra' => array(),

tests/Monolog/Formatter/LineFormatterTest.php

@@ -21,27 +21,29 @@ class LineFormatterTest extends \PHPUnit_Framework_TestCase
         $message = $formatter->format(array(
             'level_name' => 'WARNING',
             'channel' => 'log',
+            'context' => array(),
             'message' => 'foo',
             'datetime' => new \DateTime,
             'extra' => array(),
         ));
-        $this->assertEquals('['.date('Y-m-d').'] log.WARNING: foo '."\n", $message);
+        $this->assertEquals('['.date('Y-m-d').'] log.WARNING: foo [] []'."\n", $message);
     }
 
-    public function testDefFormatWithArray()
+    public function testDefFormatWithArrayContext()
     {
         $formatter = new LineFormatter(null, 'Y-m-d');
         $message = $formatter->format(array(
             'level_name' => 'ERROR',
             'channel' => 'meh',
+            'message' => 'foo',
             'datetime' => new \DateTime,
             'extra' => array(),
-            'message' => array(
+            'context' => array(
                 'foo' => 'bar',
                 'baz' => 'qux',
             )
         ));
-        $this->assertEquals('['.date('Y-m-d').'] meh.ERROR: message(foo: bar, baz: qux) '."\n", $message);
+        $this->assertEquals('['.date('Y-m-d').'] meh.ERROR: foo {"foo":"bar","baz":"qux"} []'."\n", $message);
     }
 
     public function testDefFormatExtras()
@@ -50,11 +52,12 @@ class LineFormatterTest extends \PHPUnit_Framework_TestCase
         $message = $formatter->format(array(
             'level_name' => 'ERROR',
             'channel' => 'meh',
+            'context' => array(),
             'datetime' => new \DateTime,
             'extra' => array('ip' => '127.0.0.1'),
             'message' => 'log',
         ));
-        $this->assertEquals('['.date('Y-m-d').'] meh.ERROR: log extra(ip: 127.0.0.1)'."\n", $message);
+        $this->assertEquals('['.date('Y-m-d').'] meh.ERROR: log [] {"ip":"127.0.0.1"}'."\n", $message);
     }
 
     public function testDefFormatWithObject()
@@ -63,11 +66,12 @@ class LineFormatterTest extends \PHPUnit_Framework_TestCase
         $message = $formatter->format(array(
             'level_name' => 'ERROR',
             'channel' => 'meh',
+            'context' => array(),
             'datetime' => new \DateTime,
             'extra' => array('foo' => new TestFoo, 'bar' => new TestBar, 'baz' => array()),
             'message' => 'foobar',
         ));
-        $this->assertEquals('['.date('Y-m-d').'] meh.ERROR: foobar extra(foo: O:25:"Monolog\\Formatter\\TestFoo":1:{s:3:"foo";s:3:"foo";}, bar: bar, baz: a:0:{})'."\n", $message);
+        $this->assertEquals('['.date('Y-m-d').'] meh.ERROR: foobar [] {"foo":"[object] (Monolog\\Formatter\\TestFoo: {"foo":"foo"})","bar":"[object] (Monolog\\Formatter\\TestBar: {})","baz":[]}'."\n", $message);
     }
 
     public function testBatchFormat()
@@ -78,6 +82,7 @@ class LineFormatterTest extends \PHPUnit_Framework_TestCase
                 'level_name' => 'CRITICAL',
                 'channel' => 'test',
                 'message' => 'bar',
+                'context' => array(),
                 'datetime' => new \DateTime,
                 'extra' => array(),
             ),
@@ -85,11 +90,12 @@ class LineFormatterTest extends \PHPUnit_Framework_TestCase
                 'level_name' => 'WARNING',
                 'channel' => 'log',
                 'message' => 'foo',
+                'context' => array(),
                 'datetime' => new \DateTime,
                 'extra' => array(),
             ),
         ));
-        $this->assertEquals('['.date('Y-m-d').'] test.CRITICAL: bar '."\n".'['.date('Y-m-d').'] log.WARNING: foo '."\n", $message);
+        $this->assertEquals('['.date('Y-m-d').'] test.CRITICAL: bar [] []'."\n".'['.date('Y-m-d').'] log.WARNING: foo [] []'."\n", $message);
     }
 }
 

tests/Monolog/Formatter/WildfireFormatterTest.php

@@ -15,34 +15,24 @@ use Monolog\Logger;
 
 class WildfireFormatterTest extends \PHPUnit_Framework_TestCase
 {
-    /**
+    public function testDefaultFormatIsLineFormatterWithoutNewLine()
-     * @dataProvider recordProvider
-     */
-    public function testDefaultFormatIsLineFormatterWithoutNewLine($record)
     {
         $wildfire = new WildfireFormatter();
-
-        $message = $wildfire->format($record);
-
-        $this->assertEquals(
-            '70|[{"Type":"ERROR","File":"","Line":""},"meh: log extra(ip: 127.0.0.1)"]|',
-            $message
-        );
-    }
-
-    public function recordProvider()
-    {
         $record = array(
             'level' => Logger::ERROR,
             'level_name' => 'ERROR',
             'channel' => 'meh',
+            'context' => array(),
             'datetime' => new \DateTime,
             'extra' => array('ip' => '127.0.0.1'),
             'message' => 'log',
         );
 
-        return array(
+        $message = $wildfire->format($record);
-            array($record),
+
+        $this->assertEquals(
+            '84|[{"Type":"ERROR","File":"","Line":"","Label":"meh"},"log [] {\\"ip\\":\\"127.0.0.1\\"}"]|',
+            $message
         );
     }
 }

tests/Monolog/Handler/FirePHPHandlerTest.php

@@ -31,8 +31,8 @@ class FirePHPHandlerTest extends TestCase
             'X-Wf-Protocol-1'    => 'http://meta.wildfirehq.org/Protocol/JsonStream/0.2',
             'X-Wf-1-Structure-1' => 'http://meta.firephp.org/Wildfire/Structure/FirePHP/FirebugConsole/0.1',
             'X-Wf-1-Plugin-1'    => 'http://meta.firephp.org/Wildfire/Plugin/FirePHP/Library-FirePHPCore/0.3',
-            'X-Wf-1-1-1-1'       => '50|[{"Type":"LOG","File":"","Line":""},"test: test "]|',
+            'X-Wf-1-1-1-1'       => '64|[{"Type":"LOG","File":"","Line":"","Label":"test"},"test [] []"]|',
-            'X-Wf-1-1-1-2'       => '51|[{"Type":"WARN","File":"","Line":""},"test: test "]|',
+            'X-Wf-1-1-1-2'       => '65|[{"Type":"WARN","File":"","Line":"","Label":"test"},"test [] []"]|',
         );
 
         $this->assertEquals($expected, $handler->getHeaders());
@@ -52,13 +52,13 @@ class FirePHPHandlerTest extends TestCase
             'X-Wf-Protocol-1'    => 'http://meta.wildfirehq.org/Protocol/JsonStream/0.2',
             'X-Wf-1-Structure-1' => 'http://meta.firephp.org/Wildfire/Structure/FirePHP/FirebugConsole/0.1',
             'X-Wf-1-Plugin-1'    => 'http://meta.firephp.org/Wildfire/Plugin/FirePHP/Library-FirePHPCore/0.3',
-            'X-Wf-1-1-1-1'       => '50|[{"Type":"LOG","File":"","Line":""},"test: test "]|',
+            'X-Wf-1-1-1-1'       => '64|[{"Type":"LOG","File":"","Line":"","Label":"test"},"test [] []"]|',
-            'X-Wf-1-1-1-2'       => '51|[{"Type":"WARN","File":"","Line":""},"test: test "]|',
+            'X-Wf-1-1-1-2'       => '65|[{"Type":"WARN","File":"","Line":"","Label":"test"},"test [] []"]|',
         );
 
         $expected2 = array(
-            'X-Wf-1-1-1-3'       => '50|[{"Type":"LOG","File":"","Line":""},"test: test "]|',
+            'X-Wf-1-1-1-3'       => '64|[{"Type":"LOG","File":"","Line":"","Label":"test"},"test [] []"]|',
-            'X-Wf-1-1-1-4'       => '51|[{"Type":"WARN","File":"","Line":""},"test: test "]|',
+            'X-Wf-1-1-1-4'       => '65|[{"Type":"WARN","File":"","Line":"","Label":"test"},"test [] []"]|',
         );
 
         $this->assertEquals($expected, $handler->getHeaders());

tests/Monolog/TestCase.php

@@ -20,6 +20,7 @@ class TestCase extends \PHPUnit_Framework_TestCase
     {
         return array(
             'message' => $message,
+            'context' => array(),
             'level' => $level,
             'level_name' => Logger::getLevelName($level),
             'channel' => 'test',