Fix double-escaping due to Twig autoescape in dblog event "operations"

Attached a test-only patch and a fix+test patch.

Test-only patch failed, so that looks good.

Looks good, maybe make the generateLogEntries() easier to read by having a $default log message and allow the caller to override options at call-time? Especially in the case of verifyLinkEscaping() where you only need to override the link paramater.

generateLogEntries(1, array(
  'message' => 'test message',
  'link' => l('View', 'node/1'),
));

New patch. Replaced the hardcoded link by a call to l(), gave the generateLogEntries() function an $options array paramater and updated all calls to use the new format.

I'm currently reviewing it.
Hope everything works fine.

It's been tested and seems legit!
The patch did solved the problem.

I'm on reroll now since the patch seems outdated at the moment.

Fixed a minor coding standard issue in the patch.

The l() function was deprecated recently and those references need to be changed.

In #13 you changed in function eventDetails() from
$dblog->link
to
SafeMarkup::set($dblog->link)

So basically you say everything someone passes as link is safe.
When I call it with something like
<a href="http://drupal.org">drupal</a><script>alert("hi there");</script>
the Javascript will get passed unchanged to the page and execute (see attached image).

In overview() we use
Xss::filter($dblog->link)
so I think it's better to apply it here too.

One could argue that a module should make sure, what it passes into the Logger, but I do not think so.
Anyway we should either use SafeMarkup or Xss::filter in both eventDetails() and overview().

Working on a patch...

Hello Guys,

I just had a go on the patch. Here is what I modified.

1. Instead of directly using SafeMarkup::set() I've added a check to validate if the event URL is safe or not with SafeMarkup::isSafe(). If it's not that safe then used Xss::filterAdmin() (since its an admin page) to sanitize it properly.
2. The previous test patch was failing due to call to l() function. This should be _l()
3. As suggested by @mradcliffe, l() function is deprecated so I've used the URL generation API

1. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -238,6 +239,13 @@ public function eventDetails($event_id) {
   +      if (!SafeMarkup::isSafe($dblog->link)) {
   

   I like this use of SafeMarkup. NIce. +1.

2. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -123,20 +125,18 @@ private function verifyCron($row_limit) {
   +   *   (optional) An array of options that override the default values.
   

   It's a private function, but maybe a core developer would want to know what the options are.

   Maybe:

     (optional) An array options that override the default values:
     - type: etc...
     - severity: etc...
   

Test failed but the code seems to work properly in local installations. However, have to check the test cases.

Some issues fixed with SafeMarkup checks. Also, when used Url::fromUri($dblog->referer), if the value $dblog->referer is not set then an error was triggering. Like,

[04-Oct-2014 16:55:16 UTC] Uncaught PHP Exception InvalidArgumentException: "You must use a valid URI scheme. Use base:// for a path, e.g., to a Drupal file that needs the base path. Do not use this for internal paths controlled by Drupal." at /var/lib/drupaltestbot/sites/default/files/checkout/core/lib/Drupal/Core/Url.php line 206 

So added an empty check.

Uploading a new patch and marking for review. Keeping fingers crossed. :-)

reviewing

applied patch 22
The code make sense and is working as intended.
before

after

updating image

We have tests and we have a patch.

What the?? The patch was passed initially and now how its failing? Any ideas?

The patch no longer applies to HEAD. The next step is to re-roll the patch after fetching and merging the latest changes from HEAD - https://www.drupal.org/patch/reroll

The patch no longer applies cleanly to the codebase. See https://www.drupal.org/patch/reroll for instructions on rerolling it.

Thanks guys.

I'll have a look at this tonight.

I rerolled the patch.

I think we should not only test for displaying of the link,
but also for checking XSS, so I added tests for that.

Other than that, I also sorted the use-statements alphabetically.

Sorry, there we're some misplaced spaces left.
Other than that #39 is the same as #38.

Also forgot to mark it "needs review"... ;)

Thanks @gngn for this patch. Lets make it RTBC.

I tested #39 and it works as expected.

I think I accidentally changed the status to needs work... setting it back to needs review...

+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -123,20 +126,18 @@ private function verifyCron($row_limit) {
-  private function generateLogEntries($count, $type = 'custom', $severity = WATCHDOG_NOTICE) {
+  private function generateLogEntries($count, $options = array()) {

Why is there an API change here? Is this necessary or out of scope of this issue?

I know it's easy to fall victim to cleaning up all of the files, but it can muddy the waters for a reviewer to try to determine what parts of the code were fixing the the problem and which parts are just nice to have clean-ups. And also provide bikeshed fodder. So be warned:P

The parameters of generateLogEntries() were changed because we needed to set not only type (aka channel) and severity, but also the link.
The new version allows to change every parameter by passing an array of a options (and provides defaults).
We could have added just one new parameter:

private function generateLogEntries($count, $type = 'custom', $severity = WATCHDOG_NOTICE, $link = '')

but I think it's better to allow overriding all parameters.
This way if we need more settings in future test cases, we do not need to change the API again and again.

This isn't an API change either way. That is a *private* method of a test. It cannot be overridden by subclasses.

Probably shouldn't say API change there, meant function definition.

Trying to prevent scope creep, that's all. Anyways seems like you have it sorted and thought out. Carry on...

The patch in #39 is working alright. It just needed reroll.

The change to the generateLogEntries function signature was removed between #38 and #39.
So a new patch should be created, based on #52, but with this change added:
- private function generateLogEntries($count, $type = 'custom', $severity = WATCHDOG_NOTICE) {
+ private function generateLogEntries($count, $options = array()) {

Maybe someone should check if other stuff also went missing by doing a diff between the patches.

@Yaron Tal I did not found much difference between #38 and #39. Interdiff attached.

I hope this one will pass the test.

It would be good if we do not use l() function, it is deprecated.

This patch uses \Drupal::l()

1. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -254,11 +262,11 @@ public function eventDetails($event_id) {
   -          $this->l($dblog->location, $dblog->location ? Url::fromUri('base://' . $dblog->location) : Url::fromRoute('<none>')),
   +          \Drupal::l($dblog->location, (!empty($dblog->location) ? Url::fromUri($dblog->location) : new Url('<front>'))),
   ...
   -          $this->l($dblog->referer, $dblog->referer ? Url::fromUri('base://' . $dblog->referer) : Url::fromRoute('<none>')),
   +          \Drupal::l($dblog->referer, (!empty($dblog->referer) ? Url::fromUri($dblog->referer) : new Url('<front>'))),
   

   These changes are wrong, $this->l() is preferred over \Drupal::l()

2. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -147,11 +147,19 @@ private function generateLogEntries($count, $type = 'custom', $severity = RfcLog
   +        $this->container->get('logger.dblog')
   ...
   +      $this->container->get('logger.dblog')
   

   I'd do $logger = $this->container->get('logger.dblog'); outside this code block. The first one is in a loop, it's a waste of get() calls.

3. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -243,6 +251,43 @@ public function verifySort($sort = 'asc', $order = 'Date') {
   +  private function verifyLinkEscaping() {
   

   Please use protected (I know the other method uses private, but fixing that is out of scope here)

@tim.plunkett Could you please explain why the l() function changes are wrong. I see that l() has been deprecated in 8 (Deprecated)

I think I can answer that. By using the internal method instead of the global static method the object is easier to unit test.
Because the object is self-contained with its dependencies injected.

The same applies for the \Drupal::t() method vs $this->t()

Does that help? I'm sure Tim can elaborate if I missed something or needs further clarification.

Thanks that helps :) And here is the patch with suggestions from Tim in #61

Patch no longer applies, tagging for reroll.

RTBC +1 for #68

Re-rolled.

Re-rolled.

Its not working anymore

@subhojit777, I'm not able to reproduce what you got, actually the double-scaping just occurs in the operation detail

@gvso I was installing some modules (xmlsitemap, extlink) and they were not installing cleanly in my Drupal 8 instance. Message details is double escaped, I think we should fix it in this issue only.

Using the same logic as used in event link.

Sending to testbots

I could apply the patch, so no reroll is needed.

Using the same test logic as used for link.

Attached patch includes the patch from #2409881-1: Exception log messages are double-escaped when viewing a single entry to fix the failing test.

Re rolling patch to apply cleanly at ce199a1 with improvements for coding style.

+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -44,11 +44,19 @@ class DbLogTest extends WebTestBase {
+      'administer users'));

If you are using multi-line array style, the closing braces should appear in next line.

Tests have been added, hence removing the tag

Changes look good! I have added a test-only version to verify the tests failures.

The patch fixes the display and includes tests to make sure the markup is escaped. Looks RTBC to me :)

I have updated the issue summary with a beta evaluation to reflect this is a bugfix.

Testbot hickup? I didn't have an opportunity to have a look at the test report, but since it comes back green I take it everything is all good.

+++ b/core/modules/dblog/src/Controller/DbLogController.php
@@ -240,6 +240,22 @@ public function eventDetails($event_id) {
+        $event_link = SafeMarkup::set($dblog->link);

  /**
   * Adds a string to a list of strings marked as secure.
   *
   * This method is for internal use. Do not use it to prevent escaping of
   * markup; instead, use the appropriate
   * @link sanitization sanitization functions @endlink or the
   * @link theme_render theme and render systems @endlink so that the output
   * can be themed, escaped, and altered properly.

^^ is the documentation from SafeMarkup::set(). I think we need another solution here.

I suppose there is no need to call that function there, since the markup is already considered safe.

Patch looks good, and it fixes the problem. Patch includes all changes asked in #95. Tests included. Marking it as RTBC.

There is a tonne of unrelated change in this patch

1. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -255,11 +268,11 @@ public function eventDetails($event_id) {
   -          $this->l($dblog->location, $dblog->location ? Url::fromUri($dblog->location) : Url::fromRoute('<none>')),
   +          $this->l($dblog->location, (!empty($dblog->location) ? Url::fromUri($dblog->location) : new Url('<front>'))),
   ...
   -          $this->l($dblog->referer, $dblog->referer ? Url::fromUri($dblog->referer) : Url::fromRoute('<none>')),
   +          $this->l($dblog->referer, (!empty($dblog->referer) ? Url::fromUri($dblog->referer) : new Url('<front>'))),
   

   Why the change to ?

2. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -299,7 +312,7 @@ public function eventDetails($event_id) {
   -      return;
   +      return NULL;
   

   Why?

3. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -329,7 +342,7 @@ protected function buildFilterQuery() {
   -   * @param stdClass $row
   +   * @param \stdClass $row
   

   unrelated

4. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -50,7 +52,12 @@ protected function setUp() {
   -    $this->adminUser = $this->drupalCreateUser(array('administer site configuration', 'access administration pages', 'access site reports', 'administer users'));
   +    $this->adminUser = $this->drupalCreateUser(array(
   +      'administer site configuration',
   +      'access administration pages',
   +      'access site reports',
   +      'administer users',
   +    ));
   
   @@ -61,7 +68,7 @@ protected function setUp() {
   -  function testDbLog() {
   +  public function testDbLog() {
   
   @@ -240,13 +253,89 @@ private function verifyEvents() {
   -  public function verifySort($sort = 'asc', $order = 'Date') {
   +  protected function verifySort($sort = 'asc', $order = 'Date') {
   
   @@ -338,7 +427,11 @@ private function doUser() {
   -    $perm = array('create ' . $type . ' content', 'edit own ' . $type . ' content', 'delete own ' . $type . ' content');
   +    $perm = array(
   +      'create ' . $type . ' content',
   +      'edit own ' . $type . ' content',
   +      'delete own ' . $type . ' content',
   +    );
   
   @@ -497,7 +590,10 @@ protected function testFilter() {
   -        $this->generateLogEntries($type['count'], $type['type'], $type['severity']);
   +        $this->generateLogEntries($type['count'], array(
   +          'channel' => $type['type'],
   +          'severity' => $type['severity'],
   +        ));
   

   Unrelated

5. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -129,21 +138,18 @@ private function verifyCron($row_limit) {
       * @param int $count
       *   Number of watchdog entries to generate.
   -   * @param string $type
   -   *   (optional) The type of watchdog entry. Defaults to 'custom'.
   -   * @param int $severity
   -   *   (optional) The severity of the watchdog entry. Defaults to
   -   *   \Drupal\Core\Logger\RfcLogLevel::NOTICE.
   +   * @param array $options
   +   *   (optional) An array of options that override the default values.
       */
   -  private function generateLogEntries($count, $type = 'custom', $severity = RfcLogLevel::NOTICE) {
   +  private function generateLogEntries($count, $options = array()) {
        global $base_root;
    
   -    // Prepare the fields to be logged
   -    $log = array(
   -      'channel'     => $type,
   -      'message'     => 'Log entry added to test the dblog row limit.',
   +    // Prepare the fields to be logged.
   +    $log = $options + array(
   +      'channel'     => 'system',
   +      'message'     => 'Dblog test log message',
          'variables'   => array(),
   -      'severity'    => $severity,
   +      'severity'    => RfcLogLevel::NOTICE,
          'link'        => NULL,
          'user'        => $this->adminUser,
          'uid'         => $this->adminUser->id(),
   @@ -151,11 +157,18 @@ private function generateLogEntries($count, $type = 'custom', $severity = RfcLog
   
   @@ -151,11 +157,18 @@ private function generateLogEntries($count, $type = 'custom', $severity = RfcLog
          'referer'     => \Drupal::request()->server->get('HTTP_REFERER'),
          'ip'          => '127.0.0.1',
          'timestamp'   => REQUEST_TIME,
   -      );
   -    $message = 'Log entry added to test the dblog row limit. Entry #';
   -    for ($i = 0; $i < $count; $i++) {
   -      $log['message'] = $message . $i;
   -      $this->container->get('logger.dblog')->log($severity, $log['message'], $log);
   +    );
   +
   +    $logger = $this->container->get('logger.dblog');
   +    if ($count > 1) {
   +      $row_message = $log['message'] . ' Entry #';
   +      for ($i = 0; $i < $count; $i++) {
   +        $log['message'] = $row_message . $i;
   +        $logger->log($log['severity'], $log['message'], $log);
   +      }
   +    }
   +    else {
   +      $logger->log($log['severity'], $log['message'], $log);
        }
      }
   

   Why are we changing this?

6. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -240,6 +240,19 @@ public function eventDetails($event_id) {
   +      // Validate the message if it is safe.
   +      if (!SafeMarkup::isSafe($message)) {
   +        $message = Xss::filterAdmin($message);
   +      }
   
   @@ -352,7 +365,7 @@ public function formatMessage($row) {
   +    return ($message) ? Xss::filterAdmin($message) : FALSE;
   

   We're always filtering in the formatMessage() so this will always be safe.

Removed unrelated changes as per #99

We still need to keep the fix from #2409881: Exception log messages are double-escaped when viewing a single entry. I've also removed a couple of unrelated changes.

Credit should be give to @joelpittet in the commit.

From comment #99, we infact need some changes to fix the bug.

This issue is to fix html escape bug in dblog events (messages, links). The previous generateLogEntries() did not covered custom dblog message and links. Therefore we need this change #99.5. And due to this we also have to change testFilter() (as mentioned in last part of #99.4)

I hope other queries in #99 has been covered.

Comments in #99 have been addressed,
There are tests in the patch and they pass,
Fixes the escaping issue.

1. +++ b/core/modules/dblog/src/Controller/DbLogController.php
   @@ -240,6 +241,14 @@ public function eventDetails($event_id) {
   +      // Validate the event link if it is safe.
   +      if (!SafeMarkup::isSafe($dblog->link)) {
   +        $event_link = Xss::filterAdmin($dblog->link);
   +      }
   +      else {
   +        $event_link = $dblog->link;
   +      }
   
   @@ -275,7 +284,7 @@ public function eventDetails($event_id) {
   -          $dblog->link,
   +          $event_link,
   

   Can use $event_link = SafeMarkup::checkAdminXss($dblog->link); here instead of all of this. Perhaps can just remove the $event_link variable completely.

2. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -129,21 +133,18 @@ private function verifyCron($row_limit) {
   +   * @param array $options
   +   *   (optional) An array of options that override the default values.
   

   The new $options parameter should have documentation about the defaults and possible options.

3. +++ b/core/modules/dblog/src/Tests/DbLogTest.php
   @@ -151,11 +152,18 @@ private function generateLogEntries($count, $type = 'custom', $severity = RfcLog
   +    $logger = $this->container->get('logger.dblog');
   +    if ($count > 1) {
   +      $message = $log['message'] . ' Entry #';
   +      for ($i = 0; $i < $count; $i++) {
   +        $log['message'] = $message . $i;
   +        $logger->log($log['severity'], $log['message'], $log);
   +      }
   +    }
   +    else {
   +      $logger->log($log['severity'], $log['message'], $log);
        }
   

   This looks a bit painful. Is the if ($count > 1) { actually necessary?

Took the suggestions from @alexpott and made the changes to the patch.
Re-tested, appears to fix the problem, and it simpler.
The descriptions in the options array might need some tweaking.
My first issue update for core, let me know if I've made any mistakes please.

+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -129,21 +133,33 @@ private function verifyCron($row_limit) {
+   *   - 'link': String linking to view the result of the event
+   *   - 'user': String identifying the username
+   *   - 'uid': Int identifying the user id for the user
...
+   *   - 'referer': String identifying the referring url
+   *   - 'ip': String The ip address of the client machine triggering the log
...
+   *   - 'timestamp': Int unix timestamp

Use sentences - missing period.

Added periods to sentences in options section

I have confirmed that the patch applies cleanly on head and that it resolves the problem, and also that it follows coding standards.

This issue addresses a major bug and is allowed per https://www.drupal.org/core/beta-changes. Committed 630edf8 and pushed to 8.0.x. Thanks!

+++ b/core/modules/dblog/src/Controller/DbLogController.php
@@ -354,7 +354,7 @@ public function formatMessage($row) {
-    return $message;
+    return ($message) ? Xss::filterAdmin($message) : FALSE;

+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -247,6 +265,82 @@ public function verifySort($sort = 'asc', $order = 'Date') {
+    // Check for XSS filtering.
+    $js_txt = 'This should not pop up!';
+    $js = '<script>alert("' . $js_txt . '");</script>';
+    $this->generateLogEntries(1, array(
+      'message' => $message . $js,
+      'link' => $link,
+    ));

Done some more thinking about this change. I don't think it is correct. This is preventing someone from writing code like $logger->notice('<script>alert('blah')</script>'); - however this is does not need to be defended against. All user input should be passed to the message through the variables with the correct escaping strategy.

Xss filtering of the message and testing of same removed in updated patch & interdiff attached.

+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -71,6 +73,8 @@ function testDbLog() {
+    $this->verifyMessageEscaping();

@@ -247,6 +265,46 @@ public function verifySort($sort = 'asc', $order = 'Date') {
+  /**
+   * Test the escaping of message in the operation row of a database log detail
+   * page.
+   */
+  private function verifyMessageEscaping() {
+    $link = \Drupal::l('View', Url::fromRoute('entity.node.canonical', array('node' => 1)));
+    $message = String::format('%message', array(
+      '%message' => 'Log entry added to do the verifyMessageEscaping test.',
+    ));
+    $this->generateLogEntries(1, array(
+      'message' => $message,
+      'link' => $link,
+    ));
+
+    $result = db_query_range('SELECT wid FROM {watchdog} ORDER BY wid DESC', 0, 1);
+    $this->drupalGet('admin/reports/dblog/event/' . $result->fetchField());
+
+    // Check if the link exists (unescaped).
+    $this->assertRaw($message);
+  }

This is no longer needed.

Marked #2462133: Link in log message should not be escaped as a duplicate of this issue.

I could apply the patch, so no reroll is needed.

I removed two private functions because they were no longer called. Tested it again, still passed.
So now ready to be commited.

@Noe_ Thanks for working on this patch! If you make any changes to a patch, please set the status to 'Needs review' so it can be reviewed by fellow developers. More information on issue status can be found in the Issue queue handbook: https://www.drupal.org/node/156119.

It seems the private functions seem to be called by the Testbot, so here is the new patch.

@Noe_ @alexpott has asked to removed verifyMessageEscaping() in #119. Please correct the patch.

The verifyMessageEscaping() function is the only one that is removed now as @alexpott pointed out in #119

Forgot the interdiff.

That's another upload of #127 since testbot had some obvious problem last week.

Ok, just realized that you removed testDbLog() to get green test results - that's cool ;) but I guess it's not something we can do. I will work on it but will take #118 as a base since that was last patch with testDbLog()

Here is a patch based on #118 and suggestion from #119 which passes local tests. Let's try it against DrupalCI.

Ok
Since last patch is based on RTBC, and nothing, but Alex suggestion, were added, I'm bumping it back to RTBC

Committed 4b1714a and pushed to 8.0.x. Thanks!

Thanks for adding the beta evaluation.

diff --git a/core/modules/dblog/src/Tests/DbLogTest.php b/core/modules/dblog/src/Tests/DbLogTest.php
index 52e801f..7db1b16 100644
--- a/core/modules/dblog/src/Tests/DbLogTest.php
+++ b/core/modules/dblog/src/Tests/DbLogTest.php
@@ -7,7 +7,6 @@
 
 namespace Drupal\dblog\Tests;
 
-use Drupal\Component\Utility\String;
 use Drupal\Component\Utility\Unicode;
 use Drupal\Component\Utility\Xss;
 use Drupal\Core\Logger\RfcLogLevel;

Fixed unused use.