diff --git a/src/Mustache/Engine.php b/src/Mustache/Engine.php index 43ac4f6..16e2e86 100644 --- a/src/Mustache/Engine.php +++ b/src/Mustache/Engine.php @@ -488,7 +488,7 @@ class Mustache_Engine // If the named partial cannot be found, log then return null. $this->log( Mustache_Logger::WARNING, - sprintf('Partial not found: "%s"', $name), + 'Partial not found: "{name}"', array('name' => $name) ); } @@ -535,7 +535,7 @@ class Mustache_Engine if (!is_file($fileName)) { $this->log( Mustache_Logger::DEBUG, - sprintf('Writing "%s" class to template cache: "%s"', $className, $fileName), + 'Writing "{className}" class to template cache: "{fileName}"', array('className' => $className, 'fileName' => $fileName) ); @@ -546,7 +546,7 @@ class Mustache_Engine } else { $this->log( Mustache_Logger::WARNING, - sprintf('Template cache disabled, evaluating "%s" class at runtime', $className), + 'Template cache disabled, evaluating "{className}" class at runtime', array('className' => $className) ); @@ -556,7 +556,7 @@ class Mustache_Engine $this->log( Mustache_Logger::DEBUG, - sprintf('Instantiating template: "%s"', $className), + 'Instantiating template: "{className}"', array('className' => $className) ); @@ -610,8 +610,8 @@ class Mustache_Engine $this->log( Mustache_Logger::INFO, - sprintf('Compiling template to "%s" class', $name), - array('name' => $name) + 'Compiling template to "{className}" class', + array('className' => $name) ); return $this->getCompiler()->compile($source, $tree, $name, isset($this->escape), $this->charset); @@ -647,7 +647,7 @@ class Mustache_Engine if (!is_dir($dirName)) { $this->log( Mustache_Logger::INFO, - sprintf('Creating Mustache template cache directory: "%s"', $dirName), + 'Creating Mustache template cache directory: "{dirName}"', array('dirName' => $dirName) ); @@ -660,8 +660,8 @@ class Mustache_Engine $this->log( Mustache_Logger::DEBUG, - sprintf('Caching compiled template to "%s"', dirname($fileName)), - array('filename' => $fileName) + 'Caching compiled template to "{fileName}"', + array('fileName' => $fileName) ); $tempFile = tempnam($dirName, basename($fileName)); @@ -675,8 +675,8 @@ class Mustache_Engine $this->log( Mustache_Logger::ERROR, - sprintf('Unable to rename Mustache temp cache file: "%s" -> "%s"', $tempFile, $fileName), - array('tempFile' => $tempFile, 'fileName' => $fileName) + 'Unable to rename Mustache temp cache file: "{tempName}" -> "{fileName}"', + array('tempName' => $tempFile, 'fileName' => $fileName) ); } diff --git a/src/Mustache/Logger.php b/src/Mustache/Logger.php index 0a6b027..e08359a 100644 --- a/src/Mustache/Logger.php +++ b/src/Mustache/Logger.php @@ -16,7 +16,7 @@ * * The message MUST be a string or object implementing __toString(). * - * The message MAY contain placeholders in the form: %foo% where foo + * The message MAY contain placeholders in the form: {foo} where foo * will be replaced by the context data in key "foo". * * The context array can contain arbitrary data, the only assumption that @@ -132,4 +132,4 @@ interface Mustache_Logger * @return null */ public function log($level, $message, array $context = array()); -} \ No newline at end of file +} diff --git a/src/Mustache/Logger/AbstractLogger.php b/src/Mustache/Logger/AbstractLogger.php new file mode 100644 index 0000000..bb057d6 --- /dev/null +++ b/src/Mustache/Logger/AbstractLogger.php @@ -0,0 +1,121 @@ +log(Mustache_Logger::EMERGENCY, $message, $context); + } + + /** + * Action must be taken immediately. + * + * Example: Entire website down, database unavailable, etc. This should + * trigger the SMS alerts and wake you up. + * + * @param string $message + * @param array $context + */ + public function alert($message, array $context = array()) + { + $this->log(Mustache_Logger::ALERT, $message, $context); + } + + /** + * Critical conditions. + * + * Example: Application component unavailable, unexpected exception. + * + * @param string $message + * @param array $context + */ + public function critical($message, array $context = array()) + { + $this->log(Mustache_Logger::CRITICAL, $message, $context); + } + + /** + * Runtime errors that do not require immediate action but should typically + * be logged and monitored. + * + * @param string $message + * @param array $context + */ + public function error($message, array $context = array()) + { + $this->log(Mustache_Logger::ERROR, $message, $context); + } + + /** + * Exceptional occurrences that are not errors. + * + * Example: Use of deprecated APIs, poor use of an API, undesirable things + * that are not necessarily wrong. + * + * @param string $message + * @param array $context + */ + public function warning($message, array $context = array()) + { + $this->log(Mustache_Logger::WARNING, $message, $context); + } + + /** + * Normal but significant events. + * + * @param string $message + * @param array $context + */ + public function notice($message, array $context = array()) + { + $this->log(Mustache_Logger::NOTICE, $message, $context); + } + + /** + * Interesting events. + * + * Example: User logs in, SQL logs. + * + * @param string $message + * @param array $context + */ + public function info($message, array $context = array()) + { + $this->log(Mustache_Logger::INFO, $message, $context); + } + + /** + * Detailed debug information. + * + * @param string $message + * @param array $context + */ + public function debug($message, array $context = array()) + { + $this->log(Mustache_Logger::DEBUG, $message, $context); + } +} diff --git a/src/Mustache/Logger/StreamLogger.php b/src/Mustache/Logger/StreamLogger.php index 57e90f3..7f3fd50 100644 --- a/src/Mustache/Logger/StreamLogger.php +++ b/src/Mustache/Logger/StreamLogger.php @@ -18,7 +18,7 @@ * * Hint: Try `php://stderr` for your stream URL. */ -class StreamLogger implements Mustache_Logger +class Mustache_Logger_StreamLogger extends Mustache_Logger_AbstractLogger { protected static $levels = array( self::DEBUG => 100, @@ -35,6 +35,8 @@ class StreamLogger implements Mustache_Logger protected $url = null; /** + * @throws InvalidArgumentException if the logging level is unknown. + * * @param string $stream Resource instance or URL * @param integer $level The minimum logging level at which this handler will be triggered */ @@ -49,6 +51,16 @@ class StreamLogger implements Mustache_Logger } } + /** + * Close stream resources. + */ + public function __destruct() + { + if (is_resource($this->stream)) { + fclose($this->stream); + } + } + /** * Set the minimum logging level. * @@ -75,120 +87,14 @@ class StreamLogger implements Mustache_Logger return $this->level; } - /** - * System is unusable. - * - * @param string $message - * @param array $context - * @return null - */ - public function emergency($message, array $context = array()) - { - $this->log(self::EMERGENCY, $message, $context); - } - - /** - * Action must be taken immediately. - * - * Example: Entire website down, database unavailable, etc. This should - * trigger the SMS alerts and wake you up. - * - * @param string $message - * @param array $context - * @return null - */ - public function alert($message, array $context = array()) - { - $this->log(self::ALERT, $message, $context); - } - - /** - * Critical conditions. - * - * Example: Application component unavailable, unexpected exception. - * - * @param string $message - * @param array $context - * @return null - */ - public function critical($message, array $context = array()) - { - $this->log(self::CRITICAL, $message, $context); - } - - /** - * Runtime errors that do not require immediate action but should typically - * be logged and monitored. - * - * @param string $message - * @param array $context - * @return null - */ - public function error($message, array $context = array()) - { - $this->log(self::ERROR, $message, $context); - } - - /** - * Exceptional occurrences that are not errors. - * - * Example: Use of deprecated APIs, poor use of an API, undesirable things - * that are not necessarily wrong. - * - * @param string $message - * @param array $context - * @return null - */ - public function warning($message, array $context = array()) - { - $this->log(self::WARNING, $message, $context); - } - - /** - * Normal but significant events. - * - * @param string $message - * @param array $context - * @return null - */ - public function notice($message, array $context = array()) - { - $this->log(self::NOTICE, $message, $context); - } - - /** - * Interesting events. - * - * Example: User logs in, SQL logs. - * - * @param string $message - * @param array $context - * @return null - */ - public function info($message, array $context = array()) - { - $this->log(self::INFO, $message, $context); - } - - /** - * Detailed debug information. - * - * @param string $message - * @param array $context - * @return null - */ - public function debug($message, array $context = array()) - { - $this->log(self::DEBUG, $message, $context); - } - /** * Logs with an arbitrary level. * + * @throws InvalidArgumentException if the logging level is unknown. + * * @param mixed $level * @param string $message * @param array $context - * @return null */ public function log($level, $message, array $context = array()) { @@ -196,7 +102,7 @@ class StreamLogger implements Mustache_Logger throw new InvalidArgumentException('Unexpected logging level: ' . $level); } - if (self::$levels[$level] >= $this->level) { + if (self::$levels[$level] >= self::$levels[$this->level]) { $this->writeLog($level, $message, $context); } } @@ -217,7 +123,9 @@ class StreamLogger implements Mustache_Logger $this->stream = fopen($this->url, 'a'); if (!is_resource($this->stream)) { + // @codeCoverageIgnoreStart throw new UnexpectedValueException(sprintf('The stream or file "%s" could not be opened.', $this->url)); + // @codeCoverageIgnoreEnd } } @@ -235,10 +143,6 @@ class StreamLogger implements Mustache_Logger */ protected static function getLevelName($level) { - if (!array_key_exists($level, self::$levels)) { - throw new InvalidArgumentException('Unexpected logging level: ' . $level); - } - return strtoupper($level); } @@ -248,14 +152,37 @@ class StreamLogger implements Mustache_Logger * @param integer $level The logging level * @param string $message The log message * @param array $context The log context + * + * @return string */ protected static function formatLine($level, $message, array $context = array()) + { + return sprintf( + "%s: %s\n", + self::getLevelName($level), + self::interpolateMessage($message, $context) + ); + } + + /** + * Interpolate context values into the message placeholders. + * + * @param string $message + * @param array $context + * + * @return string + */ + protected static function interpolateMessage($message, array $context = array()) { $message = (string) $message; + + // build a replacement array with braces around the context keys + $replace = array(); foreach ($context as $key => $val) { - $message = str_replace('%'.$key.'%', $val, $message); + $replace['{' . $key . '}'] = $val; } - return sprintf('%s: %s %s', self::getLevelName($level), (string) $message, json_encode($context)); + // interpolate replacement values into the the message and return + return strtr($message, $replace); } } diff --git a/test/Mustache/Test/EngineTest.php b/test/Mustache/Test/EngineTest.php index 7178786..bf59d18 100644 --- a/test/Mustache/Test/EngineTest.php +++ b/test/Mustache/Test/EngineTest.php @@ -27,11 +27,14 @@ class Mustache_Test_EngineTest extends PHPUnit_Framework_TestCase public function testConstructor() { + $logger = new Mustache_Logger_StreamLogger(tmpfile()); $loader = new Mustache_Loader_StringLoader; $partialsLoader = new Mustache_Loader_ArrayLoader; $mustache = new Mustache_Engine(array( 'template_class_prefix' => '__whot__', - 'cache' => self::$tempDir, + 'cache' => self::$tempDir, + 'cache_file_mode' => 777, + 'logger' => $logger, 'loader' => $loader, 'partials_loader' => $partialsLoader, 'partials' => array( @@ -45,6 +48,7 @@ class Mustache_Test_EngineTest extends PHPUnit_Framework_TestCase 'charset' => 'ISO-8859-1', )); + $this->assertSame($logger, $mustache->getLogger()); $this->assertSame($loader, $mustache->getLoader()); $this->assertSame($partialsLoader, $mustache->getPartialsLoader()); $this->assertEquals('{{ foo }}', $partialsLoader->load('foo')); @@ -85,12 +89,17 @@ class Mustache_Test_EngineTest extends PHPUnit_Framework_TestCase public function testSettingServices() { + $logger = new Mustache_Logger_StreamLogger(tmpfile()); $loader = new Mustache_Loader_StringLoader; $tokenizer = new Mustache_Tokenizer; $parser = new Mustache_Parser; $compiler = new Mustache_Compiler; $mustache = new Mustache_Engine; + $this->assertNotSame($logger, $mustache->getLogger()); + $mustache->setLogger($logger); + $this->assertSame($logger, $mustache->getLogger()); + $this->assertNotSame($loader, $mustache->getLoader()); $mustache->setLoader($loader); $this->assertSame($loader, $mustache->getLoader()); @@ -222,6 +231,74 @@ class Mustache_Test_EngineTest extends PHPUnit_Framework_TestCase $mustache->setHelpers('monkeymonkeymonkey'); } + /** + * @expectedException InvalidArgumentException + */ + public function testSetLoggerThrowsExceptions() + { + $mustache = new Mustache_Engine; + $mustache->setLogger(new StdClass); + } + + public function testPartialLoadFailLogging() + { + $name = tempnam(sys_get_temp_dir(), 'mustache-test'); + $mustache = new Mustache_Engine(array( + 'logger' => new Mustache_Logger_StreamLogger($name, Mustache_Logger::WARNING), + 'partials' => array( + 'foo' => 'FOO', + 'bar' => 'BAR', + ), + )); + + $result = $mustache->render('{{> foo }}{{> bar }}{{> baz }}', array()); + $this->assertEquals('FOOBAR', $result); + + $this->assertContains('WARNING: Partial not found: "baz"', file_get_contents($name)); + } + + public function testCacheWarningLogging() + { + $name = tempnam(sys_get_temp_dir(), 'mustache-test'); + $mustache = new Mustache_Engine(array( + 'logger' => new Mustache_Logger_StreamLogger($name, Mustache_Logger::WARNING) + )); + + $result = $mustache->render('{{ foo }}', array('foo' => 'FOO')); + $this->assertEquals('FOO', $result); + + $this->assertContains('WARNING: Template cache disabled, evaluating', file_get_contents($name)); + } + + public function testLoggingIsNotTooAnnoying() + { + $name = tempnam(sys_get_temp_dir(), 'mustache-test'); + $mustache = new Mustache_Engine(array( + 'logger' => new Mustache_Logger_StreamLogger($name) + )); + + $result = $mustache->render('{{ foo }}{{> bar }}', array('foo' => 'FOO')); + $this->assertEquals('FOO', $result); + + $this->assertEmpty(file_get_contents($name)); + } + + public function testVerboseLoggingIsVerbose() + { + $name = tempnam(sys_get_temp_dir(), 'mustache-test'); + $mustache = new Mustache_Engine(array( + 'logger' => new Mustache_Logger_StreamLogger($name, Mustache_Logger::DEBUG) + )); + + $result = $mustache->render('{{ foo }}{{> bar }}', array('foo' => 'FOO')); + $this->assertEquals('FOO', $result); + + $log = file_get_contents($name); + + $this->assertContains("DEBUG: Instantiating template: ", $log); + $this->assertContains("WARNING: Partial not found: \"bar\"", $log); + } + private static function rmdir($path) { $path = rtrim($path, '/').'/'; diff --git a/test/Mustache/Test/Logger/AbstractLoggerTest.php b/test/Mustache/Test/Logger/AbstractLoggerTest.php new file mode 100644 index 0000000..733b2eb --- /dev/null +++ b/test/Mustache/Test/Logger/AbstractLoggerTest.php @@ -0,0 +1,60 @@ +emergency('emergency message'); + $logger->alert('alert message'); + $logger->critical('critical message'); + $logger->error('error message'); + $logger->warning('warning message'); + $logger->notice('notice message'); + $logger->info('info message'); + $logger->debug('debug message'); + + $expected = array( + array(Mustache_Logger::EMERGENCY, 'emergency message', array()), + array(Mustache_Logger::ALERT, 'alert message', array()), + array(Mustache_Logger::CRITICAL, 'critical message', array()), + array(Mustache_Logger::ERROR, 'error message', array()), + array(Mustache_Logger::WARNING, 'warning message', array()), + array(Mustache_Logger::NOTICE, 'notice message', array()), + array(Mustache_Logger::INFO, 'info message', array()), + array(Mustache_Logger::DEBUG, 'debug message', array()), + ); + + $this->assertEquals($expected, $logger->log); + } +} + +class Mustache_Test_Logger_TestLogger extends Mustache_Logger_AbstractLogger +{ + public $log = array(); + + /** + * Logs with an arbitrary level. + * + * @param mixed $level + * @param string $message + * @param array $context + */ + public function log($level, $message, array $context = array()) + { + $this->log[] = array($level, $message, $context); + } +} diff --git a/test/Mustache/Test/Logger/StreamLoggerTest.php b/test/Mustache/Test/Logger/StreamLoggerTest.php new file mode 100644 index 0000000..9dfd4c2 --- /dev/null +++ b/test/Mustache/Test/Logger/StreamLoggerTest.php @@ -0,0 +1,206 @@ +log(Mustache_Logger::CRITICAL, 'message'); + + $this->assertEquals("CRITICAL: message\n", file_get_contents($name)); + } + + public function testAcceptsResource() + { + $name = tempnam(sys_get_temp_dir(), 'mustache-test'); + $file = fopen($name, 'a'); + $logger = new Mustache_Logger_StreamLogger($file); + $logger->log(Mustache_Logger::CRITICAL, 'message'); + + $this->assertEquals("CRITICAL: message\n", file_get_contents($name)); + } + + /** + * @expectedException LogicException + */ + public function testPrematurelyClosedStreamThrowsException() + { + $stream = tmpfile(); + $logger = new Mustache_Logger_StreamLogger($stream); + fclose($stream); + + $logger->log(Mustache_Logger::CRITICAL, 'message'); + } + + /** + * @dataProvider getLevels + */ + public function testLoggingThresholds($logLevel, $level, $shouldLog) + { + $stream = tmpfile(); + $logger = new Mustache_Logger_StreamLogger($stream, $logLevel); + $logger->log($level, "logged"); + + rewind($stream); + $result = fread($stream, 1024); + + if ($shouldLog) { + $this->assertContains("logged", $result); + } else { + $this->assertEmpty($result); + } + } + + public function getLevels() + { + // $logLevel, $level, $shouldLog + return array( + // identities + array(Mustache_Logger::EMERGENCY, Mustache_Logger::EMERGENCY, true), + array(Mustache_Logger::ALERT, Mustache_Logger::ALERT, true), + array(Mustache_Logger::CRITICAL, Mustache_Logger::CRITICAL, true), + array(Mustache_Logger::ERROR, Mustache_Logger::ERROR, true), + array(Mustache_Logger::WARNING, Mustache_Logger::WARNING, true), + array(Mustache_Logger::NOTICE, Mustache_Logger::NOTICE, true), + array(Mustache_Logger::INFO, Mustache_Logger::INFO, true), + array(Mustache_Logger::DEBUG, Mustache_Logger::DEBUG, true), + + // one above + array(Mustache_Logger::ALERT, Mustache_Logger::EMERGENCY, true), + array(Mustache_Logger::CRITICAL, Mustache_Logger::ALERT, true), + array(Mustache_Logger::ERROR, Mustache_Logger::CRITICAL, true), + array(Mustache_Logger::WARNING, Mustache_Logger::ERROR, true), + array(Mustache_Logger::NOTICE, Mustache_Logger::WARNING, true), + array(Mustache_Logger::INFO, Mustache_Logger::NOTICE, true), + array(Mustache_Logger::DEBUG, Mustache_Logger::INFO, true), + + // one below + array(Mustache_Logger::EMERGENCY, Mustache_Logger::ALERT, false), + array(Mustache_Logger::ALERT, Mustache_Logger::CRITICAL, false), + array(Mustache_Logger::CRITICAL, Mustache_Logger::ERROR, false), + array(Mustache_Logger::ERROR, Mustache_Logger::WARNING, false), + array(Mustache_Logger::WARNING, Mustache_Logger::NOTICE, false), + array(Mustache_Logger::NOTICE, Mustache_Logger::INFO, false), + array(Mustache_Logger::INFO, Mustache_Logger::DEBUG, false), + ); + } + + /** + * @dataProvider getLogMessages + */ + public function testLogging($level, $message, $context, $expected) + { + $stream = tmpfile(); + $logger = new Mustache_Logger_StreamLogger($stream, Mustache_Logger::DEBUG); + $logger->log($level, $message, $context); + + rewind($stream); + $result = fread($stream, 1024); + + $this->assertEquals($expected, $result); + } + + public function getLogMessages() + { + // $level, $message, $context, $expected + return array( + array(Mustache_Logger::DEBUG, 'debug message', array(), "DEBUG: debug message\n"), + array(Mustache_Logger::INFO, 'info message', array(), "INFO: info message\n"), + array(Mustache_Logger::NOTICE, 'notice message', array(), "NOTICE: notice message\n"), + array(Mustache_Logger::WARNING, 'warning message', array(), "WARNING: warning message\n"), + array(Mustache_Logger::ERROR, 'error message', array(), "ERROR: error message\n"), + array(Mustache_Logger::CRITICAL, 'critical message', array(), "CRITICAL: critical message\n"), + array(Mustache_Logger::ALERT, 'alert message', array(), "ALERT: alert message\n"), + array(Mustache_Logger::EMERGENCY, 'emergency message', array(), "EMERGENCY: emergency message\n"), + + // with context + array( + Mustache_Logger::ERROR, + 'error message', + array('name' => 'foo', 'number' => 42), + "ERROR: error message\n" + ), + + // with interpolation + array( + Mustache_Logger::ERROR, + 'error {name}-{number}', + array('name' => 'foo', 'number' => 42), + "ERROR: error foo-42\n" + ), + + // with iterpolation false positive + array( + Mustache_Logger::ERROR, + 'error {nothing}', + array('name' => 'foo', 'number' => 42), + "ERROR: error {nothing}\n" + ), + + // with interpolation injection + array( + Mustache_Logger::ERROR, + '{foo}', + array('foo' => '{bar}', 'bar' => 'FAIL'), + "ERROR: {bar}\n" + ), + ); + } + + public function testChangeLoggingLevels() + { + $stream = tmpfile(); + $logger = new Mustache_Logger_StreamLogger($stream); + + $logger->setLevel(Mustache_Logger::ERROR); + $this->assertEquals(Mustache_Logger::ERROR, $logger->getLevel()); + + $logger->log(Mustache_Logger::WARNING, 'ignore this'); + + $logger->setLevel(Mustache_Logger::INFO); + $this->assertEquals(Mustache_Logger::INFO, $logger->getLevel()); + + $logger->log(Mustache_Logger::WARNING, 'log this'); + + $logger->setLevel(Mustache_Logger::CRITICAL); + $this->assertEquals(Mustache_Logger::CRITICAL, $logger->getLevel()); + + $logger->log(Mustache_Logger::ERROR, 'ignore this'); + + rewind($stream); + $result = fread($stream, 1024); + + $this->assertEquals("WARNING: log this\n", $result); + } + + /** + * @expectedException InvalidArgumentException + */ + public function testThrowsInvalidArgumentExceptionWhenSettingUnknownLevels() + { + $logger = new Mustache_Logger_StreamLogger(tmpfile()); + $logger->setLevel('bacon'); + } + + /** + * @expectedException InvalidArgumentException + */ + public function testThrowsInvalidArgumentExceptionWhenLoggingUnknownLevels() + { + $logger = new Mustache_Logger_StreamLogger(tmpfile()); + $logger->log('bacon', 'CODE BACON ERROR!'); + } +}