ENH Improve deprecation logging

src/Dev/Deprecation.php

@@ -61,12 +61,22 @@ class Deprecation
      * Must be configured outside of the config API, as deprecation API
      * must be available before this to avoid infinite loops.
      *
-     * This will be overriden by the SS_DEPRECATION_ENABLED environment if present
+     * This will be overriden by the SS_DEPRECATION_ENABLED environment variable if present
      *
      * @internal - Marked as internal so this and other private static's are not treated as config
      */
     private static bool $currentlyEnabled = false;
 
+    /**
+     * @internal
+     */
+    private static bool $shouldShowForHttp = false;
+
+    /**
+     * @internal
+     */
+    private static bool $shouldShowForCli = true;
+
     /**
      * @internal
      */
@@ -77,6 +87,11 @@ class Deprecation
      */
     private static bool $insideWithNoReplacement = false;
 
+    /**
+     * @internal
+     */
+    private static bool $isTriggeringError = false;
+
     /**
      * Buffer of user_errors to be raised
      *
@@ -94,12 +109,26 @@ class Deprecation
      */
     private static bool $showNoReplacementNotices = false;
 
+    /**
+     * Enable throwing deprecation warnings. By default, this excludes warnings for
+     * deprecated code which is called by core Silverstripe modules.
+     *
+     * This will be overriden by the SS_DEPRECATION_ENABLED environment variable if present.
+     *
+     * @param bool $showNoReplacementNotices If true, deprecation warnings will also be thrown
+     * for deprecated code which is called by core Silverstripe modules.
+     */
     public static function enable(bool $showNoReplacementNotices = false): void
     {
         static::$currentlyEnabled = true;
         static::$showNoReplacementNotices = $showNoReplacementNotices;
     }
 
+    /**
+     * Disable throwing deprecation warnings.
+     *
+     * This will be overriden by the SS_DEPRECATION_ENABLED environment variable if present.
+     */
     public static function disable(): void
     {
         static::$currentlyEnabled = false;
@@ -208,7 +237,11 @@ class Deprecation
         if (!Director::isDev()) {
             return false;
         }
-        return static::$currentlyEnabled || Environment::getEnv('SS_DEPRECATION_ENABLED');
+        $envVar = Environment::getEnv('SS_DEPRECATION_ENABLED');
+        if (Environment::hasEnv('SS_DEPRECATION_ENABLED')) {
+            return self::varAsBoolean($envVar);
+        }
+        return static::$currentlyEnabled;
     }
 
     /**
@@ -223,29 +256,86 @@ class Deprecation
         // noop
     }
 
+    /**
+     * If true, any E_USER_DEPRECATED errors should be treated as coming
+     * directly from this class.
+     */
+    public static function isTriggeringError(): bool
+    {
+        return self::$isTriggeringError;
+    }
+
+    /**
+     * Determine whether deprecation warnings should be included in HTTP responses.
+     * Does not affect logging.
+     *
+     * This will be overriden by the SS_DEPRECATION_SHOW_HTTP environment variable if present.
+     */
+    public static function setShouldShowForHttp(bool $value): void
+    {
+        self::$shouldShowForHttp = $value;
+    }
+
+    /**
+     * Determine whether deprecation warnings should be included in CLI responses.
+     * Does not affect logging.
+     *
+     * This will be overriden by the SS_DEPRECATION_SHOW_CLI environment variable if present.
+     */
+    public static function setShouldShowForCli(bool $value): void
+    {
+        self::$shouldShowForCli = $value;
+    }
+
+    /**
+     * If true, deprecation warnings should be included in HTTP responses.
+     * Does not affect logging.
+     */
+    public static function shouldShowForHttp(): bool
+    {
+        $envVar = Environment::getEnv('SS_DEPRECATION_SHOW_HTTP');
+        if (Environment::hasEnv('SS_DEPRECATION_SHOW_HTTP')) {
+            return self::varAsBoolean($envVar);
+        }
+        return self::$shouldShowForHttp;
+    }
+
+    /**
+     * If true, deprecation warnings should be included in CLI responses.
+     * Does not affect logging.
+     */
+    public static function shouldShowForCli(): bool
+    {
+        $envVar = Environment::getEnv('SS_DEPRECATION_SHOW_CLI');
+        if (Environment::hasEnv('SS_DEPRECATION_SHOW_CLI')) {
+            return self::varAsBoolean($envVar);
+        }
+        return self::$shouldShowForCli;
+    }
+
     public static function outputNotices(): void
     {
         if (!self::isEnabled()) {
             return;
         }
-        $outputMessages = [];
+
-        // using a while loop with array_shift() to ensure that self::$userErrorMessageBuffer will have
+        $count = 0;
-        // have values removed from it before calling user_error()
+        $origCount = count(self::$userErrorMessageBuffer);
-        while (count(self::$userErrorMessageBuffer)) {
+        while ($origCount > $count) {
+            $count++;
             $arr = array_shift(self::$userErrorMessageBuffer);
             $message = $arr['message'];
-            // often the same deprecation message appears dozens of times, which isn't helpful
-            // only need to show a single instance of each message
-            if (in_array($message, $outputMessages)) {
-                continue;
-            }
             $calledInsideWithNoReplacement = $arr['calledInsideWithNoReplacement'];
             if ($calledInsideWithNoReplacement && !self::$showNoReplacementNotices) {
                 continue;
             }
+            self::$isTriggeringError = true;
             user_error($message, E_USER_DEPRECATED);
-            $outputMessages[] = $message;
+            self::$isTriggeringError = false;
         }
+        // Make absolutely sure the buffer is empty - array_shift seems to leave an item in the array
+        // if we're not using numeric keys.
+        self::$userErrorMessageBuffer = [];
     }
 
     /**
@@ -265,10 +355,12 @@ class Deprecation
         // try block needs to wrap all code in case anything inside the try block
         // calls something else that calls Deprecation::notice()
         try {
+            $data = null;
             if ($scope === self::SCOPE_CONFIG) {
                 // Deprecated config set via yaml will only be shown in the browser when using ?flush=1
                 // It will not show in CLI when running dev/build flush=1
-                self::$userErrorMessageBuffer[] = [
+                $data = [
+                    'key' => sha1($string),
                     'message' => $string,
                     'calledInsideWithNoReplacement' => self::$insideWithNoReplacement
                 ];
@@ -302,20 +394,26 @@ class Deprecation
                 if ($caller) {
                     $string = $caller . ' is deprecated.' . ($string ? ' ' . $string : '');
                 }
-                self::$userErrorMessageBuffer[] = [
+                $data = [
+                    'key' => sha1($string),
                     'message' => $string,
                     'calledInsideWithNoReplacement' => self::$insideWithNoReplacement
                 ];
             }
-            if (!self::$haveSetShutdownFunction && self::isEnabled()) {
+            if ($data && !array_key_exists($data['key'], self::$userErrorMessageBuffer)) {
+                // Store de-duplicated data in a buffer to be outputted when outputNotices() is called
+                self::$userErrorMessageBuffer[$data['key']] = $data;
+
                 // Use a shutdown function rather than immediately calling user_error() so that notices
                 // do not interfere with setting session varibles i.e. headers already sent error
                 // it also means the deprecation notices appear below all phpunit output in CI
                 // which is far nicer than having it spliced between phpunit output
-                register_shutdown_function(function () {
+                if (!self::$haveSetShutdownFunction && self::isEnabled()) {
-                    self::outputNotices();
+                    register_shutdown_function(function () {
-                });
+                        self::outputNotices();
-                self::$haveSetShutdownFunction = true;
+                    });
+                    self::$haveSetShutdownFunction = true;
+                }
             }
         } catch (BadMethodCallException $e) {
             if ($e->getMessage() === InjectorLoader::NO_MANIFESTS_AVAILABLE) {
@@ -353,4 +451,31 @@ class Deprecation
         static::notice('4.12.0', 'Will be removed without equivalent functionality to replace it');
         // noop
     }
+
+    private static function varAsBoolean($val): bool
+    {
+        if (is_string($val)) {
+            $truthyStrings = [
+                'on',
+                'true',
+                '1',
+            ];
+
+            if (in_array(strtolower($val), $truthyStrings, true)) {
+                return true;
+            }
+
+            $falsyStrings = [
+                'off',
+                'false',
+                '0',
+            ];
+
+            if (in_array(strtolower($val), $falsyStrings, true)) {
+                return false;
+            }
+        }
+
+        return (bool) $val;
+    }
 }

src/Logging/HTTPOutputHandler.php

@@ -7,6 +7,7 @@ use Monolog\Handler\AbstractProcessingHandler;
 use SilverStripe\Control\Controller;
 use SilverStripe\Control\Director;
 use SilverStripe\Control\HTTPResponse;
+use SilverStripe\Dev\Deprecation;
 
 /**
  * Output the error to the browser, with the given HTTP status code.
@@ -137,6 +138,16 @@ class HTTPOutputHandler extends AbstractProcessingHandler
         return $this;
     }
 
+    protected function shouldShowError(int $errorCode): bool
+    {
+        // show all non-E_USER_DEPRECATED errors
+        // or E_USER_DEPRECATED errors when not triggering from the Deprecation class
+        // or our deprecations when the relevant shouldShow method returns true
+        return $errorCode !== E_USER_DEPRECATED
+            || !Deprecation::isTriggeringError()
+            || ($this->isCli() ? Deprecation::shouldShowForCli() : Deprecation::shouldShowForHttp());
+    }
+
     /**
      * @param array $record
      * @return bool
@@ -145,6 +156,14 @@ class HTTPOutputHandler extends AbstractProcessingHandler
     {
         ini_set('display_errors', 0);
 
+        // Suppress errors that should be suppressed
+        if (isset($record['context']['code'])) {
+            $errorCode = $record['context']['code'];
+            if (!$this->shouldShowError($errorCode)) {
+                return;
+            }
+        }
+
         // TODO: This coupling isn't ideal
         // See https://github.com/silverstripe/silverstripe-framework/issues/4484
         if (Controller::has_curr()) {
@@ -167,4 +186,12 @@ class HTTPOutputHandler extends AbstractProcessingHandler
 
         return false === $this->getBubble();
     }
+
+    /**
+     * This method is required and must be protected for unit testing, since we can't mock static or private methods
+     */
+    protected function isCli(): bool
+    {
+        return Director::is_cli();
+    }
 }

src/Logging/MonologErrorHandler.php

@@ -5,6 +5,7 @@ namespace SilverStripe\Logging;
 use InvalidArgumentException;
 use Psr\Log\LoggerInterface;
 use Monolog\ErrorHandler as MonologHandler;
+use Psr\Log\LogLevel;
 use SilverStripe\Dev\Deprecation;
 
 class MonologErrorHandler implements ErrorHandler
@@ -92,7 +93,13 @@ class MonologErrorHandler implements ErrorHandler
         }
 
         foreach ($loggers as $logger) {
-            MonologHandler::register($logger);
+            // Log deprecation warnings as WARNING, not NOTICE
+            // see https://github.com/Seldaek/monolog/blob/1.x/doc/01-usage.md#log-levels
+            $errorLevelMap = [
+                E_DEPRECATED => LogLevel::WARNING,
+                E_USER_DEPRECATED => LogLevel::WARNING,
+            ];
+            MonologHandler::register($logger, $errorLevelMap);
         }
     }
 }

tests/php/Core/EnvironmentTest.php

@@ -124,13 +124,7 @@ class EnvironmentTest extends SapphireTest
                 $_SERVER[$name] = $value;
                 break;
             case 'putenv':
-                if ($value === null) {
+                $val = is_string($value) ? $value : json_encode($value);
-                    $val = 'null';
-                } elseif (is_bool($value)) {
-                    $val = $value ? 'true' : 'false';
-                } else {
-                    $val = (string)$value;
-                }
                 putenv("$name=$val");
                 break;
             default:

tests/php/Dev/DeprecationTest.php

@@ -3,7 +3,9 @@
 namespace SilverStripe\Dev\Tests;
 
 use PHPUnit\Framework\Error\Deprecated;
+use ReflectionMethod;
 use SilverStripe\Core\Config\Config;
+use SilverStripe\Core\Environment;
 use SilverStripe\Dev\Deprecation;
 use SilverStripe\Dev\SapphireTest;
 use SilverStripe\Dev\Tests\DeprecationTest\DeprecationTestObject;
@@ -22,7 +24,7 @@ class DeprecationTest extends SapphireTest
     protected function setup(): void
     {
         // Use custom error handler for two reasons:
-        // - Filter out errors for deprecated class properities unrelated to this unit test
+        // - Filter out errors for deprecated class properties unrelated to this unit test
         // - Allow the use of expectDeprecation(), which doesn't work with E_USER_DEPRECATION by default
         //   https://github.com/laminas/laminas-di/pull/30#issuecomment-927585210
         parent::setup();
@@ -32,7 +34,7 @@ class DeprecationTest extends SapphireTest
                 if (str_contains($errstr, 'SilverStripe\\Dev\\Tests\\DeprecationTest')) {
                     throw new Deprecated($errstr, $errno, '', 1);
                 } else {
-                    // Surpress any E_USER_DEPRECATED unrelated to this unit-test
+                    // Suppress any E_USER_DEPRECATED unrelated to this unit-test
                     return true;
                 }
             }
@@ -46,7 +48,9 @@ class DeprecationTest extends SapphireTest
 
     protected function tearDown(): void
     {
-        if (!$this->noticesWereEnabled) {
+        if ($this->noticesWereEnabled) {
+            Deprecation::enable();
+        } else {
             Deprecation::disable();
         }
         restore_error_handler();
@@ -278,4 +282,167 @@ class DeprecationTest extends SapphireTest
         Config::modify()->merge(DeprecationTestObject::class, 'array_config', ['abc']);
         Deprecation::outputNotices();
     }
+
+    public function provideConfigVsEnv()
+    {
+        return [
+            // env var not set - config setting is respected
+            [
+                // false is returned when the env isn't set, so this simulates simply not having
+                // set the variable in the first place
+                'envVal' => 'notset',
+                'configVal' => false,
+                'expected' => false,
+            ],
+            [
+                'envVal' => 'notset',
+                'configVal' => true,
+                'expected' => true,
+            ],
+            // env var is set and truthy, config setting is ignored
+            [
+                'envVal' => true,
+                'configVal' => false,
+                'expected' => true,
+            ],
+            [
+                'envVal' => true,
+                'configVal' => true,
+                'expected' => true,
+            ],
+            // env var is set and falsy, config setting is ignored
+            [
+                'envVal' => false,
+                'configVal' => false,
+                'expected' => false,
+            ],
+            [
+                'envVal' => false,
+                'configVal' => true,
+                'expected' => false,
+            ],
+        ];
+    }
+
+    /**
+     * @dataProvider provideConfigVsEnv
+     */
+    public function testEnabledConfigVsEnv($envVal, bool $configVal, bool $expected)
+    {
+        $this->runConfigVsEnvTest('SS_DEPRECATION_ENABLED', $envVal, $configVal, $expected);
+    }
+
+    /**
+     * @dataProvider provideConfigVsEnv
+     */
+    public function testShowHttpConfigVsEnv($envVal, bool $configVal, bool $expected)
+    {
+        $this->runConfigVsEnvTest('SS_DEPRECATION_SHOW_HTTP', $envVal, $configVal, $expected);
+    }
+
+    /**
+     * @dataProvider provideConfigVsEnv
+     */
+    public function testShowCliConfigVsEnv($envVal, bool $configVal, bool $expected)
+    {
+        $this->runConfigVsEnvTest('SS_DEPRECATION_SHOW_CLI', $envVal, $configVal, $expected);
+    }
+
+    private function runConfigVsEnvTest(string $varName, $envVal, bool $configVal, bool $expected)
+    {
+        $oldVars = Environment::getVariables();
+
+        if ($envVal === 'notset') {
+            if (Environment::hasEnv($varName)) {
+                $this->markTestSkipped("$varName is set, so we can't test behaviour when it's not");
+                return;
+            }
+        } else {
+            Environment::setEnv($varName, $envVal);
+        }
+
+        switch ($varName) {
+            case 'SS_DEPRECATION_ENABLED':
+                if ($configVal) {
+                    Deprecation::enable();
+                } else {
+                    Deprecation::disable();
+                }
+                $result = Deprecation::isEnabled();
+                break;
+            case 'SS_DEPRECATION_SHOW_HTTP':
+                $oldShouldShow = Deprecation::shouldShowForHttp();
+                Deprecation::setShouldShowForHttp($configVal);
+                $result = Deprecation::shouldShowForHttp();
+                Deprecation::setShouldShowForHttp($oldShouldShow);
+                break;
+            case 'SS_DEPRECATION_SHOW_CLI':
+                $oldShouldShow = Deprecation::shouldShowForCli();
+                Deprecation::setShouldShowForCli($configVal);
+                $result = Deprecation::shouldShowForCli();
+                Deprecation::setShouldShowForCli($oldShouldShow);
+                break;
+        }
+
+        Environment::setVariables($oldVars);
+
+        $this->assertSame($expected, $result);
+    }
+
+    public function provideVarAsBoolean()
+    {
+        return [
+            [
+                'rawValue' => true,
+                'expected' => true,
+            ],
+            [
+                'rawValue' => 'true',
+                'expected' => true,
+            ],
+            [
+                'rawValue' => 1,
+                'expected' => true,
+            ],
+            [
+                'rawValue' => '1',
+                'expected' => true,
+            ],
+            [
+                'rawValue' => 'on',
+                'expected' => true,
+            ],
+            [
+                'rawValue' => false,
+                'expected' => false,
+            ],
+            [
+                'rawValue' => 'false',
+                'expected' => false,
+            ],
+            [
+                'rawValue' => 0,
+                'expected' => false,
+            ],
+            [
+                'rawValue' => '0',
+                'expected' => false,
+            ],
+            [
+                'rawValue' => 'off',
+                'expected' => false,
+            ],
+        ];
+    }
+
+    /**
+     * @dataProvider provideVarAsBoolean
+     */
+    public function testVarAsBoolean($rawValue, bool $expected)
+    {
+        $reflectionVarAsBoolean = new ReflectionMethod(Deprecation::class, 'varAsBoolean');
+        $reflectionVarAsBoolean->setAccessible(true);
+
+        $this->assertSame($expected, $reflectionVarAsBoolean->invoke(null, $rawValue));
+    }
 }

tests/php/Logging/HTTPOutputHandlerTest.php

@@ -3,8 +3,11 @@
 namespace SilverStripe\Logging\Tests;
 
 use Monolog\Handler\HandlerInterface;
+use ReflectionMethod;
+use ReflectionProperty;
 use SilverStripe\Control\Director;
 use SilverStripe\Core\Injector\Injector;
+use SilverStripe\Dev\Deprecation;
 use SilverStripe\Dev\SapphireTest;
 use SilverStripe\Logging\DebugViewFriendlyErrorFormatter;
 use SilverStripe\Logging\DetailedErrorFormatter;
@@ -53,4 +56,131 @@ class HTTPOutputHandlerTest extends SapphireTest
         $this->assertInstanceOf(DetailedErrorFormatter::class, $handler->getDefaultFormatter());
         $this->assertInstanceOf(DetailedErrorFormatter::class, $handler->getFormatter());
     }
+
+    public function provideShouldShowError()
+    {
+        $provide = [];
+        // See https://www.php.net/manual/en/errorfunc.constants.php
+        $errors = [
+            E_ERROR,
+            E_WARNING,
+            E_PARSE,
+            E_NOTICE,
+            E_CORE_ERROR,
+            E_CORE_WARNING,
+            E_COMPILE_ERROR,
+            E_COMPILE_WARNING,
+            E_USER_ERROR,
+            E_USER_WARNING,
+            E_USER_NOTICE,
+            E_RECOVERABLE_ERROR,
+            E_DEPRECATED,
+            E_USER_DEPRECATED,
+        ];
+        foreach ($errors as $errorCode) {
+            // Display all errors regardless of type in this scenario
+            $provide[] = [
+                'errorCode' => $errorCode,
+                'triggeringError' => true,
+                'isCli' => true,
+                'shouldShow' => true,
+                'expected' => true,
+            ];
+            // Don't display E_USER_DEPRECATED that we're triggering if shouldShow is false
+            $provide[] = [
+                'errorCode' => $errorCode,
+                'triggeringError' => true,
+                'isCli' => true,
+                'shouldShow' => false,
+                'expected' => ($errorCode !== E_USER_DEPRECATED) || false
+            ];
+            // Display all errors regardless of type in this scenario
+            $provide[] = [
+                'errorCode' => $errorCode,
+                'triggeringError' => true,
+                'isCli' => false,
+                'shouldShow' => true,
+                'expected' => true
+            ];
+            // Don't display E_USER_DEPRECATED that we're triggering if shouldShow is false
+            $provide[] = [
+                'errorCode' => $errorCode,
+                'triggeringError' => true,
+                'isCli' => false,
+                'shouldShow' => false,
+                'expected' => ($errorCode !== E_USER_DEPRECATED) || false
+            ];
+            // All of the below have triggeringError set to false, in which case
+            // all errors should be displayed.
+            $provide[] = [
+                'errorCode' => $errorCode,
+                'triggeringError' => false,
+                'isCli' => true,
+                'shouldShow' => true,
+                'expected' => true
+            ];
+            $provide[] = [
+                'errorCode' => $errorCode,
+                'triggeringError' => false,
+                'isCli' => false,
+                'shouldShow' => true,
+                'expected' => true
+            ];
+            $provide[] = [
+                'errorCode' => $errorCode,
+                'triggeringError' => false,
+                'isCli' => true,
+                'shouldShow' => false,
+                'expected' => true
+            ];
+            $provide[] = [
+                'errorCode' => $errorCode,
+                'triggeringError' => false,
+                'isCli' => false,
+                'shouldShow' => false,
+                'expected' => true
+            ];
+        }
+        return $provide;
+    }
+
+    /**
+     * @dataProvider provideShouldShowError
+     */
+    public function testShouldShowError(
+        int $errorCode,
+        bool $triggeringError,
+        bool $isCli,
+        bool $shouldShow,
+        bool $expected
+    ) {
+        $reflectionShouldShow = new ReflectionMethod(HTTPOutputHandler::class, 'shouldShowError');
+        $reflectionShouldShow->setAccessible(true);
+        $reflectionTriggeringError = new ReflectionProperty(Deprecation::class, 'isTriggeringError');
+        $reflectionTriggeringError->setAccessible(true);
+
+        $cliShouldShowOrig = Deprecation::shouldShowForCli();
+        $httpShouldShowOrig = Deprecation::shouldShowForHttp();
+        $triggeringErrorOrig = Deprecation::isTriggeringError();
+        // Set the relevant item using $shouldShow, and the other always as true
+        // to show that these don't interfere with each other
+        if ($isCli) {
+            Deprecation::setShouldShowForCli($shouldShow);
+            Deprecation::setShouldShowForHttp(true);
+        } else {
+            Deprecation::setShouldShowForCli(true);
+            Deprecation::setShouldShowForHttp($shouldShow);
+        }
+        $reflectionTriggeringError->setValue($triggeringError);
+
+        $mockHandler = $this->getMockBuilder(HTTPOutputHandler::class)->onlyMethods(['isCli'])->getMock();
+        $mockHandler->method('isCli')->willReturn($isCli);
+
+        $result = $reflectionShouldShow->invoke($mockHandler, $errorCode);
+        $this->assertSame($expected, $result);
+
+        Deprecation::setShouldShowForCli($cliShouldShowOrig);
+        Deprecation::setShouldShowForHttp($httpShouldShowOrig);
+        $reflectionTriggeringError->setValue($triggeringErrorOrig);
+    }
 }