Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

preserve keys in LogResource so that context is intact #348

Merged
merged 2 commits into from
Mar 15, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions src/Http/Resources/LogResource.php
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,8 @@
*/
class LogResource extends JsonResource
{
public bool $preserveKeys = true;

public function toArray($request): array
{
$level = $this->getLevel();
Expand Down
183 changes: 183 additions & 0 deletions tests/Unit/LaravelLogs/LaravelLogsTest.php
Original file line number Diff line number Diff line change
@@ -1,8 +1,191 @@
<?php

use Opcodes\LogViewer\LogLevels\LaravelLogLevel;
use Opcodes\LogViewer\Logs\LaravelLog;
use Opcodes\LogViewer\Utils\Utils;

use function PHPUnit\Framework\assertEquals;

it('can understand the default Laravel log format', function () {
$text = '[2022-08-25 11:16:17] local.DEBUG: Example log entry for the level debug';

$log = new LaravelLog($text, $fileIdentifier = 'laravel.log', $filePosition = 5200, $index = 10);

assertEquals($index, $log->index);
assertEquals(LaravelLogLevel::Debug, $log->level);
assertEquals('local', $log->extra['environment']);
assertEquals('2022-08-25 11:16:17', $log->datetime->toDateTimeString());
assertEquals('Example log entry for the level debug', $log->message);
assertEquals('Example log entry for the level debug', $log->getOriginalText());
assertEquals($fileIdentifier, $log->fileIdentifier);
assertEquals($filePosition, $log->filePosition);
});

it('can understand multi-line logs', function () {
$logText = <<<'EOF'
Example log entry for the level debug
with multiple lines of content.
can contain dumped objects or JSON as well - it's all part of the contents.
EOF;
$text = '[2022-08-25 11:16:17] local.DEBUG: '.$logText;

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals('Example log entry for the level debug', $log->message);
assertEquals($logText, $log->getOriginalText());
});

it('extracts JSON from the log text', function () {
config(['log-viewer.strip_extracted_context' => true]);
$logText = <<<'EOF'
Example log entry for the level debug
with multiple lines of content.
{"one":1,"two":"two","three":[1,2,3]}
can contain dumped objects or JSON as well - it's all part of the contents.
EOF;
$jsonString = '{"one":1,"two":"two","three":[1,2,3]}';
$text = '[2022-08-25 11:16:17] local.DEBUG: '.$logText;

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals('Example log entry for the level debug', $log->message);
assertEquals(rtrim(str_replace($jsonString, '', $logText)), $log->getOriginalText());
assertEquals(json_decode($jsonString, true), $log->context);
});

it('extracts JSON, but does not remove from the log text if the config is set to false', function () {
config(['log-viewer.strip_extracted_context' => false]);
$logText = <<<'EOF'
Example log entry for the level debug
with multiple lines of content.
{"one":1,"two":"two","three":[1,2,3]}
can contain dumped objects or JSON as well - it's all part of the contents.
EOF;
$text = '[2022-08-25 11:16:17] local.DEBUG: '.$logText;

$log = new LaravelLog($text, 'laravel.log');

assertEquals('Example log entry for the level debug', $log->message);
assertEquals($logText, $log->getOriginalText());
assertEquals(json_decode('{"one":1,"two":"two","three":[1,2,3]}', true), $log->context);
});

it('extracts JSON from a complex log', function () {
config(['log-viewer.strip_extracted_context' => true]);
$logText = <<<'EOF'
Initiating facebook login.
[HTTP request]
*User ID:* guest
*Request:* GET https://system.test/book/arunas/submit-facebook
*Agent:* Mozilla/5.0 (iPhone; CPU iPhone OS 15_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/19G82 [FBAN/FBIOS;FBDV/iPhone9,3;FBMD/iPhone;FBSN/iOS;FBSV/15.6.1;FBSS/2;FBID/phone;FBLC/da_DK;FBOP/5]
{"permalink":"arunas","session":{"_token":"BpqyiNyinnLamzer4jqzrh9NTyC6emFR41FitMpv","_previous":{"url":"https://system.test/book/arunas/center"},"_flash":{"old":[],"new":[]},"latest_permalink":"arunas"},"ip":"127.0.0.1","user_agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 15_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/19G82 [FBAN/FBIOS;FBDV/iPhone9,3;FBMD/iPhone;FBSN/iOS;FBSV/15.6.1;FBSS/2;FBID/phone;FBLC/da_DK;FBOP/5]"}
EOF;

$jsonString = '{"permalink":"arunas","session":{"_token":"BpqyiNyinnLamzer4jqzrh9NTyC6emFR41FitMpv","_previous":{"url":"https://system.test/book/arunas/center"},"_flash":{"old":[],"new":[]},"latest_permalink":"arunas"},"ip":"127.0.0.1","user_agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 15_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/19G82 [FBAN/FBIOS;FBDV/iPhone9,3;FBMD/iPhone;FBSN/iOS;FBSV/15.6.1;FBSS/2;FBID/phone;FBLC/da_DK;FBOP/5]"}';
$text = '[2022-08-25 11:16:17] local.DEBUG: '.$logText;

$log = new LaravelLog($text, 'laravel.log');

assertEquals('arunas', $log->context['permalink'] ?? null);
assertEquals('Initiating facebook login.', $log->message);
assertEquals(rtrim(str_replace($jsonString, '', $logText)), $log->getOriginalText());
assertEquals(json_decode($jsonString, true), $log->context);
});

it('can understand the optional microseconds in the timestamp', function () {
$text = '[2022-08-25 11:16:17.125000] local.DEBUG: Example log entry for the level debug';

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals(125000, $log->datetime->micro);
});

it('can understand the optional time offset in the timestamp', function () {
$text = '[2022-08-25 11:16:17.125000+02:00] local.DEBUG: Example log entry for the level debug';
$expectedTimestamp = 1661418977;

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals($expectedTimestamp, $log->datetime->timestamp);

// Meanwhile, if we switch the time offset an hour forward,
// we can expect the timestamp to be reduced by 3600 seconds.
$text = '[2022-08-25 11:16:17.125000+03:00] local.DEBUG: Example log entry for the level debug';
$newExpectedTimestamp = $expectedTimestamp - 3600;

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals($newExpectedTimestamp, $log->datetime->timestamp);
});

it('can handle text in-between timestamp and environment/severity', function () {
$text = '[2022-08-25 11:16:17] some additional text [!@#$%^&] and characters // !@#$ local.DEBUG: Example log entry for the level debug';
$expectedAdditionalText = 'some additional text [!@#$%^&] and characters // !@#$';

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals($expectedAdditionalText.' Example log entry for the level debug', $log->message);
assertEquals($expectedAdditionalText.' Example log entry for the level debug', $log->getOriginalText());
// got to make sure the rest of the data is still processed correctly!
assertEquals('local', $log->extra['environment']);
assertEquals(LaravelLogLevel::Debug, $log->level);
});

it('finds the correct log level', function ($levelProvided, $levelExpected) {
$text = "[2022-08-25 11:16:17] local.$levelProvided: Example log entry for the level debug";

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals($levelExpected, $log->level);
})->with([
['INFO', LaravelLogLevel::Info],
['DEBUG', LaravelLogLevel::Debug],
['ERROR', LaravelLogLevel::Error],
['WARNING', LaravelLogLevel::Warning],
['CRITICAL', LaravelLogLevel::Critical],
['ALERT', LaravelLogLevel::Alert],
['EMERGENCY', LaravelLogLevel::Emergency],
['info', LaravelLogLevel::Info],
['iNfO', LaravelLogLevel::Info],
['', LaravelLogLevel::None],
]);

it('handles missing message', function () {
$text = '[2022-11-07 17:51:33] production.ERROR: ';

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals('2022-11-07 17:51:33', $log->datetime?->toDateTimeString());
assertEquals(LaravelLogLevel::Error, $log->level);
assertEquals('production', $log->extra['environment']);
assertEquals('', $log->getOriginalText());
});

it('strips extracted context when there\'s multiple contexts available', function () {
config(['log-viewer.strip_extracted_context' => true]);
$logText = <<<'EOF'
[2023-08-16 14:00:25] testing.INFO: Test message. ["one","two"] {"memory_usage":"78 MB","process_id":1234}
EOF;

$log = new LaravelLog($logText);

assertEquals('Test message.', $log->message);
assertEquals(2, count($log->context));
assertEquals(['one', 'two'], $log->context[0]);
assertEquals(['memory_usage' => '78 MB', 'process_id' => 1234], $log->context[1]);
});

it('correctly handles objects with number keys', function () {
$logText = <<<'EOF'
[2024-03-13 12:57:30] local.DEBUG: This is a log message {"array":{"10":"value1","20":"value2"}}
EOF;

$log = new LaravelLog($logText);

assertEquals('This is a log message', $log->message);
assertEquals(['array' => ['10' => 'value1', '20' => 'value2']], $log->context);
});

it('can extract mail preview from a log', function () {
$messageString = <<<'EOF'
[2023-08-24 15:51:14] local.DEBUG: From: sender@example.com
Expand Down
170 changes: 0 additions & 170 deletions tests/Unit/LogTest.php
Original file line number Diff line number Diff line change
@@ -1,165 +1,9 @@
<?php

use Opcodes\LogViewer\LogLevels\LaravelLogLevel;
use Opcodes\LogViewer\Logs\LaravelLog;

use function PHPUnit\Framework\assertEquals;

it('can understand the default Laravel log format', function () {
$text = '[2022-08-25 11:16:17] local.DEBUG: Example log entry for the level debug';

$log = new LaravelLog($text, $fileIdentifier = 'laravel.log', $filePosition = 5200, $index = 10);

assertEquals($index, $log->index);
assertEquals(LaravelLogLevel::Debug, $log->level);
assertEquals('local', $log->extra['environment']);
assertEquals('2022-08-25 11:16:17', $log->datetime->toDateTimeString());
assertEquals('Example log entry for the level debug', $log->message);
assertEquals('Example log entry for the level debug', $log->getOriginalText());
assertEquals($fileIdentifier, $log->fileIdentifier);
assertEquals($filePosition, $log->filePosition);
});

it('can understand multi-line logs', function () {
$logText = <<<'EOF'
Example log entry for the level debug
with multiple lines of content.
can contain dumped objects or JSON as well - it's all part of the contents.
EOF;
$text = '[2022-08-25 11:16:17] local.DEBUG: '.$logText;

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals('Example log entry for the level debug', $log->message);
assertEquals($logText, $log->getOriginalText());
});

it('extracts JSON from the log text', function () {
config(['log-viewer.strip_extracted_context' => true]);
$logText = <<<'EOF'
Example log entry for the level debug
with multiple lines of content.
{"one":1,"two":"two","three":[1,2,3]}
can contain dumped objects or JSON as well - it's all part of the contents.
EOF;
$jsonString = '{"one":1,"two":"two","three":[1,2,3]}';
$text = '[2022-08-25 11:16:17] local.DEBUG: '.$logText;

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals('Example log entry for the level debug', $log->message);
assertEquals(rtrim(str_replace($jsonString, '', $logText)), $log->getOriginalText());
assertEquals(json_decode($jsonString, true), $log->context);
});

it('extracts JSON, but does not remove from the log text if the config is set to false', function () {
config(['log-viewer.strip_extracted_context' => false]);
$logText = <<<'EOF'
Example log entry for the level debug
with multiple lines of content.
{"one":1,"two":"two","three":[1,2,3]}
can contain dumped objects or JSON as well - it's all part of the contents.
EOF;
$text = '[2022-08-25 11:16:17] local.DEBUG: '.$logText;

$log = new LaravelLog($text, 'laravel.log');

assertEquals('Example log entry for the level debug', $log->message);
assertEquals($logText, $log->getOriginalText());
assertEquals(json_decode('{"one":1,"two":"two","three":[1,2,3]}', true), $log->context);
});

it('extracts JSON from a complex log', function () {
config(['log-viewer.strip_extracted_context' => true]);
$logText = <<<'EOF'
Initiating facebook login.
[HTTP request]
*User ID:* guest
*Request:* GET https://system.test/book/arunas/submit-facebook
*Agent:* Mozilla/5.0 (iPhone; CPU iPhone OS 15_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/19G82 [FBAN/FBIOS;FBDV/iPhone9,3;FBMD/iPhone;FBSN/iOS;FBSV/15.6.1;FBSS/2;FBID/phone;FBLC/da_DK;FBOP/5]
{"permalink":"arunas","session":{"_token":"BpqyiNyinnLamzer4jqzrh9NTyC6emFR41FitMpv","_previous":{"url":"https://system.test/book/arunas/center"},"_flash":{"old":[],"new":[]},"latest_permalink":"arunas"},"ip":"127.0.0.1","user_agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 15_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/19G82 [FBAN/FBIOS;FBDV/iPhone9,3;FBMD/iPhone;FBSN/iOS;FBSV/15.6.1;FBSS/2;FBID/phone;FBLC/da_DK;FBOP/5]"}
EOF;

$jsonString = '{"permalink":"arunas","session":{"_token":"BpqyiNyinnLamzer4jqzrh9NTyC6emFR41FitMpv","_previous":{"url":"https://system.test/book/arunas/center"},"_flash":{"old":[],"new":[]},"latest_permalink":"arunas"},"ip":"127.0.0.1","user_agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 15_6_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/19G82 [FBAN/FBIOS;FBDV/iPhone9,3;FBMD/iPhone;FBSN/iOS;FBSV/15.6.1;FBSS/2;FBID/phone;FBLC/da_DK;FBOP/5]"}';
$text = '[2022-08-25 11:16:17] local.DEBUG: '.$logText;

$log = new LaravelLog($text, 'laravel.log');

assertEquals('arunas', $log->context['permalink'] ?? null);
assertEquals('Initiating facebook login.', $log->message);
assertEquals(rtrim(str_replace($jsonString, '', $logText)), $log->getOriginalText());
assertEquals(json_decode($jsonString, true), $log->context);
});

it('can understand the optional microseconds in the timestamp', function () {
$text = '[2022-08-25 11:16:17.125000] local.DEBUG: Example log entry for the level debug';

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals(125000, $log->datetime->micro);
});

it('can understand the optional time offset in the timestamp', function () {
$text = '[2022-08-25 11:16:17.125000+02:00] local.DEBUG: Example log entry for the level debug';
$expectedTimestamp = 1661418977;

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals($expectedTimestamp, $log->datetime->timestamp);

// Meanwhile, if we switch the time offset an hour forward,
// we can expect the timestamp to be reduced by 3600 seconds.
$text = '[2022-08-25 11:16:17.125000+03:00] local.DEBUG: Example log entry for the level debug';
$newExpectedTimestamp = $expectedTimestamp - 3600;

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals($newExpectedTimestamp, $log->datetime->timestamp);
});

it('can handle text in-between timestamp and environment/severity', function () {
$text = '[2022-08-25 11:16:17] some additional text [!@#$%^&] and characters // !@#$ local.DEBUG: Example log entry for the level debug';
$expectedAdditionalText = 'some additional text [!@#$%^&] and characters // !@#$';

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals($expectedAdditionalText.' Example log entry for the level debug', $log->message);
assertEquals($expectedAdditionalText.' Example log entry for the level debug', $log->getOriginalText());
// got to make sure the rest of the data is still processed correctly!
assertEquals('local', $log->extra['environment']);
assertEquals(LaravelLogLevel::Debug, $log->level);
});

it('finds the correct log level', function ($levelProvided, $levelExpected) {
$text = "[2022-08-25 11:16:17] local.$levelProvided: Example log entry for the level debug";

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals($levelExpected, $log->level);
})->with([
['INFO', LaravelLogLevel::Info],
['DEBUG', LaravelLogLevel::Debug],
['ERROR', LaravelLogLevel::Error],
['WARNING', LaravelLogLevel::Warning],
['CRITICAL', LaravelLogLevel::Critical],
['ALERT', LaravelLogLevel::Alert],
['EMERGENCY', LaravelLogLevel::Emergency],
['info', LaravelLogLevel::Info],
['iNfO', LaravelLogLevel::Info],
['', LaravelLogLevel::None],
]);

it('handles missing message', function () {
$text = '[2022-11-07 17:51:33] production.ERROR: ';

$log = new LaravelLog($text, 'laravel.log', 0, 0);

assertEquals('2022-11-07 17:51:33', $log->datetime?->toDateTimeString());
assertEquals(LaravelLogLevel::Error, $log->level);
assertEquals('production', $log->extra['environment']);
assertEquals('', $log->getOriginalText());
});

it('can set a custom timezone of the log entry', function () {
$text = '[2022-11-07 17:51:33] production.ERROR: test message';
config(['log-viewer.timezone' => $tz = 'Europe/Vilnius']);
Expand All @@ -170,17 +14,3 @@
$expectedTime = \Carbon\Carbon::parse('2022-11-07 17:51:33', 'UTC')->setTimezone($tz)->toDateTimeString();
assertEquals($expectedTime, $log->datetime->toDateTimeString());
});

it('strips extracted context when there\'s multiple contexts available', function () {
config(['log-viewer.strip_extracted_context' => true]);
$logText = <<<'EOF'
[2023-08-16 14:00:25] testing.INFO: Test message. ["one","two"] {"memory_usage":"78 MB","process_id":1234}
EOF;

$log = new LaravelLog($logText);

assertEquals('Test message.', $log->message);
assertEquals(2, count($log->context));
assertEquals(['one', 'two'], $log->context[0]);
assertEquals(['memory_usage' => '78 MB', 'process_id' => 1234], $log->context[1]);
});
Loading