Incorrect use of FormattableMarkup in logger messages

I just wanted to inform you that I have removed the use of FormattableMarkup in log messages and have instead passed the message as the first parameter and the parameters as the second. This change ensures a more consistent and efficient logging system. Let me know if there are any questions or concerns.

probably it needs some test or runtime assertion to catch it

It fails for 1 test, how to fix that?

Hi @royalpinto007!

I've added the string messages with parameters into $this->t() function. It seems like if we use it directly into the loggers, it will break the tests.

The logger methods should take an untranslated string as the first argument and the context array as the second argument; the untranslated string and context is stored, and translation is handled at display time, so the logs can be viewed in different languages.

Thanks @longwave for the feedback!

It seems like this approach is currently used in CKEditor5.

The only logger method that is not being passed the FormattableMarkup, is using it.

See: https://git.drupalcode.org/project/drupal/-/blob/9.5.0/core/modules/cked...

To give more context on this, I was debugging the test() in SmartDefaultSettingsTest class, and when we use the logger method passing the string as the first argument and the context as second, the context arguments are not being transformed into the string when they are being called in the tests.

This makes me think that by not using the FormattableMarkup, the messages are being stored in the watchdog table as untransformed strings. But I don't really understand why...

You are right @gxleano, the messages are stored as they are, without the replacements applied. See the "log" method here: https://api.drupal.org/api/drupal/core%21modules%21dblog%21src%21Logger%...
(->info(... ->warning(... ->error(... call the "log" method, ie: warning).

I think, in this case, the test might need to be updated too as part of this issue, as it assumes that the stored value in DB has the replacements, and that's not correct. The test checks the array entries "expected_db_logs" with the context already replaced.

So, the way I see it, the initial fix from @royalpinto007 was valid, but it also needed to have the tests updated. Maybe you want to give it a go @gxleano? Note that the "$this->t" commit will need to be reverted.

Thanks @fjgarlin for the feedback!

Sure, I will try to rework the "expected_db_logs" and revert $this->t() changes.

Woah, great catch! Looks like this is getting close 😊

I've updated the kernel test in order to do it compatible with the logger context.

I think the test cases should stay the same, otherwise we are losing coverage of the contextual values; the test should format the message and then check that the final string is as expected.

the test should format the message and then check that the final string is as expected.

@longwave - in this part of the test https://git.drupalcode.org/project/drupal/-/blob/8aaf79d53b2251e8bd3d9b2... we are storing the "message" column as it is in the database, without replacements.

Wouldn't it make sense to compare the same thing (aka without the replacements applied) in the tests?

Otherwise, I guess we'd need to apply the replacements in those lines (getting the variables), and then leave the strings in the test unchanged. Is that the approach that you suggest?

Yes, I mean to apply the replacements - the select statement already reads the variables column, but then does nothing with it.

@longwave

I've tried to apply the replacements with the variables column, but there is a problem. The values coming from the variables column are different than the provided data in the test.

For instance:

• value coming from variables:
  

  Basic HTML
  

• expected value:
  

  <em class="placeholder">Basic HTML</em>
  

So, the test are trying to compare the next:

--- Expected
The CKEditor 5 migration enabled the following plugins to support tags that are allowed by the <em class="placeholder">Basic HTML</em> text format: <em class="placeholder">Code (for tags: &lt;code&gt;)</em>. The text format must be saved to make these changes active.

+++ Actual (With replacements applied)
The CKEditor 5 migration enabled the following plugins to support tags that are allowed by the Basic HTML text format: Code (for tags: <code>). The text format must be saved to make these changes active.

Which code are you using to do the replacements?

    $db_logged = $this
      ->database
      ->select('watchdog', 'w')
      ->fields('w', ['message', 'variables', 'severity'])
      ->condition('type', 'ckeditor5')
      ->orderBy('wid')
      ->execute()
      ->fetchAll();

    $type_to_status = [
      6 => 'status',
      4 => 'warning',
    ];
    $db_logs = [];
    foreach ($db_logged as $log) {
      $message = $log->message;
      $variables = unserialize($log->variables);
      foreach ($variables as $key => $value) {
        if (str_contains($message, $key)) {
          $message = str_replace($key, $value, $message);
        }
      }
      $db_logs[$type_to_status[$log->severity]][] = $message;
    }

But on my eyes, it seems to be normal, because of it is storing the format name, without html.

'%text_format' => $editor->getFilterFormat()->get('name'),

You don't need the foreach loop at all.

Try something like this better (not tested):

      $variables = unserialize($log->variables);
      $message = new FormattableMarkup($log->message, $variables);

You'll need to add use Drupal\Component\Render\FormattableMarkup; to the top of the test file.

% or @ have different meanings when replacing, and the class should take care of it, instead of doing a "str_replace".

Thanks @fjgarlin for the hint.

I've refactored this piece of code and test are passing now.

$variables = unserialize($log->variables);
$message = new FormattableMarkup($log->message, $variables);
$db_logs[$type_to_status[$log->severity]][] = (string) $message;

Great to hear that! Things are looking better and better.

You might need to change your editor autosaving/autoformatting to not change the other parts of the code that are not affected or relevant to the issue. Ideally, the MR should only reflect the changes needed to fix the issue for easier review, tho if all the tests are green I guess that's not a big deal. Not sure what's the policy for core MRs on this.

Is the (string) casting needed for the tests to pass? If it is it's fine.

I have reverted the unnecessary changes.

And yes, the casting (string) is necessary to make the test pass.

Awesome, tests are running as we type and the MR looks much cleaner now. Great work!

I checked the code and it all looks good, and also tested everything manually via Drupalpod as follows:
- I uninstalled ckeditor5, enabled ckeditor.
- Then installed again ckeditor5 and assigned it to a text format (to trigger all the logging messages).
- Went to the log messages section and the messages showed up as expected, with the replacements properly parsed.

See the two images below:

Marking this as RTBC.

Adjusting issue credit as credit is not provided for button-click rebases without additional contribution.