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

That sucks indeed.

Can you give any hint what it was? Is that maybe too much memory?

That sucks indeed.

Can you give any hint what it was? Is that maybe too much memory?

Yes, how does it crash? Exception? php error?

I tried the following:

• Place an exception in HttpKernel
• Exception is logged
• Dblog itself still continues to work./li>

One thing I could imagine is that somehow you managed to get an object into $message, then maybe the (string) cast in isSafe() could fail, just one random idea.

@hass
Could you imagine that you had a really long message inside dblog?

If this happens, it'll render the dblog page in pretty rough shape, but does not render the entire system unusable, so downgrading to major.

I'm working on a patch for this at #DrupalConLA mentored sprint.

Dave and I have a patch, and he has a Drupal Unit Test that's almost done.

@Todd Zebert
Great work, I hope you can upload a patch soon. One thing you should learn, things don't have to be perfect in the first place. Better iterate quickly.

Well, we had something very close end of the sprint Fri, but I haven't heard from Dave (not Mike, my mistake) "vasi" since then. I've pinged him on twitter.

Here's a patch that attempts to fix the problem, along with some tests.

There's a bunch of choices that had to be made here:

1. What happens when someone tries to log an object? Possibilities include: It succeeds, it fails, or it succeeds but shows a warning. We decided to allow it to succeed. Since many dblogs are already warning conditions, it might get confusing to print warnings-upon-warnings.
2. What does the dblog UI do with an object? Possibilities include: Go down flaming, show some sort of placeholder (eg: "
   ", show a string representation of the object, maybe others. For now we're going with a string representation, as yielded by print_r. It's probably the closest we can get to what the user intended to show.
3. At what level do we fix this issue? It could be in the DbLogController or in SafeMarkup. Although fixing it in SafeMarkup would solve this issue everywhere, it's not clear that we want this to never yield an error--maybe in other cases that's desirable. Also, many, many other parts of Drupal use SafeMarkup, and it's hard to decide whether the same behaviour is appropriate for all of them. So for now, we're fixing it in DbLogController.

To test, apply just the test code:
git apply -v --include=core/modules/dblog/src/Tests/DbLogControllerFormatTest.php safemarkup_issafe-2481349-14.patch

To run the test (your sudo -u, and --url will vary):
sudo -u _www php ./core/scripts/run-tests.sh --url http://toddlocal.drupal8.com --browser --verbose --file core/modules/dblog/src/Tests/DbLogControllerFormatTest.php

As expect, testFormatMessageObject() fails. Here's the complete simpletest report:

Drupal\dblog\Tests\DbLogControllerFormatTest
Tests how DbLogController formats messages.
8 passes, 1 fail, 0 exceptions
Message	Group	Filename	Line	Function	Status
Enabled modules: system, dblog, user.	Other	DbLogControllerFormatTest.php	57	Drupal\dblog\Tests\DbLogControllerFormatTest->setUp()	Pass
Value 'My fruit is apple' is identical to value 'My fruit is apple'.	Other	DbLogControllerFormatTest.php	83	Drupal\dblog\Tests\DbLogControllerFormatTest->testFormatMessageString()	Pass
Value NULL is NULL.	Other	DbLogControllerFormatTest.php	84	Drupal\dblog\Tests\DbLogControllerFormatTest->testFormatMessageString()	Pass
Enabled modules: system, dblog, user.	Other	DbLogControllerFormatTest.php	57	Drupal\dblog\Tests\DbLogControllerFormatTest->setUp()	Pass
Value 'My fruit is ' is TRUE.	Other	DbLogControllerFormatTest.php	97	Drupal\dblog\Tests\DbLogControllerFormatTest->testFormatMessageObject()	Pass
Value 'htmlspecialchars() expects parameter 1 to be string, object given' is NULL.	Other	DbLogControllerFormatTest.php	98	Drupal\dblog\Tests\DbLogControllerFormatTest->testFormatMessageObject()	Fail
Enabled modules: system, dblog, user.	Other	DbLogControllerFormatTest.php	57	Drupal\dblog\Tests\DbLogControllerFormatTest->setUp()	Pass
Value 'My fruit is apple' is identical to value 'My fruit is apple'.	Other	DbLogControllerFormatTest.php	111	Drupal\dblog\Tests\DbLogControllerFormatTest->testFormatMessageObjectToString()	Pass
Value NULL is NULL.	Other	DbLogControllerFormatTest.php	112	Drupal\dblog\Tests\DbLogControllerFormatTest->testFormatMessageObjectToString()	Pass

I verified my existing object in dblog still created the existing error at /admin/reports/dblog .

Apply just the patched code:
git apply -v --include=core/modules/dblog/src/Controller/DbLogController.php safemarkup_issafe-2481349-14.patch

Rerun the test:
sudo -u _www php ./core/scripts/run-tests.sh --url http://toddlocal.drupal8.com --browser --verbose --file core/modules/dblog/src/Tests/DbLogControllerFormatTest.php

All nine tests passes, excerpt:

Value 'My fruit is stdClass Object ( [apple] => mcintosh ) ' is TRUE.	Other	DbLogControllerFormatTest.php	97	Drupal\dblog\Tests\DbLogControllerFormatTest->testFormatMessageObject()	Pass
Value NULL is NULL.	Other	DbLogControllerFormatTest.php	98	Drupal\dblog\Tests\DbLogControllerFormatTest->testFormatMessageObject()	Pass

I verified my existing object in dblog DOES NOT created the existing error at /admin/reports/dblog .

We should throw an exception when the incorrect argument is passed in the first place rather than trying to account for the incorrect API usage.

In our first discussion of this with our mentor @heddn we figured "saving" the data - that is, the data sent to the log - was worthwhile, vs just throwing an exception. Additionally, if we throw an exception, we can't even include the data causing the error because that that would cause another exception, unless of course we did the equivalent of a __toString; but then it seems silly to capture the data in an error in the log and not just capture the data in the log to begin with.

public function DbLog::log doesn't put constraints on the type of items in $context, nor does public function LoggerInterface::log. As it is, the log takes the data fine. It's just the making the output safe for render that breaks.

re #19: Go ahead and throw an exception when the incorrect type of object is passed. Instead of trying to make things work.

Replacing with the throwing-an-exception-on-misuse approach.

Tests fail because of what looks like a bug in LogMessageParser. It's still looking for old-style '!placeholder', and doesn't understand ':placeholder'. Ooops!

Tests fail because of what looks like a bug in LogMessageParser. It's still looking for old-style '!placeholder', and doesn't understand ':placeholder'. Ooops!

This is fixed here: #2617330: LogMessageParser::parseMessagePlaceholders() needs to switch bang placeholder to colon placeholder but according @dawehner it needs tests.

So I merged both patches into this a single one, if tests pass I think we could close two issues with a single patch.

Possibly related issue is #2760031: Log messages won't appear translated if they have special characters in them, of which #2617330: LogMessageParser::parseMessagePlaceholders() needs to switch bang placeholder to colon placeholder was marked as a duplicate.

I'm working on triaging this issue at Drupalcon Vienna2016, following the instructions in #2474049: [meta] Major issue triage. @fgm is helping as our mentor.

The test fail also on 8.5.x-dev.
Patch need reroll.

Re-rolled patch from #27.

I saw a strange behaviuour in the tests.
I changed the foreach loop into the test to use DataProvider to pass the logging method.

Seems more stable now.

Merged @ziomizar's changes into the patch.

+++ b/core/modules/dblog/tests/src/Unit/DbLogTest.php
@@ -0,0 +1,156 @@
+      'emergency',
+      'alert',
+      'critical',
+      'error',
+      'warning',
+      'info',
+      'debug',

According to the PHPunit docs, this should be an array of arrays.

+++ b/core/modules/dblog/tests/src/Unit/DbLogTest.php
@@ -0,0 +1,156 @@
+    $this->dblog = new DbLog($this->conn, $parser);
+

This should be mocked too. Mocking this class we could move this unit test outside the scope of dblog.

Corrected the test failures.
Corrected the coding standards errors.
Corrected the data provider.

@dagmar Can you explain more about the need to mock DBLog, please? I don't understand the reason for doing so and, if my implementation is correct, it would require a lot of work.

AIUI, the idea of mocking DBLog is that it no longer needs the dblog module to be enabled to run the tests, and no longer needs to be a even a KernelTest but can be just a UnitTest.

In my opinion, this exception should be triggered at LogMessageParser level.

If you have dblog disabled, and some contrib module runs this line of code:

\Drupal::logger('php')->warning('closure %c', ['%c' => function () { } ]);

Then syslog will log this:

Recoverable fatal error: Object of class Closure could not be converted to string in Drupal\syslog\Logger\SysLog->log() (line 71 of /var/www/drupal/core/modules/syslog/src/Logger/SysLog.php which is basically the same thing you saw when try to see the log using dblog.

If we move this exception to the LogMessageParser then, you can mock the use of Dblog, or just use a different logger to try this functionality.

Something like this.

We should check only for placeholders not all the items in the context array.

I think this title reflects better the idea behind this patch.

Updated issue summary to reflect the proposed solution. This patch only needs some code review.

Raising an exception during logging seems like a big red flag for me. How are you supposed to log it ? It looks like it has the potential for infinite recursion in some scenarios (can't imagine which ones right now, but in earlier watchdog code, we had specific logic to avoid such recursions, and this doesn't seem to be included here.

Two core maintainers proposed in #18 and #21 proposed to trow an exception.

We should throw an exception when the incorrect argument is passed in the first place rather than trying to account for the incorrect API usage.

Maybe we need some test coverage that ensure that some log is created when the log placeholders are not convertible into strings. What do you think @fgm?

The problem with #18 and #21, IMHO, is that they fail to appreciate the specificity of logging as a way to track problems vs other situations.

This is partly covered by #19, which could provide a middle ground: how about generating a (synthetic) log record as an error/critical about incorrect API usage about to throw, passing minimaly safe data (probably just a limited call stack slice without arguments to pinpoint the source code line causing the problem), and only then throw an exception. That way tracability, which is what logging is all about, is preserved for future analysis, while interactive usage provides the immediate feedback.

learning,understanding drupal8 to covert d7 module and I needed to dblog some object to debug and get info stored in that object.

\Drupal::logger('mymodule')->info('<pre>' . print_r( $form_state_values, true) . '</pre>'); //works fine

\Drupal::logger('mymodule')->info($account); //raised Recoverable fatal error: Object of class Drupal\user\Entity\User could not be converted to string 

\Drupal::logger('mymodule')->info(print_r($account, TRUE)); // raised exception Fatal error: Allowed memory size of 134217728 bytes exhausted

Is that mean \Drupal::logger supports only selected objects(in my case $form_state_values worked)?

https://www.drupal.org/node/2270941 has some code having $message without clarifying whether we can use print_r with objects.

That has nothing to with logging, that's your code. print_r() and similar functions just can't handle content entities. the same error would happen if you just have print_r() without anything else.

One option is to use $account->toArray(), then you have a simple array structure of the values of that account. Or you can use kint() from the devel.module. Or use a real debugger.

see https://wizzlern.nl/drupal/drupal-8-entity-cheat-sheet on how to work with content entities.

Maybe we should make the logger API aware of APIs like ComplexDataInterface, which seems to be the lowest level interface including such a method to enable representing content without specific processing on the caller side ?

The problem with #18 and #21, IMHO, is that they fail to appreciate the specificity of logging as a way to track problems vs other situations.

This is partly covered by #19, which could provide a middle ground: how about generating a (synthetic) log record as an error/critical about incorrect API usage about to throw, passing minimaly safe data (probably just a limited call stack slice without arguments to pinpoint the source code line causing the problem),

I see what you mean @fgm. What about this?

Make tests easier to read providing to sets of @dataProviders.

@dagmar : looks like a sane workaround to me. It would be good to have an UX opinion, though, I guess.

If someone can review the message shown to developers (see issue summary) and decide if needs some modification would be great.

It turns out that this issue also fix #2703877: Logger tries to replace {users_field_data} with current user object and #2980802: Object of class Drupal\\Core\\Session\\AccountProxy could not be converted to string so I included a test to check this exception for those cases too.

Patch #64 does not fix
Serialization of 'Closure' is not allowed in serialize() (line 14 of core/lib/Drupal/Component/Serialization/PhpSerialize.php).
As mentioned in https://www.drupal.org/project/drupal/issues/1872690

I get this error if
$this->keyValueExpirableFactory->get('form')->setWithExpire($form_build_id, $form, $expire);
is called.

Hi @Insasse thanks for your comment.

I think your issue is different than this one. His is trying to avoid crash viewing the log report. Please read the issue summary. Yours is mentioning a different subsystem, the keyvalue.database I may be wrong anyway, so could you provide the backtrack of your error?

Hey @Dagmar,

The Full error message:

"
An AJAX HTTP error occurred.
HTTP Result Code: 500
Debugging information follows.
Path: /en/user/1088/edit/optional?element_parents=user_picture/widget/0&ajax_form=1
StatusText: 500 Service unavailable (with message)
ResponseText: The website encountered an unexpected error. Please try again later.Exception: Serialization of 'Closure' is not allowed in serialize() (line 14 of core/lib/Drupal/Component/Serialization/PhpSerialize.php). Drupal\Component\Serialization\PhpSerialize::encode(Array) (Line: 81)
Drupal\Core\KeyValueStore\DatabaseStorageExpirable->setWithExpire('form--IxSTJJ_FAhjzrQ1vib0fLKlWdhOy5rf2o-KeGQGCsk', Array, 21600) (Line: 193)
Drupal\Core\Form\FormCache->setCache('form--IxSTJJ_FAhjzrQ1vib0fLKlWdhOy5rf2o-KeGQGCsk', Array, Object) (Line: 445)
Drupal\Core\Form\FormBuilder->setCache('form--IxSTJJ_FAhjzrQ1vib0fLKlWdhOy5rf2o-KeGQGCsk', Array, Object) (Line: 423)
Drupal\Core\Form\FormBuilder->rebuildForm('user_optional_form', Object, Array) (Line: 625)
Drupal\Core\Form\FormBuilder->processForm('user_optional_form', Array, Object) (Line: 318)
Drupal\Core\Form\FormBuilder->buildForm('user_optional_form', Object) (Line: 93)
Drupal\Core\Controller\FormController->getContentResult(Object, Object)
call_user_func_array(Array, Array) (Line: 123)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 582)
Drupal\Core\Render\Renderer->executeInRenderContext(Object, Object) (Line: 124)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->wrapControllerExecutionInRenderContext(Array, Array) (Line: 97)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 151)
Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object, 1) (Line: 68)
Symfony\Component\HttpKernel\HttpKernel->handle(Object, 1, 1) (Line: 57)
Drupal\Core\StackMiddleware\Session->handle(Object, 1, 1) (Line: 47)
Drupal\Core\StackMiddleware\KernelPreHandle->handle(Object, 1, 1) (Line: 47)
Drupal\Core\StackMiddleware\ReverseProxyMiddleware->handle(Object, 1, 1) (Line: 52)
Drupal\Core\StackMiddleware\NegotiationMiddleware->handle(Object, 1, 1) (Line: 23)
Stack\StackedHttpKernel->handle(Object, 1, 1) (Line: 693)
Drupal\Core\DrupalKernel->handle(Object) (Line: 19)
"

$form_state->setCached(FALSE); fixed it for me.

@Insasse I don't see dblog module involved in the process. It seems a new issue. Feel free to create a new one, probably under the base system component. Thanks!

Rerolled for 9.5 but not able to figure out why the tests are breaking.

Fixed build errors.

My 2¢ is that the PSR-3 log standard should be followed as much as possible:

Every method accepts an array as context data. This is meant to hold any extraneous information that does not fit well in a string. The array can contain anything. Implementors MUST ensure they treat context data with as much lenience as possible. A given value in the context MUST NOT throw an exception nor raise any php error, warning or notice.

So ideally, parseMessagePlaceholders() - which is called by the two built-in implementors, dblog and syslog - wouldn't throw. If a placeholder can't be stringified then it could simply be removed from the message placeholders, under the logic that it's not a valid message placeholder, it's just part of the context.

An alternative solution, which requires a bit more code, would be to helpfully generate a string that describes the unstringable object, callable, resource, array, or whatever it is, e.g. 'Object ' . get_class($value), 'Array of length ' . count($value), etc.

I have just rerolled the patch to work with Drupal core 9.5.2 - would be good to have some more community testing on it.

The idea of throwing an exception is 8 year old... But I agree with @mfb that we should follow the PSR-3 log standard as much as possible.

IMO we should:

1. Not raise a new exception.
2. Remove the problematic context value.
3. Keep the second log indicating the misuse of the logging API.

So there's dealing with logging with the original patch was doing. Didn't really have time to review while in the middle of dealing with this blocking debugging a broken site. Attached is a quick fix I made that deals with variables not being strings similar to the way we already deal with unserialization failures in the UI.

This was useful but doesn't help other systems using logging so the deeper fix seems needed too. Conflict was with #2617330: LogMessageParser::parseMessagePlaceholders() needs to switch bang placeholder to colon placeholder. Untested re-roll for that also attached.

   * @throws Psr\Log\InvalidArgumentException

At the least this needs to be converted to a FQDN(add the first \).

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.

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

Random test failure.

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 #3387437: Unify logic for determining valid placeholder keys and values

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 wrapped 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. 🙂 It came up in discussion on this issue but was not in scope; therefore, to preserve the unresolved discussion once the issue is marked fixed, we file a followup.

@xjm I filed the one followup issue we found so far: #3387437: Unify logic for determining valid placeholder keys and values, 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 #3387437: Unify logic for determining valid placeholder keys and values

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!