Display backtrace for logged throwables on log message details page

Thank you for the MR quick fix.

This could use an issue summary update. What is being fixed and why.
Also with a new feature a test will be needed.

Shouldn't $error already contain $error['@backtrace_string'] so there would be no need to add it to the array?

To avoid code duplication, could the string be something like this: Error::DEFAULT_ERROR_MESSAGE . ' <pre class="backtrace">@backtrace_string</pre>'

And as I mentioned, there should be no need to add another element to the $error array - the backtrace string is already there.

Moving this to 10.1.x where new features need to land.

Rerolled the patch #9 in Drupal 10.1.x and changes comment #10 .

$error should still be passed in as an argument

It looks like I was wrong about adding the <pre> tag. Apparently, dblog module adds this tag itself when rendering a log message containing @backtrace_string

So, this line should read: $this->logger->get('php')->log($error['severity_level'], Error::DEFAULT_ERROR_MESSAGE . ' @backtrace_string', $error);

@mfb updated patch with the changes you suggested.
Please check.

Moving back to NW for the issue summary update and tests

For anyone who wants to work on tests, I'd suggest adding a functional test to dblog module, using one of the error_test module routes which throw exceptions

May have time this week to try a test as I just used that error_test module for another issue.

May need help with the IS update.

Here's a test.

Leaving in NW for the issue summary update.

This is looking good to me so moving to RTBC

+++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
@@ -143,6 +143,30 @@ public function testLogEventPage() {
+  /**
+   * Test that an error logged has a backtrace.
+   */
+  public function testOnError() {

This test being in the dblog module feels wrong. Because with the dblog module you do have the full backtrace. It'll be in the variables column.

I think the point of this change is that other logging services (for example syslog) don't save all the variables. So for me we should be testing this outside of dblog.

I think a unit test would suffice here.

You make a good point @alexpott, and it brings up a question: Since dblog is already storing the @backtrace_string in the variables database column, we could simply display @backtrace_string as a new row at the bottom of the dblog event details page, without "forcing" all loggers to ingest @backtrace_string as part of the log message? I could go either way on this; but as @backtrace_string already does appear in *some* log messages, the current approach of the patch feels pretty reasonable. In any case, I'll work on unit test.

Here's a unit test checking for the correct log message; didn't remove the new dblog functional test as it seems fine to have both.

The question in #24 is a good one.

+++ b/core/lib/Drupal/Core/EventSubscriber/ExceptionLoggingSubscriber.php
@@ -67,7 +67,7 @@ public function on404(ExceptionEvent $event) {
-    $this->logger->get('php')->log($error['severity_level'], Error::DEFAULT_ERROR_MESSAGE, $error);
+    $this->logger->get('php')->log($error['severity_level'], Error::DEFAULT_ERROR_MESSAGE . ' @backtrace_string', $error);
 
     $is_critical = !$exception instanceof HttpExceptionInterface || $exception->getStatusCode() >= 500;

I think we should only be adding the backtrace for critical errors. Like I don't think we should be adding backtraces for \Symfony\Component\HttpKernel\Exception\UnsupportedMediaTypeHttpException for example.

And we should have concerns about swamping logs.

So yeah I think we should have the ability to display the backtrace in dblog if we have the backtrace_string in the context variables - even if it is not in the message. Great idea @mfb

And then we won't need to make the change to ExceptionLoggingSubscriber

Here's the alternate approach to not add @backtrace_string to the log message, and instead display it as a new row at the bottom of the dblog event details page.

@mfb #28 looks nice!

I think we should only do this if the string does not have the @backtrace_string in it - otherwise the page is going to have a lot of duplicate content.

Resolves #29

Fix command failures #30

+++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
@@ -143,6 +143,30 @@ public function testLogEventPage() {
diff --git a/core/themes/gin b/core/themes/gin

diff --git a/core/themes/gin b/core/themes/gin
new file mode 160000

new file mode 160000
index 0000000000..0a89ac8733

index 0000000000..0a89ac8733
--- /dev/null

--- /dev/null
+++ b/core/themes/gin

+++ b/core/themes/gin
+++ b/core/themes/gin
@@ -0,0 +1 @@

@@ -0,0 +1 @@
+Subproject commit 0a89ac873395ae9ecff7474a4685a305463c9ac6

This should not be here.

Resolved #32

This issue is being reviewed by the kind folks in Slack, #needs-review-queue-initiative. We are working to keep the size of Needs Review queue [2700+ issues] to around 400 (1 month or less), following Review a patch or merge request as a guide.

#33 appears (from what I can tell) to be a rebase.

Since there were a number of changes since I added a test case in #19 think I'm good to review.

So reviewing #34

Tested this using the error_test module and visiting /error-test/trigger-exception
Checking the logs and I see

Exception: Drupal & awesome in Drupal\error_test\Controller\ErrorTestController->triggerException() (line 74 of /var/www/html/web/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php).

with no backtrace

Applying fix
I see the same issue with the backtrace.

Looks good!

Created a draft change record @ https://www.drupal.org/node/3340781

+++ b/core/includes/errors.inc
@@ -172,7 +172,7 @@ function _drupal_log_error($error, $fatal = FALSE) {
-      \Drupal::logger('php')->log($severity, '%type: @message in %function (line %line of %file) @backtrace_string.', $error + ['backtrace' => $backtrace, 'exception' => $exception, 'severity_level' => $severity]);
+      \Drupal::logger('php')->log($severity, Error::DEFAULT_ERROR_MESSAGE, $error + ['backtrace' => $backtrace, 'exception' => $exception, 'severity_level' => $severity]);

+++ b/core/lib/Drupal/Core/Config/Entity/ConfigEntityUpdater.php
@@ -154,7 +154,7 @@ public function update(array &$sandbox, $entity_type_id, callable $callback = NU
-        \Drupal::logger('update')->error('Unable to update %entity_type %view due to error @message %function (line %line of %file). <pre>@backtrace_string</pre>', $context);
+        \Drupal::logger('update')->error('Unable to update %entity_type %view due to error @message %function (line %line of %file).', $context);

I don't think we should be making these changes here. This will alter the syslog output.

Well, I'm unclear on the logic of sending @backtrace_string to syslog here, but not for most throwables which are logged by the ExceptionLoggingSubscriber. Note that previously PHP triggered lots of old-fashioned PHP errors/warnings/etc. but now throwing an Error is more common, and they go to ExceptionLoggingSubscriber most of the time. And throwables are the main thing that you would expect to have a backtrace for.

My understanding is anything thrown during normal request handling is logged by ExceptionLoggingSubscriber; and outside of that _drupal_log_error() is used (e.g. running a script via drush with drupal bootstrapped).

We could have syslog start logging @backtrace_string? Or have a new syslog config toggle to add @backtrace_string to the syslog message? That way it could finally be logged for most throwabes.

Note that when you send @backtrace_string to syslog you actually get multiple syslog messages, one for each line :/ So I'm not sure everyone appreciates it, but if syslog is your only logging then I guess that's where you want to find backtraces..

@mfb let’s open a follow-up to discuss that. I don’t think that working that out needs to impact us making this improvement in dblog.

Ok removed those changes, and updated the change record to match.

Filed a followup @ #3340963: Sort out @backtrace_string logging by Syslog module

I don't use syslog module so I don't have strong feelings how it should work, but I do maintain two contrib logger modules, so more sanity around this is helpful :)

Moving back to RTBC but could some strike out in the issue summary which option wasn't chosen?

Unrelated failure

+1. Moving patch to MR.

There are reasons to convert a patch to an MR but this was already RTBC and doing so it was not needed. There are no comments why the MR was done. This MR is against 9.4.x, where this patch is not eligible. It also generated two unnecessary test runs. To be sure there were no changes I downloaded both the MR and patch. They are the same. Therefor, credit has been removed per How is credit granted for Drupal core issues.

Also, the latest patch is no longer being tested every two day. Since I have already downloaded the patch, I will upload again to be sure that the automatic testing restarts.

That was an unrelated failure, back to RTBC

I am doing triage on the core RTBC queue.

I read the issue summary, comments and the patch. The proposed resolution matches the patch. The remaining tasks is a bit of date but lets see if I find anything still to do.

I don't know the error handling system so I applied the patch and ran the tests. The output in the logs is just another row for the backtrace and it was formatted correctly. I then copied the trigger_error line from the test to another form and went to that form. The resulting error does not have a backtrace. Why? To answer that I read the CR. I guess the form I was using doesn't use ExceptionLoggingSubscriber?

Now that I have read the CR I see that the branch/version are out of date. The CR mentions adding '@backtrace_string' in the context array. This should be accompanied by a before and after example. Along with anything else one needs to do to use this functionality.

Oh, and the title should explain what the change is. Maybe something like 'Backtrace can be logged when using ExceptionLoggingSubscriber or watchdog_exception()"?

For updating the CR I am adding the tag and setting to NW.

And from reading the patch there were two small things.

+++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
@@ -143,6 +143,30 @@ public function testLogEventPage() {
+   * Test that an error logged has a backtrace.

Should be "Tests" not "Test".
This reads as if any error logged will have a backtrace which isn't true

@quietone thanks for the review, I tried to clarify the change record. Let me know what you think.

I also updated the test method description to clarify that this specific test is about the backtrace being displayed when a throwable is logged.

The idea is that with this change, Database Logging module will display a backtrace in many common cases. When trigger_error() is called, both the log message and context should contain @backtrace_string and therefore the backtrace should be displayed as part of the log message. This was already the case, and is tested by \Drupal\Tests\dblog\Functional\DbLogTest::testBacktrace(). When a throwable is logged, the context should contain @backtrace_string, although the log message will not, and therefore the backtrace should be displayed at the bottom of the details page. This is the new behavior, and is tested by \Drupal\Tests\dblog\Functional\DbLogTest::testOnError().

@quietone could you clarify the situation where there is no backtrace so we can double check all this?

(By the way, in followup issue #3340963: Sort out @backtrace_string logging by Syslog module, we can discuss if it makes sense to remove @backtrace_string from the log message and provide it only in the context, under the reasoning that such a string is too long for a log message, and loggers can retrieve it from the context if/when they want it, as dblog is doing in this case.)

Removed remaining tasks (until next review :)

@mfb Any particular reason why

          // Save a reference so the backtrace can be displayed separately.
          if (!str_contains($row->message, '@backtrace_string')) {
            $row->backtrace = $variables['@backtrace_string'];
          }

Can be calculated inside the eventDetails method? The logic here seems a bit odd to follow. Also with change from #52 ::formatMessage would do more than just formatting the message.

Ok, I added more documentation re: the formatMessage() method not just formatting the message, but also adding a backtrace property to the row if there is a @backtrace_string that is not used in the message.

In the formatMessage() method, the variables are unserialized and the backtrace markup object is created for use in the message. It would be redundant to repeat these two steps again in the eventDetails() method. If we need to further refactor this code, it would be nice to figure out a way to do that without redundancy.

latest MR applies cleanly to 10.1 and works great, thanks y'all!
+1 RTBC from me

Would love to see this feature in an upcoming D10 release, and not have to maintain this patch for the next couple years... do we need a "needs backport" tag for that?

In the formatMessage() method, the variables are unserialized and the backtrace markup object is created for use in the message. It would be redundant to repeat these two steps again in the eventDetails()

@mfb I see. Thanks!

Are we re-introducing #2371141: XSS vulnerability when displaying exception backtrace because we are not sanitizing the output? I would love to see a test case for this new addition.

Added an assertion that the backtrace is HTML-encoded

Seems #57 has been addressed. Remarking this one.

+1 for interest on getting this one commited.

There are two open merge requests and a patch in the issue summary. There should be only one canonical patch or merge request listed.

Please close the non-canonical merge request(s) and hide non-canonical patches. If you don't have permission to close merge requests, please hide any non-canonical patches and then document which merge request(s) should be closed in an issue comment and the IS. This will allow a committer to close them for you. Thanks!

#62 also MR is saying unmeragble so will need manual rebase it seems.

My latest work on this is patch #59; please close both MRs thank you!

Done, thanks @mfb!

Some things to review and fix -- mostly small docs stuff.

1. Should there be a new restricted-access permission for viewing backtraces? Or is whatever current permission is required sufficient?

2. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -291,6 +291,12 @@ public function eventDetails($event_id) {
   +        ['data' => $this->t('Backtrace'), 'header' => TRUE],
   +        $dblog->backtrace,
   

   I feel like some things already have backtraces in the description... or am I thinking of devel? If I am thinking of devel, it merely needs a CR. If I'm actually remembering other backtraces in the log, then we also need core issue followups for those cases.

3. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -348,7 +354,10 @@ protected function buildFilterQuery(Request $request) {
       *   The record from the watchdog table. The object properties are: wid, uid,
   -   *   severity, type, timestamp, message, variables, link, name.
   +   *   severity, type, timestamp, message, variables, link, name. If the
   +   *   variables contain a @backtrace_string placeholder which is not used in
   +   *   the message, the formatted backtrace will be assigned to a new backtrace
   +   *   property on the row object which can be displayed separately.
   

   I think the added information should be in a separate paragraph in the row description. (I also think the list of properties should be in a list, but that's out of scope here.)

4. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -142,6 +142,31 @@ public function testLogEventPage() {
   +   * Tests that the details page displays the backtrace for a logged throwable.
   

   "Throwable" is a Drupalism used in like five places that we might try to remove from the dictionary. Could we just say "logged exception"?

5. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -142,6 +142,31 @@ public function testLogEventPage() {
   +    // Login the admin user.
   

   Nit: "Login" is a noun. "Log in" is a verb. So:

   Log in as the admin user.

6. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -142,6 +142,31 @@ public function testLogEventPage() {
   +    // Trigger error.
   

   I don't think this comment is helpful as-is. It should either be removed or expanded with more detail.

7. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -142,6 +142,31 @@ public function testLogEventPage() {
   +    $query = Database::getConnection()->select('watchdog')
   +      ->condition('type', 'php');
   +    $query->addExpression('MAX([wid])');
   +    $wid = $query->execute()->fetchField();
   +    $this->drupalGet('admin/reports/dblog/event/' . $wid);
   

   OTOH, this could use an inline comment. explaining what's going on.

8. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -142,6 +142,31 @@ public function testLogEventPage() {
   +    $table = $this->assertSession()->elementExists('xpath', "//table[@class='dblog-event']");
   +    $type = "//tr/th[contains(text(), 'Type')]/../td";
   +    $this->assertSession()->elementsCount('xpath', $type, 1, $table);
   

   As could this.

9. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -142,6 +142,31 @@ public function testLogEventPage() {
   +    $backtrace = "//tr//pre[contains(@class, 'backtrace')]";
   +    $this->assertCount(1, $table->findAll('xpath', $backtrace));
   +    $this->assertSession()->responseContains(htmlspecialchars("<script>alert('xss')</script>"));
   

   As could this. Especially the last line. I had a brief moment of panic with the positive assertion and the JS before I re-read and caught the htmlspecialchars(). 😛 I would prefer that assertions contain a string literal rather than functions operating on a string.

10. +++ b/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php
    @@ -69,8 +69,11 @@ public function generateFatals() {
    -  public function triggerException() {
    +  public function triggerException($argument = "<script>alert('xss')</script>") {
    

    The new parameter needs a typehint and documentation in the docblock.

11. +++ b/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php
    @@ -69,8 +69,11 @@ public function generateFatals() {
    +    // Add function calling arguments to the exception backtrace.
    

    I think "function call" would work here (rather than "function calling")?

Removed the "Needs change record" tag because this issue already has a change record. Feel free to criticize and/or re-draft it though :)

Should there be a new restricted-access permission for viewing backtraces? Or is whatever current permission is required sufficient?

I don't think a new permission is necessary, because A) some Drupal core logging mechanisms already make backtraces available as part of the log message, so this is not the first time that site admins have access to exception backtraces, it would just be happening more often now; and B) PHP, assuming it is configured correctly (!), keeps backtraces free of sensitive data via two configs: zend.exception_ignore_args (should be enabled on production to leave function arguments out of the backtrace) and zend.exception_string_param_max_len (should be zero on production, such that if arguments are added to the backtrace, strings will be cutoff at zero characters).

I feel like some things already have backtraces in the description... or am I thinking of devel? If I am thinking of devel, it merely needs a CR. If I'm actually remembering other backtraces in the log, then we also need core issue followups for those cases.

Yes, some things already have a backtrace in the log message: 1) When a \Throwable is thrown early or late in the request lifecycle, it is caught by Drupal's exception handler; and 2) when a PHP error/warning is triggered (these are triggered not thrown), it is caught by Drupal's error handler; both of these mechanisms add the backtrace to the log message.

This issue is addressing two other logging mechanisms. There is no backtrace added to the log message 1) when a \Throwable is thrown in the middle of the request (e.g. in a controller) and caught by \Drupal\Core\EventSubscriber\ExceptionLoggingSubscriber::onError(), or 2) when a developer uses \Drupal\Core\Utility\Error::logException() to manually log a \Throwable. The backtrace is however in the log context in both cases, and thus available to loggers such as dblog, which is what we're taking advantage of in this patch.

This was already explained to some extent in the change record, but we could flesh it out further if need be.

As far as followups: We could e.g. remove backtrace strings where they do already appear in log messages, and switch to the mechanism used in this patch. I like the idea, but I'm not sure there is consensus; some people might be relying on the currently-existing backtraces in their log messages in Syslog or wherever they are logging. Personally, I prefer to have short log messages in Syslog, and some other system for storing backtraces and other large blobs of data ("crash dumps"). I did previously open this related/followup issue for further discussion re: Syslog module: #3340963: Sort out @backtrace_string logging by Syslog module. I think anyone who really cares about logging, and wants to customize it, can install a module like Monolog and go to town, so they're not inclined to worry about how core logs out-of-the-box.

I think the added information should be in a separate paragraph in the row description. (I also think the list of properties should be in a list, but that's out of scope here.)

Done.

"Throwable" is a Drupalism used in like five places that we might try to remove from the dictionary. Could we just say "logged exception"?

Changed to \Throwable (a PHP class interface, not a Drupalism). "Logged exception" is unclear because we are talking about both \Exception and \Error objects, i.e. \Throwable objects.

Nit: "Login" is a noun. "Log in" is a verb. So:

Fixed

I don't think this comment is helpful as-is. It should either be removed or expanded with more detail.

Changed to clearly say what scenario we are testing: "Load a page that throws an exception in the controller, and includes its function arguments in the exception backtrace."

OTOH, this could use an inline comment. explaining what's going on.

Added "Load details page for the most recent event logged by the "php" logger."

As could this.

Added that - I think - this is just checking that there's a vaguely-correct dblog-event table with a "Type" header cell? Idk lol.

As could this. Especially the last line. I had a brief moment of panic with the positive assertion and the JS before I re-read and caught the htmlspecialchars(). 😛 I would prefer that assertions contain a string literal rather than functions operating on a string.

Added explanation and changed to string literal.

The new parameter needs a typehint and documentation in the docblock.

Added types and docblock documentation.

I think "function call" would work here (rather than "function calling")?

I changed "function calling arguments" to "function arguments" to make it less verbose.

Oops I fixed the wrong case of "Login" to "Log in" :p And a typo

Believe the feedback has been addressed

The Needs Review Queue Bot tested this issue.

While you are making the above changes, we recommend that you convert this patch to a merge request. Merge requests are preferred over patches. Be sure to hide the old patch files as well. (Converting an issue to a merge request without other contributions to the issue will not receive credit.)

Thanks @mfb; the explanation in #69 is helpful.

Regarding the permissions, I verified that the permission required for dblog pages is access site reports, which is already a restricted access permission, so that's fine.

That said, I noticed there's outstanding feedback from @alexpott that has not been addressed it. It was recommended to only add backtraces for critical messages to avoid blowing up the logs. I can see the value in wanting to have backtraces for non-critical messages; however, I agree with the log size concern also. Maybe a (non-UI) configuration setting would be helpful here? Tagging for framework manager review once we get a proposed solution.

Meanwhile, a couple nitpicks escaped the cleanups above:

1. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -142,6 +142,35 @@ public function testLogEventPage() {
   +  public function testOnError() {
   

   This is missing a return typehint.

2. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -142,6 +142,35 @@ public function testLogEventPage() {
   +    // Log in the admin user.
   

   Also still missing the word "as".

3. +++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
   @@ -142,6 +142,35 @@ public function testLogEventPage() {
   +    // Load details page for the most recent event logged by the "php" logger.
   

   Still missing the word "the".

@xjm This version of the patch is the response to @alexpott's concern. At this point there should not be cause for concern about log size, as we decided to display the @backtrace_string that dblog has already been storing in the variables database column this whole time (it just was not being displayed in these cases).

So there is no size increase here. There is an increase of information available in the UI, but it's helpfully in its own table row, down at the bottom of the page.

Any code doing logging always has the option of removing the @backtrace_string from the context array if it will not be helpful. But I'm not aware of any places where we should do that at this time.

Fixed up those nitpicks

@xjm @alexpott Looking at core/lib/Drupal/Core/EventSubscriber/ExceptionLoggingSubscriber.php I do see one place where we could consider removing @backtrace_string from the context array: The ExceptionLoggingSubscriber::onClientError() method.

It's already removed in the ExceptionLoggingSubscriber::on403() method.

This would clean up the UI by removing the backtrace for miscellaneous 4xx errors (e.g. \Symfony\Component\HttpKernel\Exception\UnsupportedMediaTypeHttpException) logged by this mechanism, and would reduce storage size of dblog module going forward, for sites that have been getting lots of non-404/403 4xx errors.

Could also be decided in a followup if we're not sure.

The @backtrace_string was removed for 403 errors in #3167390: ExceptionLoggingSubscriber should not log backtrace string on access denied exceptions. Looks like there was no discussion at that time re: whether or not it'd be a good idea to remove for other 4xx errors.

Think this would be a nice feature to have for 10.2.

#75 mentions we could do more in a follow up potentially.

The fix in #74 looks great. It's not adding storing anything new - it's just surfacing information we already have - nice. And the follow-ups to consider removing where it is not helpful are great too.

Thanks @alexpott.

Let's add an additional followup for #75 and then I think this is ready to go.

Opened #3402173: Remove @backtrace_string in ExceptionLoggingSubscriber::onClientError()

Opened follow up for everyone.

Ah @longwave beat me. I'll close mine out.

Saving credits.

+++ b/core/modules/system/tests/modules/error_test/src/Controller/ErrorTestController.php
@@ -68,9 +68,17 @@ public function generateFatals() {
+    ini_set('zend.exception_ignore_args', FALSE);
+    ini_set('zend.exception_string_param_max_len', 1024);

I had a brief moment of concern that this could pollute other tests. What we usually do is save the existing settings and restore them after the test has run.

However, since this is in the test module rather than the test itself, it's maybe altering the child site PHP settings rather than the parent site settings. Maybe? I do not actually know if the PHP settings are shared between the test runner and test child site or not. We have no other examples of adjusting the ini settings in a test module. I'll ask. Leaving RTBC since this might be fine.

Per @longwave:

for functional tests it should only be for the duration of the page loaded under test, as they are done through http and ini_set() only lasts for the request

different story in kernel tests or if it was in the test method for some reason

So we should be all good here.

Alright, finally committed to 11.x and 10.2.x as a UI change. Also published the change record. Thanks everyone for your dedicated work on this!

The later patches only work when using dblog. We try not to use this because of the database writes. We will use syslog or jsonlog. So patch #19 would work best for us.

Amending attribution.