dev/core#2148 - Incorrect use of ts, quotes, escape in log call

[demeritcowboy]

Overview

https://lab.civicrm.org/dev/core/-/issues/2148

• It's a sysadmin-y string not seen by end users, so ts() usually isn't used on those.
• It uses a variable inside the ts.
• The variable gets output as the literal $dbName instead of the value because the string uses single quotes.
• CRM_Utils_Type::escape is misused here. What it does when called on a string is escapes it for insertion into a SQL string. The default logger writes to a file. Even if the logger implemention/configuration ended up writing to a database, it should be that log implementation that escapes it at insertion time, not here. And for displaying on screen, it should be sanitized at display time (using a different method than CRM_Utils_Type::escape since it's not meant for screen).

Before

Well, the main functional problem is that it doesn't tell you what field it's talking about. It just literally calls it $dbName.

After

Better

Technical Details

Comments

[civibot]

(Standard links)

• If this is your first pull-request for CiviCRM, please browse CONTRIBUTING.md for information about the development and testing processes.
• If you are reviewing this pull-request, you may wish to consult the test sites and the Review Standards (long template, short template).

[eileenmcnaughton]

@seamuslee001 do you agree on the escape comments?

[artfulrobot]

We write all sorts to the log, and any presentation of the log needs the usual care (e.g. htmlspecialchars). I don't think the escaping was adding anything useful so I agree with @demeritcowboy

My preference would be to use json_encode($whatevs) when you're inlcuding variables in log output. This can be very useful in showing up things like empty strings, NULL, false etc.

I like that it tells you something useful now, though 👍

[demeritcowboy]

Thanks. I think the way to do variable representation would be to use the PSR-3 placeholders, and then whichever log implementation you're using can json_encode, var_dump, emojify, or whatever. Right now the default log implementation in civi doesn't recognize them, but it could. Or it's not hard to write an extension with a different log implementation - hook_civicrm_container: $container->setDefinition('psr_log', new Definition('\MyLog', []))->setPublic(TRUE);

[demeritcowboy]

You've prompted me to think more about the variable placeholders and I've updated the PR to use them. With the current implementation of CRM_Core_Error_Log it ends up looking a little weird when the variables are strings, but is still readable and you can match up the values, and I think it is the right way to do it. There are a couple of Civi::log calls in civi that already use them, e.g. Civi/Angular/Manager.php. This way another implementation can then decide what it wants to do with the variable values, or the core default one can be improved. Lab ticket time. (https://lab.civicrm.org/dev/core/-/issues/2161)

[artfulrobot]

Yep, it's annoying that Civi log ignores placeholders. I gave up on it ages ago and usually just append json encoded data to the message and ignore the parameters bit. I'm big fan of JSON output because it's easily copy and pasteable, so if you're debugging and need to re-run something you can easily get the values back into some code. Anyhoo. I waffle.

[eileenmcnaughton]

I think if the combined brain power of @demeritcowboy & @artfulrobot agree here then it's good to merge

[artfulrobot]

Oh @demeritcowboy I remember why I don't use {placeholders} now... I know this is not the right place but it might help me to record this here anyway:

CiviCRM, as stated above, ignores PSR log placeholders. This is annoying but could be fixed, but it would need to consider two things: (1) is the value of the placeholder stringable? e.g. numbers, strings are OK, but what if the value is an array/object? PSR suggests that the values should be as raw as possible to preserve information; so then I'd suggest something like json_encode is applied to values inserted in placeholders. OR we have a rule that anything used as a placeholder must be stringable. And (2) is it cool to have variables stored in the log that are not used in placeholders?

However Drupal 7 (don't know about 8+) gives you a world of pain if its placeholders (via watchdog) are not stringable: because the presentation assumes they are which means that if they aren't, it generates warnings that can flood your logs at the point of looking at your logs!

I think it's helpful to

• Use json_encode on placeholder values. This way things don't break if it's an array, and this way we're clear whether the value is FALSE/NULL/''/' '/0 etc. I think the only drawback is that strings with quotes in look odd as the quotes will be \ escaped.

• Allow other vars that are not included in placeholders. These can be in the logs but don't need to be in the log title. It means if you use watchdog logging you have a layer of detail below the summary shown on the table of recent log messages.

[demeritcowboy]

Cool. Yes I was thinking most implementations may or may not want to treat strings differently, including core's. Have added your comment in the lab ticket.