Bug #94043
closed
Incorrect usage of PSR-3 logger
0%
Description
The logger service is frequently used like this:
```
$this->logger->notice('The singleton "' . $classSchema->getClassName() . '" needs a prototype in the constructor.');
```
That is incorrect according to PSR-3. The string for the message is supposed to be static. If it has variable data (like the class name here), the string should have a placeholder and the value provided in the `$context` array. That is, it should be more like this:
```
$this->logger->notice('The singleton "{class}" needs a prototype in the constructor.', ['class' => $classSchema->getClassName()]);
```
This is similar in structure and concept to sprintf() and prepared statements for SQL, and for the similar reasons.
1. It allows the separate data value to be escaped if necessary in an output-dependent way, rather than inlined without escaping. (Technically not doing so is an injection vector, though I've not seen a real vector in here yet.)
2. The message may be extracted and translated in order to provide localization of log messages, especially if they are shown on screen.
3. It allows for more robust tracking of what errors are being generated. For instance, one could search a DB table of log messages for the template string.
I am not sure what all the logging backend is doing right now, so it may be more complicated than just fixing all the call sites. But fixing all the call sites would be a really good set of newbie-tasks once we're confident the backend is ready for it.
Updated by Larry Garfield over 3 years ago
- Subject changed from Correct usage of PSR-3 logger to Incorrect usage of PSR-3 logger
Updated by Markus Klein over 3 years ago
First off: Why do you declare an "incorrect usage"?
PSR-3 1.2 says
The message MAY contain placeholders which implementors MAY replace with values from the context array.
So in general this is optional and I seem to miss any more specific specification on what is allowed for messages.
Of course, I agree the described placeholder concept is desirable.
The Core is ready in the sense of "we store whatever comes along", but there is currently no output implementation that does placeholder replacement.
The PSR does not specify which component exactly is in charge of placeholder interpolation.
In our case the various Writer classes could be the ones, but I am not sure whether it is clever to do the replacement before storage or on displaying the data again (output).
For instance: A simple log file writer may interpolate before persisting a record, as arguably the file is also the final output. A database writer would probably persists a record "as is" and a dedicated viewer for these log records would take care of the interpolation.
I therefore suggest adding a dedicated feature ticket where the expected functionality is clearly defined.
This ticket may then be used to actually refactor the existing usages of the API.
Updated by Larry Garfield over 3 years ago
PSR-3 lacks a metadocument because of its age, but the intent behind that feature of the spec was precisely to be used as I described above. The context of why it was added wasn't in the spec because FIG didn't do that at the time. The idea of the metadoc was introduced later for exactly that reason.
Background: I was responsible for that part of PSR-3, so I am speaking from first-hand experience. :-)
For instance: A simple log file writer may interpolate before persisting a record, as arguably the file is also the final output. A database writer would probably persists a record "as is" and a dedicated viewer for these log records would take care of the interpolation.
That's the most likely implementation, yes. That's what Monolog and Drupal do (the two implementations with which I am most familiar). The spec itself is silent on it precisely because the "where" is variable, as you describe.
One option would be to switch to Monolog for the logger, then introduce a Monolog backend that writes the data to the database, without interpolation, and then update the GUI accordingly. That would have the benefit of punting most interpolation needs to Monolog. The alternative would be to update all of the existing loggers to do interpolation as appropriate. Between the two I think Monolog is likely the better option, and already has an issue for it: #85506. (Marking that as related.)
Updated by Larry Garfield over 3 years ago
- Related to Feature #85506: Integrate monolog as logging framework added
Updated by Markus Klein over 3 years ago
We have this monolog topic around for quite a while, but to my opinion it simply does not fit our needs.
Monolog stems from the general assumption that it covers a single app. This is quite contrary to what TYPO3 has with its extension/plugin architecture.
I sometimes call it multi-app environment.
We crafted a rather detailed concept (already a long time ago) on how logging should actually work and what properties it needs to be able to filter and process log records for various needs.
We came to the conclusion that monolog only covers a minor part of this, the writers could be reused, maybe.
The concept is still available here: https://wiki.typo3.org/Blueprints/Logging
Updated by Larry Garfield over 3 years ago
- Related to Epic #93631: PHP 8 Compat added
Updated by Larry Garfield over 3 years ago
- Related to deleted (Epic #93631: PHP 8 Compat)
Updated by Gerrit Code Review over 3 years ago
- Status changed from New to Under Review
Patch set 1 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69401
Updated by Gerrit Code Review over 3 years ago
Patch set 2 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69401
Updated by Gerrit Code Review over 3 years ago
Patch set 3 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69401
Updated by Larry Garfield over 3 years ago
- Complexity set to hard
OK, I've dug a bit deeper and there's more than one problem. Right now, the logging system is not only inconsistent but wrong on many levels.
1. Sometimes, it is called with manually concatenated strings.
2. Sometimes, it's called with sprintf() concatenated strings.
3. Sometimes, it's called with a sprintf()-friendly template string and placeholders.
3. Sometimes, the DB table is written to directly without going through the logging framework at all.
4. The DatabaseWriter class writes a JSON blob to the database. However, it seems none of the cases that use the logger directly actually use the context array, so nothing gets written.
5. The BELog module's LogEntry class (which acts as a record for the log table) reads data out of the database with unserialize().
6. FormatDetailsViewHelper removes file path bases from the context array, but only for certain types of record. I've yet to find a case where it actually happens.
None of the above is PSR-3-compatible. Whether we stick with a custom logger or switch to Monolog in the future, this needs to be corrected to properly follow PSR.3.
As a saving grace, at least, log data is generally not critical and so we don't need to worry much about compatibility with existing data. It can just be blown away.
That would entail:
1. Converting the DB writer to write the context array to the DB, probably as a JSON blob rather than serialize/unserialize as it avoids the security issues in the latter.
2. Converting all direct-db-write cases to use the actual logger.
3. Converting all logger calls to use a fixed string with {}-denoted placeholders, per spec. This is not-small.
4. Convert the other backend writers to interpolate the string immediately when writing to syslog, etc.
5. Updating FormatDetailsViewHelper to interpolate the string on display, also escaping it for HTML viewing.
6. Decide if we want to keep the file path trimming, and if so in which outputs, and apply it consistently. (I think it's actually a useful feature, so worth keeping in cases where the path is actually in context rather than in the string, such as when catching an exception or warning.)
7. Probably a fair bit of cleanup along the way, just because.
Because this is a not-small lift, I want to get a second opinion on it before I expand my scope. To be clear, this is the same work that will need to be done no matter what the long-term future of the logger is, because right now the API is being abused and is not compatible with PSR-3. At bare minimum all call sites need to be updated to call it properly, and the writers/display updated to handle that.
Updated by Markus Klein over 3 years ago
Larry, as I just commented on the patch as well, you have to distinguish between the Logging Framework/API being very much PSR-3 compatible and the old legacy logging stuff still in use.
Please check out the loads of tickets regarding the necessary transition and the missing features in the logging framework and the concept we crafted some time ago, how we think the logging framework must look like: https://wiki.typo3.org/Blueprints/Logging
Regarding "display log entries": Once we use the logging framework this topic is getting ultra-tough, because anyone can configure the logs to go anywhere (files, database tables, whatever) in almost any format. At this point the ext:belog is actually pointless as a generic log viewer.
Updated by Larry Garfield over 3 years ago
Marcus and I had a long call this morning (thanks!), and he brought me up to speed on the bits of the logging story I didn't know yet. We've developed a new plan to proceed that I am going to start on, although the later parts of it still need feedback from others.
Phase 1 (uncontroversial):
1. Update the existing Writers in place to interpolate PSR-3 strings properly.
2. Update the DatabaseWriter specifically to write to a new SQL table, separate from the old log table.
3. Update all current calls to the PSR-3 logger to use PSR-3 strings properly.
Phase 2 (feedback needed):
0. Re-evaluate Monolog to see if it can do what is described below already, or can be made to do so. If so, build on that. If not:
1. Overhaul the existing logging system. The tentative plan is to replace the processors and writers with PSR-14 events, in 2 passes. (One for enhancing a log record before it gets written, one for writing it to various outputs). Enhancing and writing events can come in pairs or separately.
2. Establish some standard optional names for context keys that the system will recognize. Mainly, probably a free-tagging field that can flag "security"/"user"/"php error", etc. as well as things like "class that triggered the error." Exact details here still TBD.
3. Add built-in log enhancers that do the stuff mentioned in the blueprint that Markus linked above.
4. Devise how to make it easy to configure which listeners run on which sites. I don't know the specific PSR-14 implementation here well enough yet to say what the ideal would be. (Custom provider, perhaps?)
Phase 3 (uncontroversial, but requires the previous steps first):
1. Add code to everywhere that uses writeLog now to double-enter data into the new logging framework.
2. Reimplement the database log viewer in belog to use the new DB log instead, doing HTML interpolation as appropriate.
Phase 4 (in v12, after people have time to transition):
1. Delete the old writeLog() method, its table, and so on.
Phase 1 should keep me busy for a day or three, so I'll start on that while we gather feedback on the still--open parts of phase 2.
Updated by Gerrit Code Review over 3 years ago
Patch set 1 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69425
Updated by Gerrit Code Review over 3 years ago
Patch set 2 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69425
Updated by Gerrit Code Review over 3 years ago
Patch set 3 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69425
Updated by Gerrit Code Review over 3 years ago
Patch set 4 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69425
Updated by Gerrit Code Review over 3 years ago
Patch set 5 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69425
Updated by Gerrit Code Review over 3 years ago
Patch set 6 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69425
Updated by Larry Garfield over 3 years ago
- Related to Bug #94315: Use PSR-3 interpolation added
Updated by Larry Garfield over 3 years ago
Moving the current patch to #94315, so we can break this up into pieces.
Still looking for feedback on phase 2.
Updated by Gerrit Code Review over 3 years ago
Patch set 4 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69401
Updated by Gerrit Code Review over 3 years ago
Patch set 5 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69401
Updated by Gerrit Code Review over 3 years ago
Patch set 6 for branch master of project Packages/TYPO3.CMS has been pushed to the review server.
It is available at https://review.typo3.org/c/Packages/TYPO3.CMS/+/69401
Updated by Benni Mack over 3 years ago
One thing we need to find is a good solution for everything in BackendUserAuthenticaton->writeLog() and DataHandler->log() which effectively log into `sys_log`. If we achieve a better replacement for this based on PSR-3, we can then replace our custom calls, and rely on PSR-3 completely. After that, we can look at monolog, but that's rather related to the Configuration Management topic.
Updated by Larry Garfield over 3 years ago
- Related to Task #94344: Move PSR-3 logger to its own table added
Updated by Larry Garfield over 3 years ago
- Related to Task #94352: Tidy up logging framework added
Updated by Larry Garfield over 3 years ago
- Related to Epic #94356: Embrace PSR-3 added
Updated by Christian Kuhn over 3 years ago
- Status changed from Under Review to Closed