[HttpKernel][Debug] Fix missing trace on deprecations collected during bootstrapping & silenced errors #23007

ogizanagi · 2017-06-01T09:20:49Z

Q	A
Branch?	3.3
Bug fix?	yes
New feature?	no
BC breaks?	no
Deprecations?	no
Tests pass?	yes
Fixed tickets	#22958
License	MIT
Doc PR	N/A

Before	After

(failures unrelated or deps=high fixed when merged in upper branches)

stof · 2017-06-01T10:55:49Z

src/Symfony/Component/HttpKernel/DataCollector/LoggerDataCollector.php

        $logs = array();
        foreach (unserialize(file_get_contents($file)) as $log) {
-            $log['context'] = array('exception' => new SilencedErrorContext($log['type'], $log['file'], $log['line']));


why not adding trance support for the SilencedErrorContext instead of using reflection on ErrorException ?

I hesitated. I've finally opted for the \ErrorException as we already get for runtime deprecations.

Also SilencedErrorContext implements JsonSerializable; I wasn't convinced what to do with the trace regarding this. If it's cleaned from any object (by not having objects and arguments in the trace) it's ok. But by adding a $trace argument, we can't assume the trace is safe and would need to be cleaned (hence not really a DTO anymore)...or simply ignored in the serialized version.

stof · 2017-06-01T10:58:19Z

Do deprecations catched by the error handler have their trace properly already ? You haven't changed this code path

nicolas-grekas · 2017-06-01T10:59:17Z

This might explode memory.

ogizanagi · 2017-06-01T11:18:34Z

Do deprecations catched by the error handler have their trace properly already

They did. So I didn't dig deeper in the debug component and the usage of the SilencedErrorContext actually (this only targets the deprecations collected during bootstrapping).

This might explode memory.

I think we're safe enough, as we ignore args and objects (which anyway is required to me as I serialize the trace). But perhaps set a limit on debug_backtrace.

ro0NL · 2017-06-01T13:25:02Z

Works for us 👍

{▼
  /base-path/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/DependencyInjection/Extension.php:62: {▶}
  /base-path/vendor/symfony/assetic-bundle/DependencyInjection/AsseticExtension.php:135: {▶}
  /base-path/vendor/symfony/symfony/src/Symfony/Component/DependencyInjection/Compiler/MergeExtensionConfigurationPass.php:59: {▶}
  /base-path/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/DependencyInjection/MergeExtensionConfigurationPass.php:39: {▶}
  /base-path/vendor/symfony/symfony/src/Symfony/Component/DependencyInjection/Compiler/Compiler.php:143: {▶}
  /base-path/vendor/symfony/symfony/src/Symfony/Component/DependencyInjection/ContainerBuilder.php:736: {▶}
  /base-path/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/Kernel.php:564: {▶}
  /base-path/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/Kernel.php:119: {▶}
  /base-path/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/Kernel.php:168: {▶}
  /base-path/web/app.php:24: {▶}
}

ogizanagi · 2017-06-01T16:31:52Z

@stof : I updated the PR to use back the SilencedErrorContext DTO.

Actually, the trace was already available for runtime deprecations because they were thrown, and thus convert to \ErrorException. But if the error is not thrown (for instance by triggering a php warning (silenced) or using @trigger_error('foo', E_USER_WARNING)), the log doesn't come with the full trace:

Before	After

nicolas-grekas · 2017-06-02T21:57:34Z

src/Symfony/Component/Debug/ErrorHandler.php

@@ -687,4 +676,23 @@ protected function getFatalErrorHandlers()
            new ClassNotFoundFatalErrorHandler(),
        );
    }
+
+    private function cleanTrace($backtrace, $type, $file, $line, $throw, $excludeSelf = true)


rename $excludeSelf to $offset (integer)?
I'd remove the default value also

nicolas-grekas · 2017-06-02T21:58:17Z

src/Symfony/Component/Debug/ErrorHandler.php

@@ -407,7 +407,8 @@ public function handleError($type, $message, $file, $line)
            $errorAsException = self::$toStringException;
            self::$toStringException = null;
        } elseif (!$throw && !($type & $level)) {
-            $errorAsException = new SilencedErrorContext($type, $file, $line);
+            $lightTrace = $this->tracedErrors & $type ? $this->cleanTrace($backtrace ?: debug_backtrace(), $type, $file, $line, false, false) : array();


debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS)

nicolas-grekas · 2017-06-02T22:00:59Z

src/Symfony/Component/Debug/Exception/SilencedErrorContext.php

    public function JsonSerialize()
    {
        return array(
            'severity' => $this->severity,
            'file' => $this->file,
            'line' => $this->line,
+            'trace' => array_map(function ($item) {
+                unset($item['object'], $item['args']);


these should not be injected in the first place to I'd remove that filtering

nicolas-grekas · 2017-06-02T22:02:06Z

src/Symfony/Component/HttpKernel/Kernel.php

@@ -545,11 +545,21 @@ protected function initializeContainer()
                        return $previousHandler ? $previousHandler($type, $message, $file, $line) : false;
                    }

+                    $backtrace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);


does this provide value at all?
it looks like duplication to me

I don't get this comment :/ . I need to call debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS) here to get the trace to be added to the array we persist in appDevDebugProjectContainerDeprecations.log.

I'm suggesting we don't need this trace at all: it's always the same so it provides no value.

ok, nevermind, this is in an error handler so the stack is dynamic.

nicolas-grekas · 2017-06-02T22:03:34Z

src/Symfony/Component/VarDumper/Caster/ExceptionCaster.php

@@ -93,12 +92,12 @@ public static function castSilencedErrorContext(SilencedErrorContext $e, array $
            $a[$s] = new ConstStub(self::$errorTypes[$a[$s]], $a[$s]);
        }

-        $trace = array(
+        $trace = $a[$sPrefix.'trace'] ?: array(array(


this is not compatible with older version of Debug, an isset check is missing

nicolas-grekas · 2017-06-02T22:12:44Z

I'm still worried about the perf impact, both in terms of memory and speed. Deprecations can be thousands, this may add overhead to a hot code path.

I was about to propose deduplicating silenced notices based solely on the message. To prevent any mem leak, we should have a fixed size dedup map, keyed by messages. Then we could add a counter to silenced error objects.

Or any better idea. The main point is doing as less as possible here :)

ogizanagi · 2017-06-03T07:53:40Z

For the record, I made some comparisons for runtimes silenced errors:

1 vs 1 000 warnings: https://blackfire.io/profiles/compare/16a69caa-8004-42d7-beb8-066ae4f1c1a1/graph
1 vs 10 000 warnings: https://blackfire.io/profiles/compare/0d4e2718-1a16-4385-a989-3e427c5e539d/graph

So indeed, dedup silenced notices based on their type, file, line and message looks like a good tradeoff to me.
Hence, I added a cache for SilencedErrorContext instances in the ErrorHandler. This change looks enough to me to get satisfying results for silenced errors:

1 000 warnings vs 1 000 warnings with cache: https://blackfire.io/profiles/compare/35872a18-2815-4aab-b9e3-245a7d0f0402/graph
10 000 warnings vs 10 000 warnings with cache: https://blackfire.io/profiles/compare/fae60ef6-f17d-44c5-8f43-05b3b8af70a1/graph
1 vs 10 000 warnings with cache: https://blackfire.io/profiles/compare/d9c9ba87-af73-4243-ac9e-e02dbcd0a1bf/graph

nicolas-grekas · 2017-06-03T09:11:34Z

Here is one more (unfinished) step:

--- a/src/Symfony/Component/Debug/ErrorHandler.php
+++ b/src/Symfony/Component/Debug/ErrorHandler.php
@@ -408,13 +408,17 @@ class ErrorHandler
             $errorAsException = self::$toStringException;
             self::$toStringException = null;
         } elseif (!$throw && !($type & $level)) {
-            $cacheKey = md5("$type/$line/$file\0$message", true);
-            if (isset(self::$silencedErrorCache[$cacheKey])) {
-                $errorAsException = self::$silencedErrorCache[$cacheKey];
-            } else {
-                $lightTrace = $this->tracedErrors & $type ? $this->cleanTrace(debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS), $type, $file, $line, false) : array();
-                $errorAsException = self::$silencedErrorCache[$cacheKey] = new SilencedErrorContext($type, $file, $line, $lightTrace);
+            if (isset(self::$silencedErrorCache[$message])) {
+                self::$silencedErrorCache[$message]->count += 1;
+
+                return;
+            }
+
+            if (100 < count(self::$silencedErrorCache)) {
+                self::$silencedErrorCache = array();
             }
+            $lightTrace = $this->tracedErrors & $type ? $this->cleanTrace(debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS), $type, $file, $line, false) : array();
+            $errorAsException = self::$silencedErrorCache[$message] = new SilencedErrorContext($type, $file, $line, $lightTrace);
         } else {
             if ($scope) {
                 $errorAsException = new ContextErrorException($logMessage, 0, $type, $file, $line, $context);

ogizanagi · 2017-06-03T09:29:34Z

Is just using $message over md5("$type/$line/$file\0$message", true) done on purpose? That does not seem enough to me. A same error can happen from multiple files. We only want to dedup same code paths triggering the same error, right?

nicolas-grekas · 2017-06-03T09:41:26Z

md5 removal is on purpose, that's a "heavy" call.
I propose using only $message because it removes any need for computation - even string hashing would be unnecessary to do the isset check. I agree that in theory this can be too aggressive, but I doubt this will make any practical difference (but the perf optim.)

nicolas-grekas · 2017-06-03T09:50:42Z

Better?

--- a/src/Symfony/Component/Debug/ErrorHandler.php
+++ b/src/Symfony/Component/Debug/ErrorHandler.php
@@ -408,13 +408,17 @@ class ErrorHandler
             $errorAsException = self::$toStringException;
             self::$toStringException = null;
         } elseif (!$throw && !($type & $level)) {
-            $cacheKey = md5("$type/$line/$file\0$message", true);
-            if (isset(self::$silencedErrorCache[$cacheKey])) {
-                $errorAsException = self::$silencedErrorCache[$cacheKey];
-            } else {
-                $lightTrace = $this->tracedErrors & $type ? $this->cleanTrace(debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS), $type, $file, $line, false) : array();
-                $errorAsException = self::$silencedErrorCache[$cacheKey] = new SilencedErrorContext($type, $file, $line, $lightTrace);
+            if (100 < ++self::$silencedErrorCounter)) {
+                self::$silencedErrorCache = array();
+                self::$silencedErrorCounter = 1;
+            } elseif (isset(self::$silencedErrorCache[$message])) {
+                self::$silencedErrorCache[$message]->count += 1;
+
+                return;
             }
+            $lightTrace = $this->tracedErrors & $type ? $this->cleanTrace(debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS), $type, $file, $line, false) : array();
+            $errorAsException = self::$silencedErrorCache[$message] = new SilencedErrorContext($type, $file, $line, $lightTrace);
         } else {
             if ($scope) {
                 $errorAsException = new ContextErrorException($logMessage, 0, $type, $file, $line, $context);

nicolas-grekas · 2017-06-03T11:35:18Z

src/Symfony/Component/Debug/ErrorHandler.php

@@ -100,6 +100,8 @@ class ErrorHandler
    private static $stackedErrors = array();
    private static $stackedErrorLevels = array();
    private static $toStringException = null;
+    private static $silencedErrorCache = array();
+    private static $silencedErrorCounter = 0;


should be intialized at 1 (same value as when reinit below)

nicolas-grekas · 2017-06-03T11:36:07Z

src/Symfony/Component/Debug/ErrorHandler.php

@@ -407,7 +409,17 @@ public function handleError($type, $message, $file, $line)
            $errorAsException = self::$toStringException;
            self::$toStringException = null;
        } elseif (!$throw && !($type & $level)) {
-            $errorAsException = new SilencedErrorContext($type, $file, $line);
+            if (!isset(self::$silencedErrorCache[$message]) && ++self::$silencedErrorCounter > 100) {


I'd remove the first isset check here, to still keep 1/100 duplicates

nicolas-grekas · 2017-06-03T11:38:02Z

src/Symfony/Component/HttpKernel/DataCollector/LoggerDataCollector.php

+                );
+                $sanitizedLogs[$log['message']] = $log;
+
+                continue;


if we keep 1/100 as I just proposed, this will need to account for this possibility

…g bootstrapping & silenced errors

nicolas-grekas

👍 (deps=high will be fixed when merging into 3.4)

fabpot · 2017-06-06T14:52:01Z

Thank you @ogizanagi.

…ected during bootstrapping & silenced errors (ogizanagi) This PR was merged into the 3.3 branch. Discussion ---------- [HttpKernel][Debug] Fix missing trace on deprecations collected during bootstrapping & silenced errors | Q | A | ------------- | --- | Branch? | 3.3  | Bug fix? | yes | New feature? | no  | BC breaks? | no | Deprecations? | no  | Tests pass? | yes | Fixed tickets | #22958  | License | MIT | Doc PR | N/A |Before|After| |--|--| |<img width="1086" alt="screenshot 2017-06-01 a 10 12 07" src="https://cloud.githubusercontent.com/assets/2211145/26670940/feb51b52-46b3-11e7-806f-e23e2eb248c1.PNG">|<img width="1094" alt="screenshot 2017-06-01 a 10 13 39" src="https://cloud.githubusercontent.com/assets/2211145/26670941/feb8bd66-46b3-11e7-8e54-cc4959487b7a.PNG">| (failures unrelated or deps=high fixed when merged in upper branches) Commits ------- 21ef065 [HttpKernel][Debug] Fix missing trace on deprecations collected during bootstrapping & silenced errors

carsonbot added Status: Needs Review HttpKernel Bug labels Jun 1, 2017

ogizanagi mentioned this pull request Jun 1, 2017

Unhelpful deprecation trace in 3.3 #22958

Closed

stof reviewed Jun 1, 2017

View reviewed changes

ogizanagi changed the title ~~[HttpKernel] Fix missing trace on deprecations collected during bootstrapping~~ [HttpKernel][Debug] Fix missing trace on deprecations collected during bootstrapping & silenced errors Jun 1, 2017

nicolas-grekas added this to the 3.3 milestone Jun 2, 2017

nicolas-grekas reviewed Jun 2, 2017

View reviewed changes

nicolas-grekas reviewed Jun 3, 2017

View reviewed changes

[HttpKernel][Debug] Fix missing trace on deprecations collected durin…

21ef065

…g bootstrapping & silenced errors

greg0ire mentioned this pull request Jun 6, 2017

HelperController setEnvironment throws deprectated ERROR 500 sonata-project/SonataAdminBundle#4505

Closed

nicolas-grekas approved these changes Jun 6, 2017

View reviewed changes

fabpot merged commit 21ef065 into symfony:3.3 Jun 6, 2017

ogizanagi deleted the fix/app_bootstrap_deprec branch June 6, 2017 14:53

fabpot mentioned this pull request Jul 4, 2017

Release v3.3.3 #23369

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[HttpKernel][Debug] Fix missing trace on deprecations collected during bootstrapping & silenced errors #23007

[HttpKernel][Debug] Fix missing trace on deprecations collected during bootstrapping & silenced errors #23007

ogizanagi commented Jun 1, 2017 •

edited

Loading

stof Jun 1, 2017

ogizanagi Jun 1, 2017 •

edited

Loading

stof commented Jun 1, 2017

nicolas-grekas commented Jun 1, 2017

ogizanagi commented Jun 1, 2017 •

edited

Loading

ro0NL commented Jun 1, 2017

ogizanagi commented Jun 1, 2017 •

edited

Loading

nicolas-grekas Jun 2, 2017

nicolas-grekas Jun 2, 2017 •

edited

Loading

nicolas-grekas Jun 2, 2017

nicolas-grekas Jun 2, 2017

ogizanagi Jun 3, 2017

nicolas-grekas Jun 3, 2017

nicolas-grekas Jun 3, 2017

nicolas-grekas Jun 2, 2017

nicolas-grekas commented Jun 2, 2017 •

edited

Loading

ogizanagi commented Jun 3, 2017

nicolas-grekas commented Jun 3, 2017

ogizanagi commented Jun 3, 2017

nicolas-grekas commented Jun 3, 2017 •

edited

Loading

nicolas-grekas commented Jun 3, 2017

nicolas-grekas Jun 3, 2017

nicolas-grekas Jun 3, 2017

nicolas-grekas Jun 3, 2017

nicolas-grekas left a comment •

edited

Loading

fabpot commented Jun 6, 2017

[HttpKernel][Debug] Fix missing trace on deprecations collected during bootstrapping & silenced errors #23007

[HttpKernel][Debug] Fix missing trace on deprecations collected during bootstrapping & silenced errors #23007

Conversation

ogizanagi commented Jun 1, 2017 • edited Loading

Choose a reason for hiding this comment

ogizanagi Jun 1, 2017 • edited Loading

Choose a reason for hiding this comment

stof commented Jun 1, 2017

nicolas-grekas commented Jun 1, 2017

ogizanagi commented Jun 1, 2017 • edited Loading

ro0NL commented Jun 1, 2017

ogizanagi commented Jun 1, 2017 • edited Loading

Choose a reason for hiding this comment

nicolas-grekas Jun 2, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nicolas-grekas commented Jun 2, 2017 • edited Loading

ogizanagi commented Jun 3, 2017

nicolas-grekas commented Jun 3, 2017

ogizanagi commented Jun 3, 2017

nicolas-grekas commented Jun 3, 2017 • edited Loading

nicolas-grekas commented Jun 3, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nicolas-grekas left a comment • edited Loading

Choose a reason for hiding this comment

fabpot commented Jun 6, 2017

ogizanagi commented Jun 1, 2017 •

edited

Loading

ogizanagi Jun 1, 2017 •

edited

Loading

ogizanagi commented Jun 1, 2017 •

edited

Loading

ogizanagi commented Jun 1, 2017 •

edited

Loading

nicolas-grekas Jun 2, 2017 •

edited

Loading

nicolas-grekas commented Jun 2, 2017 •

edited

Loading

nicolas-grekas commented Jun 3, 2017 •

edited

Loading

nicolas-grekas left a comment •

edited

Loading