Error backtrace malformatted

Thank you for working on those improvements! They make a difference for some people :)

+++ b/core/includes/errors.inc
@@ -160,18 +160,20 @@ function _drupal_log_error($error, $fatal = FALSE) {
-      \Drupal::logger('php')->log($error['severity_level'], '%type: @message in %function (line %line of %file) @backtrace_string.', $error + ['backtrace' => $backtrace]);
+      \Drupal::logger('php')->log($error['severity_level'], '%type: @message in %function (line %line of %file). <pre class="backtrace">@backtrace_string</pre>', $error + ['backtrace' => $backtrace]);

It is a bit weird to log HTML to be honest. Can't we make it a bit more obvious by introducing new lines here too?

Looks good!

Question, can we add this when displaying the log instead when saving it? I see a potential break in log parsers (other than provided by core) that expect to see %type: @message in %function (line %line of %file) @backtrace_string. and now they also find html inside.

> It is a bit weird to log HTML to be honest.

Yup. I thought that too but had no better idea.

I just tried this inside DbLogController::formatMessage() and seems to do the same thing. Also works for all error messages, not the new ones.

<?php
  public function formatMessage($row) {
    // Check for required properties.
    if (isset($row->message, $row->variables)) {
      $variables = @unserialize($row->variables);
      // Messages without variables or user specified text.
      if ($variables === NULL) {
        $message = Xss::filterAdmin($row->message);
      }
      elseif (!is_array($variables)) {
        $message = $this->t('Log data is corrupted and cannot be unserialized: @message', ['@message' => Xss::filterAdmin($row->message)]);
      }
      // Message to translate with injected variables.
      else {
        if ($row->message == '%type: @message in %function (line %line of %file) @backtrace_string.') {
          $row->message = '%type: @message in %function (line %line of %file) <pre class="backtrace">@backtrace_string</pre>.';
        }

        $message = $this->t(Xss::filterAdmin($row->message), $variables);
      }
    }
    else {
      $message = FALSE;
    }
    return $message;
  }
?>

@axel.rutz thanks for your comment.

It sounds very strange to me that people parse the HTML from the log, when they can swap out the error handler. (Do you do?)

I'm not saying they will parse html looking for logs. By changing that line you are basically affecting all loggers because they will now get a new error message with a new structure. We should try to minimize this type of changes if we can avoid them. For example people grepping syslog messages will not be able to do this anymore unless they notice this change.

Let's see what maintainer decides.

I cannot talk as core maintainer, but as current maintainer of the dblog and syslog modules I think it should be dblog responsibility to display the message properly. Even more when I shown in #23 is possible to do that without changing the log message structure.

If the main problem is that the dblog module is showing awful formatted back-traces, this seems more a visual fix than something to change when creating a log.

Thanks!. I would like to see a test that ensures this is working as expected.

Drupal\Tests\system\Functional\System\ErrorHandlerTest::testErrorHandler has some boilerplate you can use to trigger the exception and the code from Drupal\Tests\dblog\Functional\DbLogTest::testTemporaryUser() can be adapted to check the existence of the new <pre></pre> tags.

1. I added tests.

2. After adding the <pre></pre> tags, the dot displayed on a separate line at the end of the message. I moved the dot before backtrace.

#28 C:\drupal\core\lib\Drupal\Core\DrupalKernel.php(693): Stack\StackedHttpKernel->handle(Object(Symfony\Component\HttpFoundation\Request), 1, true)
#29 C:\drupal\index.php(19): Drupal\Core\DrupalKernel->handle(Object(Symfony\Component\HttpFoundation\Request))
#30 {main}
.

This looks really good! Thanks @Krzysztof Domański

+++ b/core/modules/dblog/src/Controller/DbLogController.php
@@ -362,6 +362,10 @@ public function formatMessage($row) {
+        // Wrap backtraces from _drupal_log_error() in a pre tag.

I think the mention to _drupal_log_error should be removed here. Since this function may chance anytime (it is internal).

In my opinion it would be better to just say. "Ensure backtrace strings are properly formatted", or something similar.

I tested the functionality as is working as expected.

My concerns from #25, #27 and #31 are now addressed.

Thanks @Krzysztof Domański.

Needs a re-roll.

Re-rolled. The code below has been added by #2228741: Replace calls to format_string() with Drupal\Component\Render\FormattableMarkup.

--- a/core/modules/dblog/tests/src/Functional/DbLogTest.php
+++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
@@ -2,6 +2,7 @@
 
 namespace Drupal\Tests\dblog\Functional;
 
+use Drupal\Component\Render\FormattableMarkup;

Nice clean-up!

1. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -362,6 +362,10 @@ public function formatMessage($row) {
   +        if ($row->message == '%type: @message in %function (line %line of %file) @backtrace_string.') {
   

   Additionally, we could consider the plain %type: @message in %function (line %line of %file). message to cover also watchdog_exception().

   Anyway, it would be safer to ensure that $variables['@backtrace_string'] is set to avoid further notices. Setting NW for this.

   Also, minor: let's use === here.

2. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -787,4 +794,28 @@ public function testSameTimestampEntries() {
   +      '%function' => 'Drupal\error_test\Controller\ErrorTestController->generateWarnings()',
   

   We could use ErrorTestController::class here and concatenate it with ->generateWarnings().

@plach Thanks for feedback. I fixed #41.2.

it would be safer to ensure that $variables['@backtrace_string'] is set to avoid further notices

I think we should address this problem in a separate issue, because it is out of scope. We should only improve the display of error backtrace here. Can you open a new issue for #41.1?

Thanks for the update!

+++ b/core/modules/dblog/src/Controller/DbLogController.php
@@ -362,6 +362,10 @@ public function formatMessage($row) {
+        if ($row->message === '%type: @message in %function (line %line of %file) @backtrace_string.') {

I don't think what I mentioned above is out of scope and thus deserves a new issue: the goal of this issue is to render backtraces correctly and watchdog_exception() is just another instance where the backtrace is rendered incorrectly (it's completely missing).

I mistakingly said that failing to check that @backtrace_string is set could trigger notices where in fact it wouldn't, however it would be a way to reinforce that we're actually dealing with the intended log event, since we're forced to check the message to recognize them. The added check would provide a bit more confidence that we are dealing with the intended case.

In short I'm proposing something like this:

if (isset($variables['@backtrace_string']) && preg_match('/%type: @message in %function \(line %line of %file\)( @backtrace_string)?./', $row->message)) {
  $row->message = '%type: @message in %function (line %line of %file). <pre class="backtrace">@backtrace_string</pre>';
}

+++ b/core/modules/dblog/src/Controller/DbLogController.php
@@ -362,6 +362,11 @@ public function formatMessage($row) {
+        if (isset($variables['@backtrace_string']) && strpos($row->message, $message_with_backtrace) !== FALSE) {

This won't work with the watchdog_exception() message, which has a trailing dot instead of the @backtrace_string bit (see #41). If we want to avoid the regexp we could list the two supported messages explicitly and use in_array.

Or we could do strpos($row->message, '%type: @message in %function (line %line of %file)') === 0.

Looks good, thanks!

I wish there were a more reliable way to identify relevant log entries, however this is a nice improvement over the current situation.

Rerolled

Is it worth opening a separate issue to refactor %type: @message in %function (line %line of %file). to a constant somewhere? This string appears at least 15 times in the codebase.

#52 Unrelated random test failure. Back to RTBC.

Back to RTBC as per #48

Poor TestBot,
lost the plot,
created a fluke fail (so Needs Work this does not).

(Yes, it's "Sinterklaas" in The Netherlands on Dec. 5th, and you need to hand out stupid rhymes along with stupid gifts...)

EDIT: Meh, I'm way too slow for @Krzysztof Domański

+++ b/core/modules/dblog/src/Controller/DbLogController.php
@@ -362,6 +362,10 @@ public function formatMessage($row) {
+        // Ensure backtrace strings are properly formatted.
+        if (isset($variables['@backtrace_string']) && strpos($row->message, '%type: @message in %function (line %line of %file)') === 0) {
+          $row->message = '%type: @message in %function (line %line of %file). <pre class="backtrace">@backtrace_string</pre>';
+        }
         $message = $this->t(Xss::filterAdmin($row->message), $variables);

To preserve the translation and not to foist extra work on the translator I'd do this a bit differently. We can do:

        if (isset($variables['@backtrace_string'])) {
          $variables['@backtrace_string'] = new FormattableMarkup(
            '<pre class="backtrace">@backtrace_string</pre>', $variables
          );
         }

Also this means that the wherever @backtrace_string has been used in custom errors it'll now appear nicely as well. This code could do with a comment.

This code could do with a comment.

@Krzysztof Domański Thanks! I think the comment is missing

This code could do with a comment.

Actually looking at the current code I think it is good to go. All we need is an RTBC :)

Tested locally. working as expected.

Committed and pushed 010c63bc66 to 9.0.x and f52c5af6f5 to 8.9.x. Thanks!

Going to ask other committers about backporting this. It make reading errors in logs simpler which has to be a good thing.

If the ancient Clan of Other Committers would decide on backporting this to D8.8 (which I really hope), patch #56 which was committed on D8.9 applies cleanly (and greenly) on the (current) latest D8.8.x-dev: https://www.drupal.org/pift-ci-job/1510080

@catch +1'd the backport.