diff --git a/src/Mustache/Engine.php b/src/Mustache/Engine.php index 34d3ce2..5eafe81 100644 --- a/src/Mustache/Engine.php +++ b/src/Mustache/Engine.php @@ -34,12 +34,13 @@ class Mustache_Engine // Environment private $templateClassPrefix = '__Mustache_'; private $cache = null; + private $cacheFileMode = null; private $loader; private $partialsLoader; private $helpers; private $escape; private $charset = 'UTF-8'; - private $cacheFileMode = null; + private $logger; /** * Mustache class constructor. @@ -81,6 +82,11 @@ class Mustache_Engine * * // Character set for `htmlspecialchars`. Defaults to 'UTF-8'. Use 'UTF-8'. * 'charset' => 'ISO-8859-1', + * + * // A Mustache Logger instance. No logging will occur unless this is set. Using a PSR-3 compatible + * // logging library -- such as Monolog -- is highly recommended. A simple stream logger implementation is + * // available as well: + * 'logger' => new Mustache_StreamLogger('php://stderr'), * ); * * @param array $options (default: array()) @@ -126,6 +132,10 @@ class Mustache_Engine if (isset($options['charset'])) { $this->charset = $options['charset']; } + + if (isset($options['logger'])) { + $this->setLogger($options['logger']); + } } /** @@ -330,6 +340,30 @@ class Mustache_Engine $this->getHelpers()->remove($name); } + /** + * Set the Mustache Logger instance. + * + * @param Mustache_Logger|Psr\Log\LoggerInterface $logger + */ + public function setLogger($logger = null) + { + if ($logger !== null && !($logger instanceof Mustache_Logger || is_a($logger, 'Psr\\Log\\LoggerInterface'))) { + throw new InvalidArgumentException('Expected an instance of Mustache_Logger or Psr\\Log\\LoggerInterface.'); + } + + $this->logger = $logger; + } + + /** + * Get the current Mustache Logger instance. + * + * @return Mustache_Logger|Psr\Log\LoggerInterface + */ + public function getLogger() + { + return $this->logger; + } + /** * Set the Mustache Tokenizer instance. * @@ -453,7 +487,12 @@ class Mustache_Engine try { return $this->loadSource($this->getPartialsLoader()->load($name)); } catch (InvalidArgumentException $e) { - // If the named partial cannot be found, return null. + // If the named partial cannot be found, log then return null. + $this->log( + Mustache_Logger::WARNING, + 'Partial not found: "{name}"', + array('name' => $name) + ); } } @@ -496,15 +535,33 @@ class Mustache_Engine if (!class_exists($className, false)) { if ($fileName = $this->getCacheFilename($source)) { if (!is_file($fileName)) { + $this->log( + Mustache_Logger::DEBUG, + 'Writing "{className}" class to template cache: "{fileName}"', + array('className' => $className, 'fileName' => $fileName) + ); + $this->writeCacheFile($fileName, $this->compile($source)); } require_once $fileName; } else { + $this->log( + Mustache_Logger::WARNING, + 'Template cache disabled, evaluating "{className}" class at runtime', + array('className' => $className) + ); + eval('?>'.$this->compile($source)); } } + $this->log( + Mustache_Logger::DEBUG, + 'Instantiating template: "{className}"', + array('className' => $className) + ); + $this->templates[$className] = new $className($this); } @@ -553,6 +610,12 @@ class Mustache_Engine $tree = $this->parse($source); $name = $this->getTemplateClassName($source); + $this->log( + Mustache_Logger::INFO, + 'Compiling template to "{className}" class', + array('className' => $name) + ); + return $this->getCompiler()->compile($source, $tree, $name, isset($this->escape), $this->charset); } @@ -573,7 +636,7 @@ class Mustache_Engine /** * Helper method to dump a generated Mustache Template subclass to the file cache. * - * @throws RuntimeException if unable to create the cache directory or write $fileName + * @throws RuntimeException if unable to create the cache directory or write to $fileName. * * @param string $fileName * @param string $source @@ -584,12 +647,25 @@ class Mustache_Engine { $dirName = dirname($fileName); if (!is_dir($dirName)) { + $this->log( + Mustache_Logger::INFO, + 'Creating Mustache template cache directory: "{dirName}"', + array('dirName' => $dirName) + ); + @mkdir($dirName, 0777, true); if (!is_dir($dirName)) { throw new RuntimeException(sprintf('Failed to create cache directory "%s".', $dirName)); } + } + $this->log( + Mustache_Logger::DEBUG, + 'Caching compiled template to "{fileName}"', + array('fileName' => $fileName) + ); + $tempFile = tempnam($dirName, basename($fileName)); if (false !== @file_put_contents($tempFile, $source)) { if (@rename($tempFile, $fileName)) { @@ -598,8 +674,28 @@ class Mustache_Engine return; } + + $this->log( + Mustache_Logger::ERROR, + 'Unable to rename Mustache temp cache file: "{tempName}" -> "{fileName}"', + array('tempName' => $tempFile, 'fileName' => $fileName) + ); } throw new RuntimeException(sprintf('Failed to write cache file "%s".', $fileName)); } + + /** + * Add a log record if logging is enabled. + * + * @param integer $level The logging level + * @param string $message The log message + * @param array $context The log context + */ + private function log($level, $message, array $context = array()) + { + if (isset($this->logger)) { + $this->logger->log($level, $message, $context); + } + } } diff --git a/src/Mustache/Logger.php b/src/Mustache/Logger.php new file mode 100644 index 0000000..e08359a --- /dev/null +++ b/src/Mustache/Logger.php @@ -0,0 +1,135 @@ +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 new file mode 100644 index 0000000..7f3fd50 --- /dev/null +++ b/src/Mustache/Logger/StreamLogger.php @@ -0,0 +1,188 @@ + 100, + self::INFO => 200, + self::NOTICE => 250, + self::WARNING => 300, + self::ERROR => 400, + self::CRITICAL => 500, + self::ALERT => 550, + self::EMERGENCY => 600, + ); + + protected $stream = null; + 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 + */ + public function __construct($stream, $level = Mustache_Logger::ERROR) + { + $this->setLevel($level); + + if (is_resource($stream)) { + $this->stream = $stream; + } else { + $this->url = $stream; + } + } + + /** + * Close stream resources. + */ + public function __destruct() + { + if (is_resource($this->stream)) { + fclose($this->stream); + } + } + + /** + * Set the minimum logging level. + * + * @throws InvalidArgumentException if the logging level is unknown. + * + * @param integer $level The minimum logging level which will be written + */ + public function setLevel($level) + { + if (!array_key_exists($level, self::$levels)) { + throw new InvalidArgumentException('Unexpected logging level: ' . $level); + } + + $this->level = $level; + } + + /** + * Get the current minimum logging level. + * + * @return integer + */ + public function getLevel() + { + return $this->level; + } + + /** + * Logs with an arbitrary level. + * + * @throws InvalidArgumentException if the logging level is unknown. + * + * @param mixed $level + * @param string $message + * @param array $context + */ + public function log($level, $message, array $context = array()) + { + if (!array_key_exists($level, self::$levels)) { + throw new InvalidArgumentException('Unexpected logging level: ' . $level); + } + + if (self::$levels[$level] >= self::$levels[$this->level]) { + $this->writeLog($level, $message, $context); + } + } + + /** + * Write a record to the log. + * + * @param integer $level The logging level + * @param string $message The log message + * @param array $context The log context + */ + protected function writeLog($level, $message, array $context = array()) + { + if (!is_resource($this->stream)) { + if (!isset($this->url)) { + throw new LogicException('Missing stream url, the stream can not be opened. This may be caused by a premature call to close().'); + } + + $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 + } + } + + fwrite($this->stream, self::formatLine($level, $message, $context)); + } + + /** + * Gets the name of the logging level. + * + * @throws InvalidArgumentException if the logging level is unknown. + * + * @param integer $level + * + * @return string + */ + protected static function getLevelName($level) + { + return strtoupper($level); + } + + /** + * Format a log line for output. + * + * @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) { + $replace['{' . $key . '}'] = $val; + } + + // 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!'); + } +}