Adjust log levels

.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

.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

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
 

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

known-issues.xml

@@ -296,11 +296,11 @@
       <code>self::at(6)</code>
     </DeprecatedMethod>
     <MixedArgument occurrences="19">
+      <code>$commands[(self::EXPECTED_SPAN_LIMIT * 2) + 1]</code>
+      <code>$commands[(self::EXPECTED_SPAN_LIMIT * 2) + 2]</code>
+      <code>$commands[(self::EXPECTED_SPAN_LIMIT * 2) + 3]</code>
+      <code>$commands[(self::EXPECTED_SPAN_LIMIT * 2) + 4]</code>
       <code>$commands[0]</code>
-      <code>$commands[3001]</code>
-      <code>$commands[3002]</code>
-      <code>$commands[3003]</code>
-      <code>$commands[3004]</code>
       <code>next($commands)</code>
       <code>next($commands)</code>
       <code>next($commands)</code>

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

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<int, (EnvSource|UserSettingsSource|DerivedSource|DefaultSource|NullSource)> */
     private $sources;

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;

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

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

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<string, mixed> $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));
         }
 

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