Prevent the use of placeholders that cannot be converted into strings when creating logs

Here's an attempt to follow the PSR-3 standard re: context data (see #83) by having LogMessageParser::parseMessagePlaceholders() ignore any non-stringable objects, arrays, etc. Dblog and syslog modules call this method to get the message placeholders, so hopefully with this change there should be less danger of invalid placeholders causing an exception to be thrown.

I didn't add extra logging, but if necessary we could have the LogMessageParser service log a notice in this scenario.

tried to fix failures in #89.

Looks good, and fixes a problem that otherwise it quite complicated to recover from (see the original issue description). However as is this patch will not apply to PHP 7.4 as Stringable is only PHP 8 available.

Updated issue summary to match logic in the most recent patches

Thanks, it is always good to see an old issue get to RTBC!

I'm triaging RTBC issues → . I re-read the IS and the comments. I didn't find any unanswered questions.

@mfb, thanks for updating the proposed resolution. That is very helpful.

However, the screenshot in the Issue Summary is for a previous version of the patch, with a different approach. It would help if that was removed.

I then read the patch, not a full review, and noticed these.

1. +++ b/core/lib/Drupal/Core/Logger/LogMessageParser.php
   @@ -29,7 +29,8 @@ public function parseMessagePlaceholders(&$message, array &$context) {
   +      if (!empty($key) && ($key[0] === '@' || $key[0] === '%' || $key[0] === ':') &&
   

   This is now fairly long and would benefit from a comment.

2. +++ b/core/modules/dblog/tests/src/Kernel/DbLogTest.php
   @@ -60,6 +60,21 @@ function (callable $hook, string $module) use (&$implementation_count) {
   +    $this->assertSame($variables, serialize(['@string' => '']));
   

   This has the actual result first and it should be the expected.

Because of the point about adding a comment I am tempted to move this to NW. However, even though it is a longish 'if' is it not complex. Therefor, I am leaving this a RTBC and I'll ping in #contribute to see if someone wants to complete the three items I mentioned. Be aware, that another committer may still choose to send this back for more work.

I just remembered I reviewed a patch today with a comment line too long. And here it is.

+++ b/core/tests/Drupal/Tests/Core/Logger/LogMessageParserTest.php
@@ -70,6 +71,41 @@ public function providerTestParseMessagePlaceholders() {
+      // Placeholders not convertible into strings that are not the first placeholder.

This should be fixed. I can do that now.

The last submitted patch, 94: 2481349-94.patch, failed testing. View results →

Addressed #93

@mfb, thanks for making those minor changes.

The failing test in #94 is unrelated. It was in

Drupal\Tests\Component\Utility\RandomTest::testRandomMachineNamesUniqueness
RuntimeException: Unable to generate a unique random machine name

.

Because the change I made was adding correct wrapping and I have reviewed that changes in #96, I am restoring the RTBC.

Restoring status per #97

The last submitted patch, 96: 2481349-96.patch, failed testing. View results →

Random test failure.

The last submitted patch, 96: 2481349-96.patch, failed testing. View results →

Random test failure.

Thanks everyone for finally identifying the root cause of this and referencing the PSR for best practices for a fix. I definitely agree that an exception or other error should not be thrown; the solution would be worse than the problem.

1. Could we get test-only versions to expose the coverage?

2. +++ b/core/lib/Drupal/Core/Logger/LogMessageParser.php
   @@ -29,8 +29,11 @@ public function parseMessagePlaceholders(&$message, array &$context) {
   +      if (!empty($key) && ($key[0] === '@' || $key[0] === '%' || $key[0] === ':') &&
   +        (is_scalar($variable) || is_null($variable) || $variable instanceof \Stringable)) {
   

   It seems kinda like the valid placeholder formats should be provided by the FormattableMarkup API and not hardcoded here. I realize the existing code has this problem as well, but maybe that's part of what led to this issue in the first place? It seems to me that we also don't allow these invalid data formats in FormattableMarkup, and there are plenty of situations where we don't want the rendering of a string to break the page.

   Ultimately, the code that acts on these placeholder values is FormattableMarkup::placeholderEscape():

   protected static function placeholderEscape($value) {
     return $value instanceof MarkupInterface ? (string) $value : Html::escape($value);
   }
   

   which calls:

   public static function escape($text) : string {
     if (is_null($text)) {
       @trigger_error('Passing NULL to ' . __METHOD__ . ' is deprecated in drupal:9.5.0 and will trigger a PHP error from drupal:11.0.0. Pass a string instead. See https://www.drupal.org/node/3318826', E_USER_DEPRECATED);
       return '';
     }
     return htmlspecialchars($text, ENT_QUOTES | ENT_SUBSTITUTE, 'UTF-8');
   }
   

   ...which throws a warning if passed a non-string on PHP 7, or a fatal on PHP 8 which typehints the argument.

   So, anything other than a string or MarkupInterface is invalid input, and it seems like FormattableMarkup should be handling that itself, possibly with a "safe" mode that silently replaces the placeholder with emptystring rather than fataling with a TypeError.

   Since this is a site-breaking bug, I'd be okay with scoping a better architecture to a followup, especially since half the problem is the existing code (and to some extent the existing switch statement "fun" of FormattableMarkup itself), so long as we file the followup and document it in the comments in this hunk.

3. +++ b/core/tests/Drupal/Tests/Core/Logger/LogMessageParserTest.php
   @@ -70,6 +71,42 @@ public function providerTestParseMessagePlaceholders() {
   +      // Placeholders convertible into a string.
   

   Our documentation standards specify that small words like "that" should not be omitted from inline documentation, so the comments on the data provider should probably be:

   • Placeholders that can be converted into a string.

   • Placeholders that cannot be converted to a string.

   • (Etc.)

   Also, I would use the phrase "can be converted" rather than "convertible" because the latter will make people think of cars and might be confusing to second-language speakers.

   All that said -- we've moved in the direction of using descriptive data provider array keys rather than inline comments in the provider, for easier debugging and clear test output. We retain inline comments for sitautions where the code is hard to read and a short phrase is not sufficient. So, the keys could be things like:

   • FormattableMarkup placeholder value
   • No placeholders but other context values
   • Plain array placeholder value
   • (Etc.)

4. +++ b/core/tests/Drupal/Tests/Core/Logger/LogMessageParserTest.php
   @@ -70,6 +71,42 @@ public function providerTestParseMessagePlaceholders() {
   +      // Placeholders not convertible into a string.
   +      [
   +        ['message' => 'array @a', 'context' => ['@a' => []]],
   +        ['message' => 'array @a', 'context' => []],
   +      ],
   +      // Placeholders not convertible into a string.
   +      [
   +        ['message' => 'object @b', 'context' => ['@b' => new \stdClass()]],
   +        ['message' => 'object @b', 'context' => []],
   

   These two cases have the same comment. It would be better for them to be distinct, maybe something like:

   Array placeholder values cannot be converted into a string.

   and:

   Classed objects that don't implement Formattable Markup cannot be converted into a string.

   This is especially important if we convert the data provider to having meaningful test case keys.

5. +++ b/core/lib/Drupal/Core/Logger/LogMessageParser.php
   @@ -29,8 +29,11 @@ public function parseMessagePlaceholders(&$message, array &$context) {
   +      // should be a string, number or \Stringable object.
   

   Nit: Missing Oxford comma after "number".

Since this is no longer displaying a message, I don't think it needs a usability review. (My guess is a usability review would have told us displaying messages about bad data in an obscure log message was bad UX.)

Thanks everyone!

Ok, I went ahead and converted the data provider to have test case keys. These all seem simple enough (to me) that just the descriptive key is good enough without a comment.

As far as followup work on what's a valid placeholder, the current status quo is that Drupal is not strict: Any \Stringable object can be used as a placeholder, not just \MarkupInterface objects. A real-world example would be a \Stringable Customer class; if you use an object of this class as a placeholder in a log message, then the object will be stored in the database (as serialized PHP) and such \Stringable objects, as well as integers and floats, will be happily cast to string when later rendering the log message.

If Html.php had declare(strict_types=1); at the top of the file, then this would not work. In this case, a \Stringable object, float or integer passed to Html::escape() would throw a TypeError when the non-string value is passed to htmlspecialchars(), which expects only a string, strictly speaking.

As someone who maintains two contrib logger modules, I don't really see a problem with the status quo - why not allow \Stringable objects to be used in various places, including logging. But certainly Drupal could decide to be more strict going forward, and either cast \Stringable-but-not-\MarkupInterface objects to string, or ignore them entirely.

Thanks @mfb; those fixes are perfect.

You are right about \Stringable -- basically replace FormattableMarkup with \Stringable throughout my comment when I reference it as a data type. So the followup scope would be to move this logic to FormattableMarkup (or whatever appropriate level of that API):

+++ b/core/lib/Drupal/Core/Logger/LogMessageParser.php
@@ -29,8 +29,11 @@ public function parseMessagePlaceholders(&$message, array &$context) {
+      if (!empty($key) && ($key[0] === '@' || $key[0] === '%' || $key[0] === ':') &&
+        (is_scalar($variable) || is_null($variable) || $variable instanceof \Stringable)) {

Might be two issues actually:

1. Internal refactoring of FormattableMarkup::placeholderFormat() to provide a list of valid key prefixes, which the logger could then use.
2. An issue there or somewhere in the render system to deal with non-stringable data types in a debuggable but non-page-breaking way.

Created a followup ✨ Unify logic for determining valid placeholder keys and values Active

The test-only patch is definitely not failing in the way I expect. I thought it was a fluke but requeued it and got the same result. 🤔 I don't get it.

@xjm idk but seems to work now 🤷

Believe the previous failures for

PHP Fatal error: Uncaught TypeError: Drupal\Core\Database\Transaction\TransactionManagerBase::removeStackItem(): Argument #1 ($id) must be of type string, int given, called in /var/www/html/core/lib/Drupal/Core/Database/Transaction/TransactionManagerBase.php on line 228 and defined in /var/www/html/core/lib/Drupal/Core/Database/Transaction/TransactionManagerBase.php:145

Were related to a break in HEAD last week, that was reverted.

This looks great now. Thanks also @mfb for the followup. One outstanding point of feedback (I thought of this during my first review, but somehow failed to post a comment about it):

+++ b/core/lib/Drupal/Core/Logger/LogMessageParser.php
@@ -29,8 +29,11 @@ public function parseMessagePlaceholders(&$message, array &$context) {
+      if (!empty($key) && ($key[0] === '@' || $key[0] === '%' || $key[0] === ':') &&
+        (is_scalar($variable) || is_null($variable) || $variable instanceof \Stringable)) {

I'm surprised that null would be an allowed value. Is the following really valid code?

$this->t(
  "The @placeholder that's null",
  ['@placeholder' => NULL]
);

What's the expected output? I suppose it's the most minimal change to the current functionality, but if we do decide to include the is_null() case as an allowed case, then we should have a test case for it.

(I have similar thoughts for Booleans, although those at least have a semi-meaningful output as 0 or 1. They should probably get test cases too.)

@xjm using NULL here is still allowed at the moment, but is deprecated. The silenced deprecation notice was added in #3255637: Deprecate NULL values in Html::escape(), ::decodeEntities(), and FormattableMarkup::placeholderFormat() to make it easier to upgrade to PHP 8 → . Therefore, I had to allow NULL in addition to scalar values for the time being. I wasn't sure it was worth adding a test, given that NULL was already deprecated, but we certainly could.

As far as TRUE and FALSE, those are /not/ deprecated yet. Probably a good idea to deprecate them, but that's out of scope of this issue. TRUE is cast to '1' and FALSE to empty string (like NULL), not '0'. Sure we could add a test case for those too, why not..

Addresses #110; also fixed the description of the last test case in previous patch, which wasn't quite right.

Appears feedback has been addressed.

Thanks @mfb; that makes total sense and the CR reference is helpful. It also explains why these do not raise deprecation errors yet.

+++ b/core/lib/Drupal/Core/Logger/LogMessageParser.php
@@ -31,7 +31,10 @@
+      // reasons, boolean and NULL placeholders are also allowed; NULL

+++ b/core/tests/Drupal/Tests/Core/Logger/LogMessageParserTest.php
@@ -87,10 +87,14 @@
+      'NULL and boolean placeholders are considered stringable' => [

Super-nit: "Boolean" is derived from a name and should be capitalized. (I can also fix this on commit.)

Shall we add a followup to decide whether Booleans should also be deprecated?

+++ b/core/lib/Drupal/Core/Logger/LogMessageParser.php
@@ -29,8 +29,14 @@ public function parseMessagePlaceholders(&$message, array &$context) {
+        (is_scalar($variable) || is_null($variable) || $variable instanceof \Stringable)) {

Dreditor ate a long comment, argh.

Something I didn't notice in previous reviews (sorry!) is that it's against our coding standards to have conditions mapped to multiple lines. It's better to define a couple local variables, e.g. $valid_prefix for the second condition, and $valid_data_type or something for the third. Then the condition becomes:

if (!empty($key) && $valid_placeholder && $valid_data_type) {

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 improvements is not recommended and will not receive credit.)

The casing thing is ultra-trivial but the change to the condition would need actual review, so NWed. If it were an MR I could have just used the suggestion feature to save us all time. :) We're recommending MRs now generally as patches are being phased out for core now.

@xjm My opinion is that a followup is out of scope of this issue. This issue is just about preventing the use of placeholders that cannot be coerced into strings because PHP throws a TypeError today, here and now, not about deciding what can or cannot be coerced into a string in the future (i.e. adding new deprecated warnings and TypeError situations).

I don't see a clear "need" for a followup from this issue because Drupal is basically following how PHP does things out of the box - certain things, like Stringable objects, numbers and even booleans are coerced to a string; coercing NULL to empty string triggers a deprecated warning; if you don't want any of this coercing to happen, you declare(strict_types=1) in your file and do your own casting.

Confused -- the exact point of followups is that they are out of scope on the issue. :)

@xjm I filed the one followup issue we found so far: ✨ Unify logic for determining valid placeholder keys and values Active , and I haven't seen any other unresolved issues that need a followup issue (yet).

@xjm In the MR I tried breaking that logic out to helper methods for hopefully improved readability, what do you think? (This does mean a couple extra function calls, so not perfect from a micro-optimization standpoint.)

p.s. more fun weird stuff you can unfortunately do with Booleans: TRUE / 4; strtr(TRUE, TRUE, FALSE); htmlspecialchars(TRUE) / FALSE; ok I lied about the last one, this throws a division by zero error :p

Believe the changes of breaking out looks fine. Agree easier to read. If reused a bunch maybe worth a trait?

We have the followup where helper methods/trait/etc. can be discussed further ✨ Unify logic for determining valid placeholder keys and values Active

The Needs Review Queue Bot → tested this issue. It no longer applies to Drupal core. Therefore, this issue status is now "Needs work".

This does not mean that the patch needs to be re-rolled or the MR rebased. Read the Issue Summary, the issue tags and the latest discussion here to determine what needs to be done.

Consult the Drupal Contributor Guide → to find step-by-step guides for working with issues.

Rebased

Rebase seems good

I'm triaging RTBC issues → . It is always a pleasure to review an older issue! I read the IS and the comments. I didn't find any unanswered questions or other work to do.

In #114, xjm asks if "we add a followup to decide whether Booleans should also be deprecated?" I am not sure that has been answered. There is already one followup but that issue does not cover this point, unless I am misunderstanding.

The introduction of two methods for the valid/invalid logic is different than the suggestion in #115 to use local variables. I don't think the logic is complex that new helper method are required. What about something like the following?

      // Valid keys are strings in \Drupal\Component\Render\FormattableMarkup
      // style.
      $valid_placeholder_key = is_string($key) && !empty($key) && ($key[0] === '@' || $key[0] === '%' || $key[0] === ':');
      // Valid variables are either a string, number, or \Stringable object. For
      // historical reasons, Boolean and NULL placeholders are also allowed;
      // NULL placeholders are deprecated and may be considered invalid in the
      // future. @see https://www.drupal.org/node/3318826
      $valid_placeholder_variable = is_scalar($variable) || is_null($variable) || $variable instanceof \Stringable;
      // Build a list of message placeholders,
      if ($valid_placeholder_key && $valid_placeholder_variable) {
        $variables[$key] = $variable;
      }

I did not review the MR.
I updated credit.

I am setting to needs work for the two items above. Once that is sorted this should be ready.

Thanks.

@quietone I'm not a fan of using local variables in that manner, because it does not break out of the conditional logic early if the key is not valid. For example, if the key is 'exception', we don't need to look at the object it stores; we can simply move on to the next key. How about two levels of conditional logic, to allow breaking out early while avoiding wrapping? See current iteration of the merge request.

re: "Shall we add a followup to decide whether Booleans should also be deprecated?" my answer was no, we don't need to. Drupal did not deprecate NULL placeholders until PHP deprecated NULL to string coercion. And PHP has not yet deprecated Boolean to string coercion, although there have been some RFCs that discussed it. When I said "Probably a good idea to deprecate them" I was referring to that slow process of PHP deprecating it, followed by Drupal deprecating it, and then eventually throwing an error. If/when we reach that point, the code in this class would need to be changed to ignore Boolean context data.

Reviewed the commit for the two levels of logic checking and think that's a good middle ground.

Also appears the question about a follow up appears to have been answered in #129.

Good to finally get this one fixed. Backported to 10.2.x as a low risk bug fix.

Committed and pushed 367e57e7bc to 11.x and a335588be2 to 10.2.x. Thanks!

longwave → closed merge request !5352

Automatically closed - issue fixed for 2 weeks with no activity.