Log messages won't appear translated if they have special characters in them

@David_Rothstein, thank you for organizing the information and creating the issue.

I created a new patch for this issue. I revised some points from the previous patch #29 of #2459339: Log messages should be XSS filtered on display.

1. Changed the following line to avoid double escaping. For example, <script>alert('foo');</script> <strong>Lorem ipsum</strong> is shown as alert('foo'); <strong>Lorem ipsum</strong> in the detailed page table if we don't change this line.

@@ -267,7 +267,7 @@ public function eventDetails($event_id) {
         ),
         array(
           array('data' => $this->t('Message'), 'header' => TRUE),
-          $message,
+          array('data' => array('#markup' => $message)),
         ),
         array(
           array('data' => $this->t('Severity'), 'header' => TRUE),

2. Changed back the @return comment of the method formatMessage().

3. Splitted the test from the testOverviewLinks() and created a dedicated test case testLogEventPageMessageEscaped().

As for the point 1 above, I'm not confident that this approach is the best. I'd like someone to review this considering twig and table template.

I'msorry, the patch #5 doesn't consider David_Rothstein's guide in comment #36 on #2459339: Log messages should be XSS filtered on display.

What is the reason for making all those changes to the generateLogEntries() method in the tests? Since we're just trying to test a specific log message here, I would think having the new test call watchdog() directly would be better.

Surely, generateLogEntries() is not necessary to use here and I revised the test case to make it simpler.

Hmm, would the data => #markup change not always escape the thing with XSS::filterAdmin() again?

I think it would be better to always return a Markup object instead similar to how https://api.drupal.org/api/drupal/core%21lib%21Drupal%21Core%21Render%21... would do it.

@Fabianx, thank you for the review and assist.

I see. I changed the return value of formatMessage() to a Markup object. Surely it looks better.

And data => #markup was necessary to avoid double escape in the patch #6 but it's no longer needed after replacing the return value of formatMessage().

RTBC - looks good to me.

The auto test succeeded once and failed later with CI error. So I believe it's OK to make this status RTBC again.

Maybe this is related to #2749955: Random fails in UpdatePathTestBase tests

You can retest patches by clicking the "Add new test" link in tiny characters underneath the last test (not obvious, I know). :)

The CI error is actually a problem with the infrastructure itself, not random fails. So usually when that happens the patch should just be retested. Doing so now.

Thanks for working on this issue.

1. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -117,6 +117,32 @@ public function testLogEventPage() {
   +    // Make sure HTML tags are filtered out in admin/reports/dblog/event/ too.
   +    \Drupal::service('logger.dblog')->log(RfcLogLevel::NOTICE, "<script>alert('foo');</script> <strong>Lorem ipsum</strong>", $context);
   +    $wid = db_query('SELECT MAX(wid) FROM {watchdog}')->fetchField();
   +
   +    $this->drupalGet('admin/reports/dblog/event/' . $wid);
   +    $this->assertResponse(200);
   +    $this->assertNoRaw("<script>alert('foo');</script>");
   +    $this->assertRaw("alert('foo'); <strong>Lorem ipsum</strong>");
   
   @@ -769,13 +795,6 @@ public function testOverviewLinks() {
   -    // Make sure HTML tags are filtered out in admin/reports/dblog/event/ too.
   -    $this->generateLogEntries(1, ['message' => "<script>alert('foo');</script> <strong>Lorem ipsum</strong>"]);
   -    $wid = db_query('SELECT MAX(wid) FROM {watchdog}')->fetchField();
   -    $this->drupalGet('admin/reports/dblog/event/' . $wid);
   -    $this->assertNoRaw("<script>alert('foo');</script>");
   -    $this->assertRaw("alert('foo'); <strong>Lorem ipsum</strong>");
   

   Why are we moving almost exactly the same test from one place to the other, without adding anything? Unless I missed something, what this accomplishes is making testbot install the site an extra time with the same coverage. That said...

2. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -347,12 +348,13 @@ public function formatMessage($row) {
        if (isset($row->message) && isset($row->variables)) {
          // Messages without variables or user specified text.
          if ($row->variables === 'N;') {
   -        $message = Xss::filterAdmin($row->message);
   +        $message = $row->message;
          }
          // Message to translate with injected variables.
          else {
   -        $message = $this->t(Xss::filterAdmin($row->message), unserialize($row->variables));
   +        $message = $this->t($row->message, unserialize($row->variables));
          }
   +      $message = Markup::create(Xss::filterAdmin($message));
   

   So I guess that the idea here is that we want to XSS filter after the message is translated, rather than before.

   It still seems a bit overcomplicated and also (in HEAD as well) a misuse of t()... however, before I recommend changes, let's get some test coverage. If the bug is that the messages do not get translated when they are supposed to be, then let's add tests for that -- for messages that should be translated and would not be in HEAD. We would upload a failing test-only patch for the translation, and a passing combined one.

   Once the test coverage is fixed, then we can ensure that any changes we make to the code itself also do what they are supposed to.

Thanks!

@xjm, thank you for your detailed review and comments.

Why are we moving almost exactly the same test from one place to the other, without adding anything? Unless I missed something, what this accomplishes is making testbot install the site an extra time with the same coverage. That said...

As you saw, this doesn't change the coverage. We overused the method generateLogEntries() in the commit http://cgit.drupalcode.org/drupal/commit/?id=a2a4051 and we're going to fix that on D7 in #2459339: Log messages should be XSS filtered on display. I thought it's better to fix it also in D8 and that's why I changed the test without adding coverage. The comment https://www.drupal.org/node/2459339#comment-11363781 may be helpful.

So I guess that the idea here is that we want to XSS filter after the message is translated, rather than before.

It still seems a bit overcomplicated and also (in HEAD as well) a misuse of t()... however, before I recommend changes, let's get some test coverage. If the bug is that the messages do not get translated when they are supposed to be, then let's add tests for that -- for messages that should be translated and would not be in HEAD. We would upload a failing test-only patch for the translation, and a passing combined one.

Once the test coverage is fixed, then we can ensure that any changes we make to the code itself also do what they are supposed to.

I see. If I understand that, we should create a test to confirm there's a bug in HEAD, right.

As the first step, I tried creating a new test-only patch. It's a little complicated and I'd like to upload another patch with working code to compare the results.

I didn't understand the misuse of t() and I'll tackle that point later.

If my understanding is wrong or not enough, please tell me. Thank you.

Thanks! @hgoto

+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -117,6 +120,91 @@ public function testLogEventPage() {
+    \Drupal::service('logger.dblog')->log(RfcLogLevel::NOTICE, "<script>alert('foo');</script> <strong>Lorem ipsum</strong>", $context);

You can use ->notice().

+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -117,6 +120,91 @@ public function testLogEventPage() {
+    $translation_variables = ['@something' => 'foo'];

Could you use the 3 types of placeholders here? We have another issue that needs tests regarding this topic. #2617330: LogMessageParser::parseMessagePlaceholders() needs to switch bang placeholder to colon placeholder

+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -22,7 +25,7 @@ class DbLogTest extends WebTestBase {
+  public static $modules = array('dblog', 'node', 'forum', 'help', 'block', 'locale');

We need to use [] now.

@dagmar thank you. Following the review #19, I revised the patch with 3 points improved. I'd like this to be reviewed.

Could you use the 3 types of placeholders here? We have another issue that needs tests regarding this topic. #2617330: LogMessageParser::parseMessagePlaceholders() needs to switch bang placeholder to colon placeholder

I think the changes including the following is enough for that but if I don't understand it correctly, please let me know.

+    $translation_variables = [
+      '@one' => 'foo',
+      '%two' => 'bar',
+      ':three' => 'http://example.com',
+    ];
+

Tests in this patch needs the patch #2617330-2: LogMessageParser::parseMessagePlaceholders() needs to switch bang placeholder to colon placeholder committed in order to pass. (I tested it in my environment.)

Also, I'm sorry, I couldn't create an interdiff. Probably it's because the code around the patch changed since then.

@hgoto thanks. I marked #2617330: LogMessageParser::parseMessagePlaceholders() needs to switch bang placeholder to colon placeholder as a duplicate of this one.

Could you include the fix from #2617330 in your patch?

@dagmar thanks!

I merged the fix in #2617330 into the last patch. There was another log(RfcLogLevel::NOTICE, ...) left and I also replaced it to notice(...). Auto Tests should pass...

Great, green. Almost there.

1. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -117,6 +120,95 @@ public function testLogEventPage() {
   +      'timestamp' => REQUEST_TIME,
   

   I forgot this, the use of REQUEST_TIME is deprecated. https://www.drupal.org/node/2785211

2. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -823,13 +915,6 @@ public function testOverviewLinks() {
   -    // Make sure HTML tags are filtered out in admin/reports/dblog/event/ too.
   -    $this->generateLogEntries(1, ['message' => "<script>alert('foo');</script> <strong>Lorem ipsum</strong>"]);
   -    $wid = db_query('SELECT MAX(wid) FROM {watchdog}')->fetchField();
   -    $this->drupalGet('admin/reports/dblog/event/' . $wid);
   -    $this->assertNoRaw("<script>alert('foo');</script>");
   -    $this->assertRaw("alert('foo'); <strong>Lorem ipsum</strong>");
   

   I would prefer to keep this lines here. The patch is adding 'locale' module as a dependency, that we could abstract into a new test case in the future because it seems only necessary for the new test. Lets keep this 6 lines of code unmodified.

Great, green. Almost there.

1. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -117,6 +120,95 @@ public function testLogEventPage() {
   +      'timestamp' => REQUEST_TIME,
   

   I forgot this, the use of REQUEST_TIME is deprecated. https://www.drupal.org/node/2785211

2. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -823,13 +915,6 @@ public function testOverviewLinks() {
   -    // Make sure HTML tags are filtered out in admin/reports/dblog/event/ too.
   -    $this->generateLogEntries(1, ['message' => "<script>alert('foo');</script> <strong>Lorem ipsum</strong>"]);
   -    $wid = db_query('SELECT MAX(wid) FROM {watchdog}')->fetchField();
   -    $this->drupalGet('admin/reports/dblog/event/' . $wid);
   -    $this->assertNoRaw("<script>alert('foo');</script>");
   -    $this->assertRaw("alert('foo'); <strong>Lorem ipsum</strong>");
   

   I would prefer to keep this lines here. The patch is adding 'locale' module as a dependency, that we could abstract into a new test case in the future because it seems only necessary for the new test. Lets keep this 6 lines of code unmodified.

Updated patch as per comment #27 & also added interdiff.

@dagmar thank you for your review.

1. Thank you. I didn't notice that. So I believe it's better to replace all REQUEST_TIME in this file, right?

2. That test is covered in testLogEventPageMessageEscaped() and we can remove it. The test method name is testOverviewLinks() and these lines shouldn't be there originally, I think. Please see comment #13 and #14. (If we keep it, it's better to change the method name, isn't it?)

1. Thank you. I didn't notice that. So I believe it's better to replace all REQUEST_TIME in this file, right?

Lets skip the replacement of REQUEST_TIME for now, several other issues has shown this change is not required as part of this patch.

2. That test is covered in testLogEventPageMessageEscaped() and we can remove it. The test method name is testOverviewLinks() and these lines shouldn't be there originally, I think. Please see comment #13 and #14. (If we keep it, it's better to change the method name, isn't it?)

I guess you are right. #29 claims it included in the interdiff but actually that's not true.

So the remaining thing for this patch is, rollaback the REQUEST_TIME related changes. and see if the testbot still pass. This will probably need a reroll. Tagging as novice since the remaining changes seems quite simple to implement.

Modified the patch as per comment #33 & also this patch failed to apply on 8.5.x branch because of "core/modules/dblog/src/Tests/DbLogTest.php" changed to "core/modules/dblog/tests/src/Functional/DbLogTest.php".

Cool, Thanks @Yogesh Pawar!

There is one more thing I would like to see in the test coverage. According to this #2952091: Show translatable db log message on the main view, the logs messages are not translated in views. So adding the same checkes that we have now for detail page logs in the logs view should expose the failure.

The approach then could be, take this portion of code and abstract it into a protected method (perhaps assertTranslations?)

+++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
@@ -118,6 +121,95 @@ public function testLogEventPage() {
+
+    $source_unfiltered = new FormattableMarkup($text_source, $translation_variables);
+    $source_filtered = Xss::filterAdmin(new FormattableMarkup($text_source, $translation_variables));
+    $translation_unfiltered = new FormattableMarkup($text_translation, $translation_variables);
+    $translation_filtered = Xss::filterAdmin(new FormattableMarkup($text_translation, $translation_variables));
+
+    $this->assertNoRaw($source_unfiltered);
+    $this->assertNoRaw($source_filtered);
+    $this->assertNoRaw($translation_unfiltered);
+    $this->assertRaw($translation_filtered);

And then use it twice, one for

+    // Make sure HTML tags are filtered out after translation.
+    $this->drupalGet('admin/reports/dblog/event/' . $wid);
+    $this->assertResponse(200);

and other for

+    // Make sure HTML tags are filtered out after translation.
+    $this->drupalGet('admin/reports/dblog/');
+    $this->assertResponse(200);

Hopefully this will fail only for views.

Changes addressed as per comment #36, also added an interdiff.

only reroll path #39 for 8.6.x

Thanks for the patches. I'm afraid my comments in #36 were not addressed properly.

An assert* method should assert "something", and currently is returning a FormattableMarkup which is not ideal.

The approach then could be, take this portion of code and abstract it into a protected method

So more code should be inside the new method and should run the same assertions.

Let me know if there is something else to explain there, I will be glad to help.

Thanks @dagmar, As per my understanding i have updated a patch. Can you please look into the patch & tell me what i am missing or is it good to go.

+++ b/core/modules/dblog/tests/src/Functional/DbLogTest.php
@@ -118,6 +121,98 @@ public function testLogEventPage() {
+  /**
+   * Returns FormattableMarkup object.
+   */
+  protected function assertTranslations($text_source, $translation_variables) {
+    $this->assertNoRaw(Xss::filterAdmin(new FormattableMarkup($text_source, $translation_variables)));
+  }
+

As I mentioned in #36. I think the assertTranslations method should make this assertions:

$this->assertNoRaw($source_unfiltered);
$this->assertNoRaw($source_filtered);
$this->assertNoRaw($translation_unfiltered);
$this->assertRaw($translation_filtered);

And the assertTranslations should be ran twice, one for a single event admin/reports/dblog/1234 and other for the full list admin/reports/dblog

This Patch should solve the purpose

Thanks @gawaksh.

I recommend you start applying the patch from #47 and make the modifications from there. You introduced some syntax errors in your patch and removed some useful function docs.

Hi,
here is a patch simply rerolling #47 as it doesn't apply no more.

Hi,
and here is a new patch based on #53 to adress #48
Thanks

Since patch #54 failed for 9.1.x so I re-rolled the patch for the same.

patch after resolving the error

Re-roll patch for 9.2

Please ignore

Previous issues were fixed.

Fixed #68 test cases.

Tagging for Florida DrupalCamp which is happening today, Feb 10, 12-4pm ET

Thanks

Tested successfully on Drupal 9.3 (see #69).

Reviewed the issue summary and reviewed the patch.

All looks correct, RTBC

+++ b/core/lib/Drupal/Core/Logger/LogMessageParser.php
@@ -29,8 +29,8 @@ public function parseMessagePlaceholders(&$message, array &$context) {
+        // The key is now in \Drupal\Component\Utility\SafeMarkup::format() style.

nit: this needs to break at 80 chars

Other than that, this looks good to me

Patch with fixes on #73

@RenatoG thanks for your patch. There is an extra file in the patch that doesnt seems related to this issue.

diff --git a/core/modules/datetime_range/datetime_range.install b/core/modules/datetime_range/datetime_range.install
new file mode 100644
index 0000000000..e69de29bb2

Addressed #75

Thanks @KapilV patch looks good now.

Setting back to RTBC.
The test failure in #79 was a glitch; re-run of test (see #76) passed.

1. +++ b/core/lib/Drupal/Core/Logger/LogMessageParser.php
   @@ -29,8 +29,9 @@ public function parseMessagePlaceholders(&$message, array &$context) {
   -      if (!empty($key) && ($key[0] === '@' || $key[0] === '%' || $key[0] === '!')) {
   -        // The key is now in \Drupal\Component\Render\FormattableMarkup style.
   +      if (!empty($key) && ($key[0] === '@' || $key[0] === '%' || $key[0] === ':')) {
   +        // The key is now in \Drupal\Component\Utility\SafeMarkup::format()
   +        // style.
   

   The change is functionally correct but the comment change is incorrect.

2. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -379,8 +380,9 @@ public function formatMessage($row) {
   +      $message = Markup::create(Xss::filterAdmin($message));
   

   Instead of doing this here we could use the render system and do

     [
       '#markup' => $message
     ]
   

   in \Drupal\dblog\Controller\DbLogController::topLogMessages() and \Drupal\dblog\Controller\DbLogController::eventDetails()

   That'd save us a Markup::create() and preserve the return type and do the admin XSS filtering consistently.

   Alternatively I think we might be able to remove it entirely as HTML in the messages apart from the

    for the backtrace is pretty meh - and auto-escape will then kick in and do what we want.
   

Done with the changes mentioned in #81.1 ad #81.2, Please have a look and advise, if it is in the right direction.

Fixed custom command fail issue.

Rerolled #83 for 9.5.x

Cleaned up some of the file displays for this ticket also

Tried adding an interdiff but some reason it failed to generate but I did tweak DbLogController.php line 442 to use

$rows[] = [$dblog->count, $message];

vs $rows[] = [$dblog->count, ['#markup' => $message]];

The latter was preventing messages from appearing on the page not found page

Fixed CI failure

Patch applied successfully, but the log messages are still not translated. attaching screenshots below.

Please ignore patches #90, #89, and #87 I introduced some out of scope changes.

@Anjali Rathod thanks for testing. For next time it's not necessary to upload a screenshot of the patch applying.
Also please rename the screenshots to be more meaningful for what it's displaying.

So going back to #83 I rerolled and applied some tweaks.

This will need an IS update. Specifically
What is being fixed?
What is the proposed solution?
Step to reproduce?
before/after screenshots.
Remaining tasks.

Got it started

Adding reroll for 10.1.x.
please review

Reuploading the previous patch after removing unnecessary whitespaces

Issue summary is full of todos which need to be addressed

This is likely the right place for me to post this.

As a followup to #2909805: LogMessageParser breaks messages containing braces, I'm attempting to add pretty printed JSON to the Drupal log, inside

{{
"foo": {{
   "bar": {{
        "baz"
      }}
   }}
}}

@trevorbradley that doesn't seem related to this issue, as far as I can tell. This issue has to do with the display of log entries by dblog module. Your issue has to do with LogMessageParser. Because of the fact that log messages/placeholders are "parsed" by LogMessageParser, json should be in the placeholders rather than part of the log message. Aside from being technically required, this makes more sense anyways, since json will typically be something that changes often, whereas messages are more like a generic, translatable template.

I will also take a look

I am removing the Novice tag from this issue because it requires proper security knowledge of using FormattableMarkup, Xss::filterAdmin, and Markup::create, and the patch size is too large.

I’m using this documentation as a source: https://www.drupal.org/community/contributor-guide/task/triage-novice-is...