diff --git a/CHANGELOG b/CHANGELOG index 1a14bfd..2a00bbb 100644 --- a/CHANGELOG +++ b/CHANGELOG @@ -128,6 +128,11 @@ and made Apache reject the whole file); the 403 message is escaped; and changes of the file are done while holding a lock, so that clients getting blocked at the same time don't overwrite each other's lines + - Log file (#185): besides being rotated once it exceeds a configurable size + (default 5 MB), entries older than a configurable number of days (default + 28) are now deleted from it once a day, also when logging was disabled in + the meantime; the log files are removed when the plugin is uninstalled, and + the component's log view got buttons to prune or clear the log - Security: the plugin's log file is rotated at 5 MB, and the username statistics (which aren't purged by age) are limited to 10000 usernames, removing those with the fewest attempts first, so a visitor can't fill up diff --git a/src/Extension/Bfstop.php b/src/Extension/Bfstop.php index 0535c15..95aa6d4 100644 --- a/src/Extension/Bfstop.php +++ b/src/Extension/Bfstop.php @@ -310,7 +310,8 @@ private function accountThrottleIfNeeded($logEntry) private function init() { - $this->logger = new LoggerHelper($this->getIntParam('logLevel', LoggerHelper::Disabled)); + $this->logger = new LoggerHelper($this->getIntParam('logLevel', LoggerHelper::Disabled), + LoggerHelper::maxBytesFromMegabytes($this->getIntParam('logMaxSize', LoggerHelper::DefaultMaxSizeMB))); $this->mydb = new DatabaseHelper($this->logger); $this->notifier = new NotifierHelper($this->logger, $this->mydb, $this->params->get('emailaddress', ''), @@ -627,6 +628,7 @@ public function onAfterInitialise($event) $this->mydb->trimUsernameStats(); $this->mydb->pruneKnownIps(); $this->mydb->purgeExpiredUnblockTokens(); + LoggerHelper::pruneByAge($this->getIntParam('logKeepDays', LoggerHelper::DefaultKeepDays)); $this->params->set('lastPurge', $now); $this->mydb->saveLastPurge($now); } diff --git a/src/Helper/LoggerHelper.php b/src/Helper/LoggerHelper.php index b5277cc..01dd99c 100644 --- a/src/Helper/LoggerHelper.php +++ b/src/Helper/LoggerHelper.php @@ -19,17 +19,25 @@ class LoggerHelper public const LogCategory = 'bfstop'; public const Disabled = -1; public const LogFile = 'plg_system_bfstop.log.php'; + // the log file moved out of the way when it gets too big; like the log + // file it has to end in .php, as the web server must not hand out its contents + public const RotatedLogFile = 'plg_system_bfstop.1.log.php'; + public const DefaultMaxSizeMB = 5; + public const DefaultKeepDays = 28; // the log is rotated once it exceeds this size, so it can't fill up the // disk (a visitor can make the plugin log by failing logins) - public const MaxLogFileBytes = 5242880; + public const MaxLogFileBytes = self::DefaultMaxSizeMB * 1048576; - public function __construct($log_level) + private $maxBytes; + + public function __construct($log_level, $maxBytes = self::MaxLogFileBytes) { $this->log_level = $log_level; + $this->maxBytes = $maxBytes; $priorities = Log::ALL; if ($log_level > self::Disabled) { - self::rotateIfTooBig(); + self::rotateIfTooBig($maxBytes); Log::addLogger(array( 'text_file' => self::LogFile, 'text_entry_format' => @@ -40,21 +48,52 @@ public function __construct($log_level) } } + /** + * The size limit of the log file in bytes, from the "log size limit" + * setting (given in MB); invalid values fall back to the default. + */ + public static function maxBytesFromMegabytes($megabytes) + { + $megabytes = (int) $megabytes; + return ($megabytes > 0 ? $megabytes : self::DefaultMaxSizeMB) * 1048576; + } + + private static function getLogPath() + { + $logPath = Factory::getApplication()->get('log_path'); + return $logPath ? rtrim($logPath, '/\\') : null; + } + + /** + * Full paths of the log file and of its previous generation (whether + * they exist or not); empty if the log directory isn't known. + */ + public static function getLogFiles() + { + $logPath = self::getLogPath(); + return $logPath === null ? array() : array( + $logPath.'/'.self::LogFile, + $logPath.'/'.self::RotatedLogFile); + } + /** * Moves the log file out of the way once it is too big, keeping one - * previous generation. The old file keeps a .php extension (the file - * names end in .log.php) as the web server must not hand out its contents. + * previous generation. */ public static function rotateIfTooBig($maxBytes = self::MaxLogFileBytes) { try { - $logPath = Factory::getApplication()->get('log_path'); + $logPath = self::getLogPath(); + if ($logPath === null) + { + return; + } $file = $logPath.'/'.self::LogFile; clearstatcache(true, $file); - if ($logPath && is_file($file) && filesize($file) > $maxBytes) + if (is_file($file) && filesize($file) > $maxBytes) { - @rename($file, $logPath.'/'.str_replace('.log.php', '.1.log.php', self::LogFile)); + @rename($file, $logPath.'/'.self::RotatedLogFile); } } catch (\Throwable $e) @@ -63,6 +102,105 @@ public static function rotateIfTooBig($maxBytes = self::MaxLogFileBytes) } } + /** + * Removes the log entries older than the given number of days from the log + * file and its previous generation, independent of the log level + * (there may be leftovers from the time logging was enabled). + * @return int the number of entries removed + */ + public static function pruneByAge($days) + { + $days = (int) $days; + if ($days < 1) + { + return 0; + } + $removed = 0; + foreach (self::getLogFiles() as $file) + { + try + { + $removed += self::pruneFile($file, time() - $days * 86400); + } + catch (\Throwable $e) + { + // see rotateIfTooBig() + } + } + return $removed; + } + + /** + * Rewrites the file in place, without the entries from before $cutoff. + * Every entry starts with a timestamp; lines that don't (e.g. the file + * header, or a message containing line breaks) are kept or dropped + * together with the entry before them. Entries other requests add while + * the file is rewritten may get lost, which is acceptable for a log. + */ + private static function pruneFile($file, $cutoff) + { + clearstatcache(true, $file); + if (!is_file($file) || !($handle = @fopen($file, 'c+'))) + { + return 0; + } + $removed = 0; + try + { + if (!flock($handle, LOCK_EX | LOCK_NB)) + { + return 0; // somebody else is pruning right now + } + $kept = tmpfile(); + $keep = true; + while (($line = fgets($handle)) !== false) + { + if (preg_match('/^\d{4}-\d\d-\d\dT\S+/', $line, $match)) + { + $time = strtotime($match[0]); + $keep = ($time === false || $time >= $cutoff); + $removed += $keep ? 0 : 1; + } + if ($keep) + { + fwrite($kept, $line); + } + } + if ($removed > 0) + { + rewind($kept); + rewind($handle); + ftruncate($handle, 0); + stream_copy_to_stream($kept, $handle); + fflush($handle); + } + fclose($kept); + flock($handle, LOCK_UN); + } + finally + { + fclose($handle); + } + return $removed; + } + + /** + * Deletes the log file and its previous generation. + * @return int the number of files deleted + */ + public static function deleteLogFiles() + { + $deleted = 0; + foreach (self::getLogFiles() as $file) + { + if (is_file($file) && @unlink($file)) + { + ++$deleted; + } + } + return $deleted; + } + public function isEnabled($priority = Log::ERROR) { return $priority <= $this->log_level; diff --git a/tests/Integration/LoggerHelperTest.php b/tests/Integration/LoggerHelperTest.php index 8cd765f..b3c1d16 100644 --- a/tests/Integration/LoggerHelperTest.php +++ b/tests/Integration/LoggerHelperTest.php @@ -21,7 +21,7 @@ protected function setUp(): void parent::setUp(); $logPath = Factory::getApplication()->get('log_path'); $this->file = $logPath.'/'.LoggerHelper::LogFile; - $this->rotated = $logPath.'/plg_system_bfstop.1.log.php'; + $this->rotated = $logPath.'/'.LoggerHelper::RotatedLogFile; $this->backup = array(); foreach (array($this->file, $this->rotated) as $file) { @@ -73,4 +73,91 @@ public function testDisabledLoggingDoesntTouchTheFile() new LoggerHelper(LoggerHelper::Disabled); $this->assertFileExists($this->file); } + + public function testSizeLimitIsConfigurable() + { + file_put_contents($this->file, str_repeat('x', 2000)); + new LoggerHelper(8, 1000); + $this->assertFileDoesNotExist($this->file); + $this->assertFileExists($this->rotated); + file_put_contents($this->file, str_repeat('x', 2000)); + new LoggerHelper(8, 5000); + $this->assertFileExists($this->file); + } + + public function testSizeLimitFromSetting() + { + $this->assertSame(3 * 1048576, LoggerHelper::maxBytesFromMegabytes(3)); + $this->assertSame(LoggerHelper::MaxLogFileBytes, LoggerHelper::maxBytesFromMegabytes(0)); + $this->assertSame(LoggerHelper::MaxLogFileBytes, LoggerHelper::maxBytesFromMegabytes(-2)); + } + + private static function entry($daysAgo, $message) + { + return gmdate('c', time() - $daysAgo * 86400 - 60).' INFO '.$message."\n"; + } + + private static function header() + { + return "#\n#Date: 2021-09-17 08:50:26 UTC\n#Software: Joomla\n\n". + "#Fields: datetime\tpriority\tmessage\n\n"; + } + + public function testPruneRemovesOldEntriesOnly() + { + file_put_contents($this->file, self::header(). + self::entry(40, 'ancient'). + "continuation of the ancient entry\n". + self::entry(29, 'old'). + self::entry(27, 'recent'). + "continuation of the recent entry\n". + self::entry(0, 'new')); + $this->assertSame(2, LoggerHelper::pruneByAge(28)); + $this->assertSame(self::header(). + self::entry(27, 'recent'). + "continuation of the recent entry\n". + self::entry(0, 'new'), + file_get_contents($this->file)); + } + + public function testPruneAlsoCoversThePreviousGeneration() + { + file_put_contents($this->rotated, self::header().self::entry(100, 'ancient')); + file_put_contents($this->file, self::header().self::entry(1, 'new')); + $this->assertSame(1, LoggerHelper::pruneByAge(28)); + $this->assertSame(self::header(), file_get_contents($this->rotated)); + $this->assertSame(self::header().self::entry(1, 'new'), file_get_contents($this->file)); + } + + public function testPruneWithoutAgeKeepsEverything() + { + $content = self::header().self::entry(400, 'ancient'); + file_put_contents($this->file, $content); + $this->assertSame(0, LoggerHelper::pruneByAge(0)); + $this->assertSame($content, file_get_contents($this->file)); + } + + public function testPruneWithoutLogFileIsFine() + { + $this->assertSame(0, LoggerHelper::pruneByAge(28)); + $this->assertFileDoesNotExist($this->file); + } + + public function testPruneWorksWhileLoggingIsDisabled() + { + file_put_contents($this->file, self::header().self::entry(40, 'ancient')); + new LoggerHelper(LoggerHelper::Disabled); + $this->assertSame(1, LoggerHelper::pruneByAge(28)); + $this->assertSame(self::header(), file_get_contents($this->file)); + } + + public function testDeleteLogFiles() + { + file_put_contents($this->file, 'a'); + file_put_contents($this->rotated, 'b'); + $this->assertSame(2, LoggerHelper::deleteLogFiles()); + $this->assertFileDoesNotExist($this->file); + $this->assertFileDoesNotExist($this->rotated); + $this->assertSame(0, LoggerHelper::deleteLogFiles()); + } } diff --git a/updatescript.php b/updatescript.php index 114cf93..3e0b7d4 100644 --- a/updatescript.php +++ b/updatescript.php @@ -32,7 +32,25 @@ public function install(InstallerAdapter $adapter) $db->execute(); } - public function uninstall(InstallerAdapter $adapter) {} + public function uninstall(InstallerAdapter $adapter) + { + // the log file holds IP addresses and usernames; don't leave it behind + try + { + $logPath = Factory::getApplication()->get('log_path'); + foreach (array('plg_system_bfstop.log.php', 'plg_system_bfstop.1.log.php') as $file) + { + if ($logPath && is_file($logPath.'/'.$file)) + { + @unlink($logPath.'/'.$file); + } + } + } + catch (\Throwable $e) + { + // a leftover log must not make the uninstallation fail + } + } public function preflight($type, InstallerAdapter $adapter) {} public function postflight($type, InstallerAdapter $adapter)