diff --git a/lib/Controller/LogController.php b/lib/Controller/LogController.php index 486c1c29a..439e82fe8 100644 --- a/lib/Controller/LogController.php +++ b/lib/Controller/LogController.php @@ -16,6 +16,7 @@ use OCP\AppFramework\Http; use OCP\AppFramework\Http\Attribute\AuthorizedAdminSetting; use OCP\AppFramework\Http\JSONResponse; +use OCP\AppFramework\Http\StreamTraversableResponse; use OCP\IRequest; use Psr\Log\LoggerInterface; @@ -26,6 +27,8 @@ * @psalm-api */ class LogController extends Controller { + /** Maximum number of entries of the shown levels a search or a poll goes through, hidden ones are not counted */ + private const MAX_SCANNED_ENTRIES = 100000; public function __construct( $appName, @@ -41,10 +44,9 @@ public function __construct( * @param string $query * @param int $count * @param int $offset - * @return JSONResponse */ #[AuthorizedAdminSetting(settings: Admin::class)] - public function get($query = '', $count = 50, $offset = 0): JSONResponse { + public function get($query = '', $count = 50, $offset = 0): JSONResponse|StreamTraversableResponse { $logType = $this->settingsService->getLoggingType(); // we only support web access when `log_type` is set to `file` (the default) if ($logType !== 'file') { @@ -55,26 +57,12 @@ public function get($query = '', $count = 50, $offset = 0): JSONResponse { $iterator = $this->logIteratorFactory->getLogIterator($this->settingsService->getShownLevels()); if ($query !== '') { - $iterator = new \LimitIterator($iterator, 0, 100000); // limit the number of message we search to avoid huge search times - $iterator->rewind(); - $iterator = new SearchFilter($iterator, $query); - $iterator->rewind(); - return $this->responseFromIterator($iterator, $count, $offset); + $iterator = new SearchFilter(new \LimitIterator($iterator, 0, self::MAX_SCANNED_ENTRIES), $query); } return $this->responseFromIterator($iterator, $count, $offset); } - /** - * @brief Gets the last item in the log, bypassing any cache. - * @return mixed - */ - private function getLastItem() { - $iterator = $this->logIteratorFactory->getLogIterator($this->settingsService->getShownLevels()); - $iterator->rewind(); - return $iterator->current(); - } - /** * @brief Use to poll for new log messages since $lastReqId. * @@ -89,7 +77,7 @@ private function getLastItem() { * request. */ #[AuthorizedAdminSetting(settings: Admin::class)] - public function poll(string $lastReqId): JSONResponse { + public function poll(string $lastReqId): JSONResponse|StreamTraversableResponse { $logType = $this->settingsService->getLoggingType(); // we only support web access when `log_type` is set to `file` (the default) if ($logType !== 'file') { @@ -97,50 +85,91 @@ public function poll(string $lastReqId): JSONResponse { return new JSONResponse([], Http::STATUS_FAILED_DEPENDENCY); } - $lastItem = $this->getLastItem(); - if ($lastItem === null || $lastItem['reqId'] === $lastReqId) { - return new JSONResponse([]); - } - $iterator = $this->logIteratorFactory->getLogIterator($this->settingsService->getShownLevels()); $iterator->rewind(); - $data = []; - - while ($iterator->valid()) { - $line = $iterator->current(); - - if ($line['reqId'] === $lastReqId) { - break; - } + return $this->streamJson($this->encodeEntriesNewerThan($iterator, $lastReqId)); + } - if (!is_null($line)) { - $line['id'] = uniqid(); - $data[] = $line; - } + protected function responseFromIterator(\Iterator $iterator, int $count, int $offset): StreamTraversableResponse { + $iterator->rewind(); + for ($i = 0; $i < $offset && $iterator->valid(); $i++) { $iterator->next(); } + return $this->streamJson($this->encodePage($iterator, $count)); + } - return new JSONResponse($data); + /** + * @return \Generator + */ + private function encodeEntriesNewerThan(\Iterator $iterator, string $lastReqId): \Generator { + yield '['; + yield from $this->encodeEntries($this->takeEntriesNewerThan($iterator, $lastReqId)); + yield ']'; } - protected function responseFromIterator(\Iterator $iterator, $count, $offset): JSONResponse { - $iterator->rewind(); - for ($i = 0; $i < $offset; $i++) { - $iterator->next(); + /** + * @return \Generator + */ + private function encodePage(\Iterator $iterator, int $count): \Generator { + yield '{"data":['; + yield from $this->encodeEntries($this->takeEntries($iterator, $count)); + yield '],"remain":' . ($iterator->valid() ? 'true' : 'false') . '}'; + } + + /** + * One part per entry, so only a single entry is held in memory at a time + * + * @param iterable $entries + * @return \Generator + */ + private function encodeEntries(iterable $entries): \Generator { + $separator = ''; + foreach ($entries as $entry) { + $entry['id'] = uniqid(); + yield $separator . $this->encodeJson($entry); + $separator = ','; } - $data = []; + } + + /** + * Leaves the iterator behind the last taken entry, so its valid() tells whether entries remain + * + * @return \Generator + */ + private function takeEntries(\Iterator $iterator, int $count): \Generator { for ($i = 0; $i < $count && $iterator->valid(); $i++) { - $line = $iterator->current(); - if (!is_null($line)) { - $line['id'] = uniqid(); - $data[] = $line; - } + yield $iterator->current(); $iterator->next(); } - return new JSONResponse([ - 'data' => $data, - 'remain' => $iterator->valid() - ]); + } + + /** + * @return \Generator + */ + private function takeEntriesNewerThan(\Iterator $iterator, string $lastReqId): \Generator { + foreach ($this->takeEntries($iterator, self::MAX_SCANNED_ENTRIES) as $entry) { + if (($entry['reqId'] ?? null) === $lastReqId) { + return; + } + yield $entry; + } + } + + /** + * @param \Generator $json + */ + private function streamJson(\Generator $json): StreamTraversableResponse { + return new StreamTraversableResponse($json, Http::STATUS_OK, ['Content-Type' => 'application/json; charset=utf-8']); + } + + /** + * Like JSONResponse::render(), but never fails and replaces values JSON cannot represent (e.g. INF), as the + * response is already being sent and skipping the entry would shift the offsets of the next pages + * + * @psalm-suppress FalsableReturnStatement, InvalidFalsableReturnType + */ + private function encodeJson(mixed $data): string { + return json_encode($data, JSON_HEX_TAG | JSON_PARTIAL_OUTPUT_ON_ERROR, 2048); } } diff --git a/lib/Log/LogIteratorFactory.php b/lib/Log/LogIteratorFactory.php index 5f571bb6b..f1d8a3996 100644 --- a/lib/Log/LogIteratorFactory.php +++ b/lib/Log/LogIteratorFactory.php @@ -41,7 +41,8 @@ public function getLogIterator(array $levels): \Iterator { if ($handle) { $iterator = new LogIterator($handle, $dateFormat, $timezone); return new \CallbackFilterIterator($iterator, function ($logItem) use ($levels) { - return $logItem && in_array($logItem['level'], $levels); + // isset() also rules out lines that decode to a scalar + return isset($logItem['level']) && in_array($logItem['level'], $levels); }); } else { throw new \Exception('Error while opening ' . $log->getLogFilePath()); diff --git a/lib/Log/SearchFilter.php b/lib/Log/SearchFilter.php index 4d6f30ed0..ac8d6d2cc 100644 --- a/lib/Log/SearchFilter.php +++ b/lib/Log/SearchFilter.php @@ -24,7 +24,6 @@ class SearchFilter extends \FilterIterator { public function __construct(\Iterator $iterator, string $query) { parent::__construct($iterator); - $this->rewind(); $this->query = strtolower($query); $this->levels = ['Debug', 'Info', 'Warning', 'Error', 'Fatal']; } diff --git a/tests/Unit/Controller/LogControllerTest.php b/tests/Unit/Controller/LogControllerTest.php index 635564b57..28f9ce523 100644 --- a/tests/Unit/Controller/LogControllerTest.php +++ b/tests/Unit/Controller/LogControllerTest.php @@ -12,7 +12,12 @@ use OCA\LogReader\Log\LogIterator; use OCA\LogReader\Log\LogIteratorFactory; use OCA\LogReader\Service\SettingsService; +use OCP\AppFramework\Http\IOutput; +use OCP\AppFramework\Http\JSONResponse; +use OCP\AppFramework\Http\Response; +use OCP\AppFramework\Http\StreamTraversableResponse; use OCP\IRequest; +use PHPUnit\Framework\Attributes\DataProvider; use PHPUnit\Framework\MockObject\MockObject; use Psr\Log\LoggerInterface; use Test\TestCase; @@ -70,6 +75,113 @@ private function mockLogWithEntries(string $log): void { ->willReturnCallback(fn () => $this->getLogIterator($log)); } + private function getLogWithEntries(int $count): string { + $lines = []; + for ($reqId = 1; $reqId <= $count; $reqId++) { + $lines[] = '{"reqId":"' . $reqId . '","level":3,"time":"2019-11-04T18:50:57+00:00","app":"files","message":"Entry ' . $reqId . '"}'; + } + return implode("\n", $lines); + } + + /** + * @return list the parts the response sends, in order + */ + private function getOutputParts(StreamTraversableResponse $response): array { + $parts = []; + $output = $this->createStub(IOutput::class); + $output->method('setOutput') + ->willReturnCallback(function (string $part) use (&$parts): void { + $parts[] = $part; + }); + $response->callback($output); + return $parts; + } + + private function getResponseData(Response $response): mixed { + if ($response instanceof JSONResponse) { + return $response->getData(); + } + $this->assertInstanceOf(StreamTraversableResponse::class, $response); + return json_decode(implode('', $this->getOutputParts($response)), true, flags: JSON_THROW_ON_ERROR); + } + + public function testGetReturnsNewestEntriesFirst(): void { + $this->mockLogWithEntries($this->getLogWithEntries(3)); + + $response = $this->logController->get(); + $data = $this->getResponseData($response); + + $this->assertSame('application/json; charset=utf-8', $response->getHeaders()['Content-Type']); + $this->assertSame(['3', '2', '1'], array_column($data['data'], 'reqId')); + $this->assertSame('Entry 3', $data['data'][0]['message']); + $this->assertCount(3, array_unique(array_column($data['data'], 'id'))); + $this->assertFalse($data['remain']); + } + + public function testGetReturnsRequestedPage(): void { + $this->mockLogWithEntries($this->getLogWithEntries(5)); + + $data = $this->getResponseData($this->logController->get('', 2, 1)); + + $this->assertSame(['4', '3'], array_column($data['data'], 'reqId')); + $this->assertTrue($data['remain']); + } + + public function testGetReturnsEmptyPageForEmptyLog(): void { + $this->mockLogWithEntries(''); + + $data = $this->getResponseData($this->logController->get()); + + $this->assertSame(['data' => [], 'remain' => false], $data); + } + + public function testGetFiltersBySearchQuery(): void { + $this->mockLogWithEntries($this->getLogWithEntries(12)); + + $data = $this->getResponseData($this->logController->get('Entry 1')); + + $this->assertSame(['12', '11', '10', '1'], array_column($data['data'], 'reqId')); + } + + public function testGetSendsEachEntrySeparately(): void { + $this->mockLogWithEntries($this->getLogWithEntries(3)); + + $response = $this->logController->get(); + + $this->assertInstanceOf(StreamTraversableResponse::class, $response); + // The opening, one part per entry and the closing with "remain" + $this->assertCount(5, $this->getOutputParts($response)); + } + + public function testGetEscapesHtmlLikeJsonResponse(): void { + $this->mockLogWithEntries('{"reqId":"1","level":3,"time":"2019-11-04T18:50:57+00:00","app":"files","message":""}'); + + $response = $this->logController->get(); + + $this->assertInstanceOf(StreamTraversableResponse::class, $response); + $json = implode('', $this->getOutputParts($response)); + $this->assertStringNotContainsString(''))->render(), '"'), $json); + } + + public function testGetKeepsPagesConsecutiveWithAnEntryThatCannotBeEncoded(): void { + // 1e999 is too large for a float and decodes to INF, which JSON cannot represent + $this->mockLogWithEntries(implode("\n", [ + '{"reqId":"1","level":3,"time":"2019-11-04T18:50:57+00:00","app":"files","message":"Entry 1"}', + '{"reqId":"2","level":3,"time":"2019-11-04T18:50:57+00:00","app":"files","message":"Entry 2"}', + '{"reqId":"3","level":3,"time":"2019-11-04T18:50:57+00:00","app":"files","message":1e999}', + '{"reqId":"4","level":3,"time":"2019-11-04T18:50:57+00:00","app":"files","message":"Entry 4"}', + ])); + + // Like the frontend, request the next page at the number of entries received so far + $firstPage = $this->getResponseData($this->logController->get('', 2, 0)); + $secondPage = $this->getResponseData($this->logController->get('', 2, count($firstPage['data']))); + + $this->assertSame(['4', '3', '2', '1'], array_column([...$firstPage['data'], ...$secondPage['data']], 'reqId')); + $this->assertSame(0, $firstPage['data'][1]['message']); + $this->assertFalse($secondPage['remain']); + } + public function testPollIncludesTheNewestLogEntry(): void { $log = '{"reqId":"1","level":3,"time":"2019-11-04T18:50:57+00:00","app":"comments"}' . "\n" . '{"reqId":"2","level":3,"time":"2019-11-04T18:50:58+00:00","app":"gallery"}' . "\n" @@ -77,7 +189,7 @@ public function testPollIncludesTheNewestLogEntry(): void { $this->mockLogWithEntries($log); $response = $this->logController->poll('1'); - $data = $response->getData(); + $data = $this->getResponseData($response); $this->assertCount(2, $data); // sorted newest first, the last written entry (reqId 3) must be included @@ -91,6 +203,129 @@ public function testPollReturnsEmptyWhenThereIsNoNewEntry(): void { $response = $this->logController->poll('1'); - $this->assertEquals([], $response->getData()); + $this->assertEquals([], $this->getResponseData($response)); + } + + public function testPollSendsEachNewEntrySeparately(): void { + $this->mockLogWithEntries($this->getLogWithEntries(4)); + + $response = $this->logController->poll('2'); + + $this->assertInstanceOf(StreamTraversableResponse::class, $response); + $parts = $this->getOutputParts($response); + // The opening bracket, one part per new entry and the closing bracket + $this->assertCount(4, $parts); + $this->assertSame(['4', '3'], array_column(json_decode(implode('', $parts), true), 'reqId')); + } + + public function testPollHandlesEntriesWithoutReqIdWithoutWarnings(): void { + $this->mockLogWithEntries(implode("\n", [ + '{"reqId":"1","level":3,"time":"2019-11-04T18:50:57+00:00","app":"files","message":"Entry 1"}', + '{"level":3,"time":"2019-11-04T18:50:58+00:00","app":"files","message":"No request id"}', + '{"level":3,"time":"2019-11-04T18:50:59+00:00","app":"files","message":"No request id either"}', + ])); + + set_error_handler(static function (int $level, string $message): never { + throw new \ErrorException($message, 0, $level); + }); + try { + $data = $this->getResponseData($this->logController->poll('1')); + } finally { + restore_error_handler(); + } + + $this->assertSame(['No request id either', 'No request id'], array_column($data, 'message')); + } + + public function testPollReadsAtMostOneHundredThousandEntries(): void { + $this->mockLogWithEntries($this->getLogWithEntries(100001)); + + $data = $this->getResponseData($this->logController->poll('unknown')); + + $this->assertCount(100000, $data); + $this->assertSame('100001', $data[0]['reqId']); + $this->assertSame('2', $data[99999]['reqId']); + } + + public static function pollProvider(): array { + return [ + 'new entries' => ['lastReqId' => '1', 'expectedReqIds' => ['3', '2']], + 'no new entry' => ['lastReqId' => '3', 'expectedReqIds' => []], + ]; + } + + #[DataProvider(methodName: 'pollProvider')] + public function testPollOpensTheLogOnce(string $lastReqId, array $expectedReqIds): void { + $log = $this->getLogWithEntries(3); + $opened = 0; + $this->logIteratorFactory->method('getLogIterator') + ->willReturnCallback(function () use ($log, &$opened) { + $opened++; + // Like the factory's filter, this needs a rewind before the first entry can be read + return new \CallbackFilterIterator($this->getLogIterator($log), fn () => true); + }); + + $data = $this->getResponseData($this->logController->poll($lastReqId)); + + $this->assertSame($expectedReqIds, array_column($data, 'reqId')); + $this->assertSame(1, $opened); + } + + public function testSearchReadsThroughTheLogOnce(): void { + $iterator = new class($this->getLogIterator($this->getLogWithEntries(20))) extends \IteratorIterator { + public int $steps = 0; + + #[\Override] + public function next(): void { + $this->steps++; + parent::next(); + } + }; + $this->logIteratorFactory->method('getLogIterator') + ->willReturn($iterator); + + $data = $this->getResponseData($this->logController->get('no entry contains this')); + + $this->assertSame(['data' => [], 'remain' => false], $data); + $this->assertSame(20, $iterator->steps); + } + + public function testGetStopsSkippingToTheOffsetAtTheEndOfTheLog(): void { + $iterator = new class($this->getLogIterator($this->getLogWithEntries(20))) extends \IteratorIterator { + public int $steps = 0; + + #[\Override] + public function next(): void { + $this->steps++; + parent::next(); + } + }; + $this->logIteratorFactory->method('getLogIterator') + ->willReturn($iterator); + + $data = $this->getResponseData($this->logController->get('', 50, 1000)); + + $this->assertSame(['data' => [], 'remain' => false], $data); + $this->assertSame(20, $iterator->steps); + } + + public function testSearchReadsThroughTheLogOnceWhenNoEntryHasAShownLevel(): void { + $iterator = new class($this->getLogIterator($this->getLogWithEntries(20))) extends \IteratorIterator { + public int $steps = 0; + + #[\Override] + public function next(): void { + $this->steps++; + parent::next(); + } + }; + // Like the factory's level filter, here with none of the entries' levels shown + $this->logIteratorFactory->method('getLogIterator') + ->willReturn(new \CallbackFilterIterator($iterator, fn () => false)); + + $data = $this->getResponseData($this->logController->get('Entry')); + + $this->assertSame(['data' => [], 'remain' => false], $data); + $this->assertSame(20, $iterator->steps); } } diff --git a/tests/Unit/Log/LogIteratorFactoryTest.php b/tests/Unit/Log/LogIteratorFactoryTest.php new file mode 100644 index 000000000..06a1f5fa3 --- /dev/null +++ b/tests/Unit/Log/LogIteratorFactoryTest.php @@ -0,0 +1,79 @@ +logFile = tempnam(sys_get_temp_dir(), 'logreader'); + + $config = $this->createStub(IConfig::class); + $config->method('getSystemValue') + ->willReturnCallback(fn (string $key, mixed $default) => $default); + + $log = $this->createStubForIntersectionOfInterfaces([IWriter::class, IFileBased::class]); + $log->method('getLogFilePath') + ->willReturn($this->logFile); + + $logFactory = $this->createStub(ILogFactory::class); + $logFactory->method('get') + ->willReturn($log); + + $this->logIteratorFactory = new LogIteratorFactory($config, $logFactory); + } + + protected function tearDown(): void { + unlink($this->logFile); + parent::tearDown(); + } + + public static function levelsProvider(): array { + return [ + 'all levels, the default' => ['levels' => [0, 1, 2, 3, 4], 'expectedReqIds' => ['8', '7', '1']], + 'warning and above' => ['levels' => [2, 3, 4], 'expectedReqIds' => ['8', '1']], + ]; + } + + #[DataProvider(methodName: 'levelsProvider')] + public function testReturnsOnlyLogEntriesOfTheRequestedLevels(array $levels, array $expectedReqIds): void { + file_put_contents($this->logFile, implode("\n", [ + '{"reqId":"1","level":3,"time":"2019-11-04T18:50:57+00:00","app":"files","message":"Error"}', + '"text"', + '123', + '[1,2]', + 'not json', + '{"reqId":"6","time":"2019-11-04T18:50:57+00:00","app":"files","message":"No level"}', + '{"reqId":"7","level":1,"time":"2019-11-04T18:50:57+00:00","app":"files","message":"Info"}', + '{"reqId":"8","level":2,"time":"2019-11-04T18:50:57+00:00","app":"files","message":"Warning"}', + ])); + + set_error_handler(static function (int $level, string $message): never { + throw new \ErrorException($message, 0, $level); + }); + try { + $entries = iterator_to_array($this->logIteratorFactory->getLogIterator($levels), false); + } finally { + restore_error_handler(); + } + + $this->assertSame($expectedReqIds, array_column($entries, 'reqId')); + } +}