Delete old log entries by age; configurable log size/retention; remove logs on uninstall

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

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);
 		}

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;

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 "#<?php die('Forbidden.'); ?>\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());
+	}
 }

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)