Merge pull request #1237 from nextcloud/backport/1235/stable29

[stable29] fix: LogIterator duplicates and drops log entries

Author: icewind1991

lib/Log/LogIterator.php

@@ -29,13 +29,13 @@ class LogIterator implements \Iterator {
 	 * @var resource
 	 */
 	private $handle;
+	private string $dateFormat;
+	private \DateTimeZone $timezone;
+
 	private string $buffer = '';
+	private string $lastLine = '';
 	private int $position = 0;
-	private string $lastLine;
-
 	private int $currentKey = -1;
-	private string $dateFormat;
-	private \DateTimeZone $timezone;
 
 	public const CHUNK_SIZE = 8192; // how many chars do we try at once to find a new line
 
@@ -49,13 +49,15 @@ public function __construct($handle, string $dateFormat, string $timezone) {
 		$this->dateFormat = $dateFormat;
 		$this->timezone = new \DateTimeZone($timezone);
 		$this->rewind();
-		$this->next();
 	}
 
 	public function rewind(): void {
 		fseek($this->handle, 0, SEEK_END);
 		$this->position = ftell($this->handle);
-		$this->currentKey = 0;
+		$this->lastLine = '';
+		$this->buffer = '';
+		$this->currentKey = -1;
+		$this->next();
 	}
 
 	/**
@@ -92,13 +94,19 @@ public function next(): void {
 		while ($this->position >= 0) {
 			$newlinePos = strrpos($this->buffer, "\n");
 			if ($newlinePos !== false) {
+				if ($newlinePos + 1 === strlen($this->buffer)) {
+					// try again with truncated buffer if it ends with newline, i.e. on first call
+					$this->buffer = substr($this->buffer, 0, $newlinePos);
+					continue;
+				}
 				$this->lastLine = substr($this->buffer, $newlinePos + 1);
 				$this->buffer = substr($this->buffer, 0, $newlinePos);
 				$this->currentKey++;
 				return;
 			} elseif ($this->position === 0) {
 				$this->lastLine = $this->buffer;
 				$this->buffer = '';
+				$this->currentKey++;
 				return;
 			} else {
 				$this->fillBuffer();
@@ -111,11 +119,7 @@ public function valid(): bool {
 			return false;
 		}
 
-		if ($this->position > 0) {
-			return true;
-		}
-
-		if ($this->lastLine === '') {
+		if ($this->lastLine === '' && $this->position === 0) {
 			return false;
 		}
 

tests/Unit/Log/LogIteratorTest.php

@@ -52,4 +52,21 @@ public function testGetLines() {
 		$this->assertEquals(2, $entries[0]['reqId']);
 		$this->assertEquals(1, $entries[1]['reqId']);
 	}
+
+	public function testGetLinesTrailingNewLine() {
+		$log = $this->getLogIterator(
+			"{\"reqId\":\"1\",\"level\":3,\"time\":\"2019-11-04T18:50:57+00:00\",\"remoteAddr\":\"127.0.0.1\",\"user\":\"admin\",\"app\":\"comments\",\"method\":\"GET\",\"url\":\"/settings/admin/logging\",\"message\":{\"Exception\":\"RuntimeException\",\"Message\":\"App class OCA\\\\Comments\\\\AppInfo\\\\Application is not setup via query() but directly\",\"Code\":0,\"Trace\":[{\"file\":\"/srv/http/cloud/apps/comments/lib/AppInfo/Application.php\",\"line\":42,\"function\":\"__construct\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\",\"args\":[\"comments\",[]]},{\"file\":\"/srv/http/cloud/apps/comments/appinfo/app.php\",\"line\":24,\"function\":\"__construct\",\"class\":\"OCA\\\\Comments\\\\AppInfo\\\\Application\",\"type\":\"->\",\"args\":[]},{\"file\":\"/srv/http/cloud/lib/private/legacy/app.php\",\"line\":260,\"args\":[\"/srv/http/cloud/apps/comments/appinfo/app.php\"],\"function\":\"require_once\"},{\"file\":\"/srv/http/cloud/lib/private/legacy/app.php\",\"line\":154,\"function\":\"requireAppFile\",\"class\":\"OC_App\",\"type\":\"::\",\"args\":[\"comments\"]},{\"file\":\"/srv/http/cloud/lib/private/legacy/app.php\",\"line\":127,\"function\":\"loadApp\",\"class\":\"OC_App\",\"type\":\"::\",\"args\":[\"comments\"]},{\"file\":\"/srv/http/cloud/lib/base.php\",\"line\":991,\"function\":\"loadApps\",\"class\":\"OC_App\",\"type\":\"::\",\"args\":[]},{\"file\":\"/srv/http/cloud/index.php\",\"line\":42,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\",\"args\":[]}],\"File\":\"/srv/http/cloud/lib/public/AppFramework/App.php\",\"Line\":77,\"CustomMessage\":\"--\"},\"userAgent\":\"Mozilla\",\"version\":\"18.0.0.1\"}
+{\"reqId\":\"2\",\"level\":3,\"time\":\"2019-11-04T18:50:57+00:00\",\"remoteAddr\":\"127.0.0.1\",\"user\":\"admin\",\"app\":\"gallery\",\"method\":\"GET\",\"url\":\"/settings/admin/logging\",\"message\":{\"Exception\":\"RuntimeException\",\"Message\":\"App class OCA\\\\Gallery\\\\AppInfo\\\\Application is not setup via query() but directly\",\"Code\":0,\"Trace\":[{\"file\":\"/srv/http/cloud/apps/gallery/lib/AppInfo/Application.php\",\"line\":70,\"function\":\"__construct\",\"class\":\"OCP\\\\AppFramework\\\\App\",\"type\":\"->\",\"args\":[\"gallery\",[]]},{\"file\":\"/srv/http/cloud/apps/gallery/appinfo/app.php\",\"line\":19,\"function\":\"__construct\",\"class\":\"OCA\\\\Gallery\\\\AppInfo\\\\Application\",\"type\":\"->\",\"args\":[]},{\"file\":\"/srv/http/cloud/lib/private/legacy/app.php\",\"line\":260,\"args\":[\"/srv/http/cloud/apps/gallery/appinfo/app.php\"],\"function\":\"require_once\"},{\"file\":\"/srv/http/cloud/lib/private/legacy/app.php\",\"line\":154,\"function\":\"requireAppFile\",\"class\":\"OC_App\",\"type\":\"::\",\"args\":[\"gallery\"]},{\"file\":\"/srv/http/cloud/lib/private/legacy/app.php\",\"line\":127,\"function\":\"loadApp\",\"class\":\"OC_App\",\"type\":\"::\",\"args\":[\"gallery\"]},{\"file\":\"/srv/http/cloud/lib/base.php\",\"line\":991,\"function\":\"loadApps\",\"class\":\"OC_App\",\"type\":\"::\",\"args\":[]},{\"file\":\"/srv/http/cloud/index.php\",\"line\":42,\"function\":\"handleRequest\",\"class\":\"OC\",\"type\":\"::\",\"args\":[]}],\"File\":\"/srv/http/cloud/lib/public/AppFramework/App.php\",\"Line\":77,\"CustomMessage\":\"--\"},\"userAgent\":\"Mozilla\",\"version\":\"18.0.0.1\"}
+"
+		);
+
+		/** @var array[] $entries */
+		$entries = iterator_to_array($log);
+
+		$this->assertCount(2, $entries);
+
+		// sorted last first
+		$this->assertEquals(2, $entries[0]['reqId']);
+		$this->assertEquals(1, $entries[1]['reqId']);
+	}
 }