diff --git a/.github/workflows/laravel.yml b/.github/workflows/laravel.yml index 7f32b531..09dca821 100644 --- a/.github/workflows/laravel.yml +++ b/.github/workflows/laravel.yml @@ -102,6 +102,8 @@ jobs: php artisan serve & sleep 2 wget http://localhost:8000 + cat index.html + ps -ax - name: "Check logs for successful payload send" run: | cd test-app diff --git a/.github/workflows/lumen.yml b/.github/workflows/lumen.yml index 63c0b2e2..9576d36e 100644 --- a/.github/workflows/lumen.yml +++ b/.github/workflows/lumen.yml @@ -108,6 +108,8 @@ jobs: LOG_CHANNEL=single php -S localhost:8000 -t public/ & sleep 2 wget http://localhost:8000 + cat index.html + ps -ax - name: "Check logs for successful payload send" run: | cd test-app diff --git a/CHANGELOG.md b/CHANGELOG.md index a7701cc3..9288e59a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,7 +10,10 @@ All notable changes to this project will be documented in this file, in reverse ### Changed -- Nothing. +- [#233](https://github.com/scoutapp/scout-apm-php/pull/233) Adjusted log levels + - Default log level is `debug` again to assist in support enquiries + - Reduced log level of span limit being reached to `info` + - Increased span limit to 3000 ### Deprecated diff --git a/README.md b/README.md index e3765b8f..aa38a667 100644 --- a/README.md +++ b/README.md @@ -54,11 +54,10 @@ $agent->send(); #### Default log level -Since release `6.2.0`, the default log level is set to `Psr\Log\LogLevel::WARNING`. If you are having issues with -instrumentation, we recommend setting the log level to `Psr\Log\LogLevel::DEBUG` to increase the verbosity of logging. -This will help support to identify issues that may occur. - -You may change the log level to any other `Psr\Log\LogLevel::*` constant value, for example: +By default, the library is *very* noisy in logging by design - this is to help us figure out what is going wrong if you +need assistance. If you are confident everything is working, and you can see data in your Scout dashboard, then you +can increase the minimum log level by adding the following configuration to set the "minimum" log level (which **only** +applies to Scout's logging): ```php use Psr\Log\LoggerInterface; @@ -74,7 +73,7 @@ $agent = Agent::fromConfig( ConfigKey::APPLICATION_NAME => 'Your application name', ConfigKey::APPLICATION_KEY => 'your scout key', ConfigKey::MONITORING_ENABLED => true, - ConfigKey::LOG_LEVEL => LogLevel::DEBUG, // <-- add this configuration to increase logging verbosity + ConfigKey::LOG_LEVEL => LogLevel::ERROR, // <-- add this configuration to reduce logging verbosity ]), $psrLoggerImplementation ); diff --git a/known-issues.xml b/known-issues.xml index e3726db4..cfbafced 100644 --- a/known-issues.xml +++ b/known-issues.xml @@ -296,11 +296,11 @@ self::at(6) + $commands[(self::EXPECTED_SPAN_LIMIT * 2) + 1] + $commands[(self::EXPECTED_SPAN_LIMIT * 2) + 2] + $commands[(self::EXPECTED_SPAN_LIMIT * 2) + 3] + $commands[(self::EXPECTED_SPAN_LIMIT * 2) + 4] $commands[0] - $commands[3001] - $commands[3002] - $commands[3003] - $commands[3004] next($commands) next($commands) next($commands) diff --git a/src/Agent.php b/src/Agent.php index 833eed6e..c781110c 100644 --- a/src/Agent.php +++ b/src/Agent.php @@ -270,7 +270,7 @@ private function onlyRunIfBelowSpanLimit(callable $codeToRunIfBelowSpanLimit) $this->request->tag(Tag::TAG_REACHED_SPAN_CAP, true); } - $this->logger->notice($spanLimitReached->getMessage(), ['exception' => $spanLimitReached]); + $this->logger->info($spanLimitReached->getMessage(), ['exception' => $spanLimitReached]); return null; } diff --git a/src/Config.php b/src/Config.php index 2a9ec2ea..0f2735ef 100644 --- a/src/Config.php +++ b/src/Config.php @@ -27,7 +27,7 @@ class Config { /** @internal */ - public const DEFAULT_LOG_LEVEL = LogLevel::WARNING; + public const DEFAULT_LOG_LEVEL = LogLevel::DEBUG; /** @var array */ private $sources; diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index 8e03e9b9..da11e5f1 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -33,7 +33,7 @@ /** @internal */ class Request implements CommandWithChildren { - private const MAX_COMPLETE_SPANS = 1500; + private const MAX_COMPLETE_SPANS = 3000; /** @var Timer */ private $timer; diff --git a/src/Logger/FilteredLogLevelDecorator.php b/src/Logger/FilteredLogLevelDecorator.php index 9a80971a..1af805e0 100644 --- a/src/Logger/FilteredLogLevelDecorator.php +++ b/src/Logger/FilteredLogLevelDecorator.php @@ -52,8 +52,9 @@ public function __construct(LoggerInterface $realLogger, string $minimumLogLevel self::LOG_LEVEL_ORDER, strtolower($minimumLogLevel), sprintf( - 'Log level %s was not a valid PSR-3 compatible log level. Should be one of: %s', + 'Log level %s was not a valid PSR-3 compatible log level, defaulting to %s. Should be one of: %s', $minimumLogLevel, + Config::DEFAULT_LOG_LEVEL, implode(', ', array_keys(self::LOG_LEVEL_ORDER)) ) ); diff --git a/tests/Unit/AgentTest.php b/tests/Unit/AgentTest.php index 1046a4d5..8b97ebb4 100644 --- a/tests/Unit/AgentTest.php +++ b/tests/Unit/AgentTest.php @@ -48,6 +48,8 @@ /** @covers \Scoutapm\Agent */ final class AgentTest extends TestCase { + private const EXPECTED_SPAN_LIMIT = 3000; + /** @var TestLogger */ private $logger; @@ -165,7 +167,7 @@ public function testMinimumLogLevelCanBeSetOnConfigurationToSquelchNoisyLogMessa self::assertFalse($this->logger->hasDebugRecords()); } - public function testNoLogMessagesAreLoggedWhenUsingDefaultConfiguration(): void + public function testLogMessagesAreLoggedWhenUsingDefaultConfiguration(): void { $agent = $this->agentFromConfigArray([ ConfigKey::APPLICATION_NAME => 'My Application', @@ -175,7 +177,8 @@ public function testNoLogMessagesAreLoggedWhenUsingDefaultConfiguration(): void $agent->connect(); - self::assertEquals([], $this->logger->records); + self::assertTrue($this->logger->hasDebugThatContains('Configuration')); + self::assertTrue($this->logger->hasDebugThatContains('Connection skipped, since monitoring is disabled')); } /** @throws Exception */ @@ -911,7 +914,7 @@ static function (): void { } /** @throws Exception */ - public function testNumberOfSpansIsLimitedAndNoticeIsLogged(): void + public function testNumberOfSpansIsLimitedAndLogged(): void { $agent = $this->agentFromConfigArray([ ConfigKey::APPLICATION_NAME => 'My test app', @@ -921,7 +924,7 @@ public function testNumberOfSpansIsLimitedAndNoticeIsLogged(): void ]); // Even if we randomise the number of spans over the limit, the number of spans actually sent should remain fixed - $maxSpansToStart = random_int(1500, 1600); + $maxSpansToStart = random_int(self::EXPECTED_SPAN_LIMIT, self::EXPECTED_SPAN_LIMIT + 100); for ($i = 0; $i <= $maxSpansToStart; $i++) { $agent->startSpan(sprintf('span %d', $i)); @@ -949,15 +952,15 @@ public function testNumberOfSpansIsLimitedAndNoticeIsLogged(): void [ 'commands' => static function (array $commands): bool { // StartRequest - // 1500 * 2 for Start/StopSpans + // span limit * 2 for Start/StopSpans // TagRequest for limit // Tag for memory, - self::assertCount(3005, $commands); + self::assertCount((self::EXPECTED_SPAN_LIMIT * 2) + 5, $commands); TestHelper::assertUnserializedCommandContainsPayload('StartRequest', [], $commands[0], null); - TestHelper::assertUnserializedCommandContainsPayload('TagRequest', ['tag' => 'scout.reached_span_cap', 'value' => true], $commands[3001], null); - TestHelper::assertUnserializedCommandContainsPayload('TagRequest', ['tag' => 'memory_delta'], $commands[3002], null); - TestHelper::assertUnserializedCommandContainsPayload('TagRequest', ['tag' => 'path'], $commands[3003], null); - TestHelper::assertUnserializedCommandContainsPayload('FinishRequest', [], $commands[3004], null); + TestHelper::assertUnserializedCommandContainsPayload('TagRequest', ['tag' => 'scout.reached_span_cap', 'value' => true], $commands[(self::EXPECTED_SPAN_LIMIT * 2) + 1], null); + TestHelper::assertUnserializedCommandContainsPayload('TagRequest', ['tag' => 'memory_delta'], $commands[(self::EXPECTED_SPAN_LIMIT * 2) + 2], null); + TestHelper::assertUnserializedCommandContainsPayload('TagRequest', ['tag' => 'path'], $commands[(self::EXPECTED_SPAN_LIMIT * 2) + 3], null); + TestHelper::assertUnserializedCommandContainsPayload('FinishRequest', [], $commands[(self::EXPECTED_SPAN_LIMIT * 2) + 4], null); return true; }, @@ -972,7 +975,7 @@ public function testNumberOfSpansIsLimitedAndNoticeIsLogged(): void self::assertTrue($agent->send()); - self::assertTrue($this->logger->hasNoticeThatContains('Span limit of 1500 has been reached trying to start span for "span 1500"')); + self::assertTrue($this->logger->hasInfoThatContains(sprintf('Span limit of %d has been reached trying to start span for "span %d"', self::EXPECTED_SPAN_LIMIT, self::EXPECTED_SPAN_LIMIT))); } public function testMetadataIsNotSentIfCached(): void diff --git a/tests/Unit/Events/Request/RequestTest.php b/tests/Unit/Events/Request/RequestTest.php index 29696680..5cad2c4c 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -26,6 +26,8 @@ /** @covers \Scoutapm\Events\Request\Request */ final class RequestTest extends TestCase { + private const EXPECTED_SPAN_LIMIT = 3000; + private const FIXED_POINT_UNIX_EPOCH_SECONDS = 1000000000.0; /** @psalm-param array $configOverrides */ @@ -41,7 +43,7 @@ public function testExceptionThrownWhenSpanLimitReached(): void { $request = $this->requestFromConfiguration(); - for ($i = 0; $i < 1500; $i++) { + for ($i = 0; $i < self::EXPECTED_SPAN_LIMIT; $i++) { $request->startSpan(uniqid('test', true)); } diff --git a/tests/Unit/Logger/FilteredLogLevelDecoratorTest.php b/tests/Unit/Logger/FilteredLogLevelDecoratorTest.php index a622245c..13a795b0 100644 --- a/tests/Unit/Logger/FilteredLogLevelDecoratorTest.php +++ b/tests/Unit/Logger/FilteredLogLevelDecoratorTest.php @@ -35,7 +35,7 @@ public function testInvalidLogLevelStringGivesClearErrorMessage(): void ->method('log') ->with( LogLevel::ERROR, - 'Log level foo was not a valid PSR-3 compatible log level. ' + 'Log level foo was not a valid PSR-3 compatible log level, defaulting to debug. ' . 'Should be one of: debug, info, notice, warning, error, critical, alert, emergency', self::anything() ); @@ -118,7 +118,7 @@ public function testInvalidLogLevelsAreLoggedAsErrors(string $invalidLogLevel): } /** @dataProvider invalidLogLevelProvider */ - public function testInvalidLogLevelsDefaultToWarning(string $invalidLogLevel): void + public function testInvalidLogLevelsPassedStillLogThings(string $invalidLogLevel): void { $decorator = new FilteredLogLevelDecorator($this->decoratedLogger, $invalidLogLevel);