[CONTROL] Logging before httpError will cause HTML to be added and output as plaintext

[Sil3ntStorm]

Affected Version

SilverStripe 4.1
composer info --direct

silverstripe-themes/simple dev-master 4d546a4 The SilverStripe simple theme (default SilverStripe 3 theme)
silverstripe/recipe-cms    1.1.0              SilverStripe recipe for fully featured page and asset content editing
silverstripe/recipe-plugin 1.2.0              Helper plugin to install SilverStripe recipes

Description

Calling httpError with an error message will (magically and at an unknown location) prefix the message with HTML Dom and then send the entire thing to the browser, which causes conforming browsers to display the complete HTML instead of only the error message, as the Content-Type Header is rightfully set to text/plain during the Exception handling for security reasons.

Steps to Reproduce

Install Base SS 4.1 composer create-project --no-dev silverstripe/installer . ^4.1 and add the following code to a custom page action and load the appropriate page.

    Injector::inst()->get(LoggerInterface::class)->error("This causes bad stuff to happen"); // Removing this line will remove the HTML and just leave the browser outputting "foo"
    $this->httpError(400, "foo"); // Will raise an HTTPResponse_Exception, setting the content-type header to text/plain

For example edit mysite/code/PageController.php and add the above to a new function crash(), add 'crash' to the allowedActions array and add the necessary use lines at the top.

Complete PageController.php:

use SilverStripe\CMS\Controllers\ContentController;
use SilverStripe\Core\Injector\Injector;
use Psr\Log\LoggerInterface;

class PageController extends ContentController
{
    private static $allowed_actions = ['crash'];

    protected function init()
    {
        parent::init();
    }

    public function crash() {
        Injector::inst()->get(LoggerInterface::class)->error("This causes bad stuff to happen"); // Removing this line will remove the HTML and just leave the browser outputting "foo"
        $this->httpError(400, "foo"); // Will raise an HTTPResponse_Exception, setting the content-type header to text/plain
    }
}

Result

Instead of displaying a text "foo", you will see a bunch of HTML source code and at the very end the "foo" we were expecting.
Comment out the Injector::inst() line, reload the page and see that you're only getting the expected "foo"

The content-type header is set to text/plain for valid security concerns and this is a good thing, however when doing so I would expect there to be no HTML present at all.

Fix Approach (by sminnee)

• MonologErrorHandler is refactored to accept an array of loggers as as well as a single logger.
  • In cases where an array is provided, it constructs a LoggerList decorator that dispatches log messages to each child LoggerInterface (maybe someone on packagist already has implemented this?)
• The default handler send messages to 2 services: %$Psr\Log\LoggerInterface and %$Psr\Log\LoggerInterface.errorhandler (in that order)
• %$Psr\Log\LoggerInterface.errorhandler is given the display error logic
• %$Psr\Log\LoggerInterface by default is just a Monolog\Logger with no handlers attached.

We should test that instructions for setting up, say, logging to a file remain working without modification, to ensure that we haven't broken any APIs in doing this.

[robbieaverill]

If you're logging errors then you should expect the system to halt in some way. If you're looking to "log" (e.g. to a file) errors, you'll need to use a lower log level, e.g. info or debug.

What is the realistic example of where you'd be logging errors in this case?

[Sil3ntStorm]

The above mentioned modifications are the only ones performed, no configuration was changed other than modifying the PageController.php to provide a working small footprint reproduction of the bug.

Logging is (almost) never a bad thing imho, and it will halt (in some way) if used for example when an exception is thrown such as

try {
    doStuff(); // May throw Exception
} catch (Exception $e) {
    // Log Exception
    Injector::inst()->get(LoggerInterface::class)->error($e->getMessage());
    // Make the user receive an error
    $this->httpError(400, "Bad things happened"); 
}
doOtherStuff(); // Never reached if Exception is thrown in doStuff call.

Logging stuff like that as an error, just seems logical and appropriate. Not to mention that without further modifications to the config, nothing obvious seems to happen when logging (apart from this bug that is), at least nothing is ever really logged to anywhere afaict.
As such this should be pretty much a no-op, but can be enabled through dev configuration on a dev cluster, by adding logging to file configuration settings.

[maxime-rainville]

I just tested @Sil3ntStorm's code sample and I'm encountering the same issue that's describe.

I think he's right that the logger shouldn't be affecting the behavior of the application beyond writing a log message to the error logs.

It's quite a common pattern to have some detailed error message printed to the logs for debugging later on and then display a nondescript error page. This bug prevents this from happening.

[robbieaverill]

I've brought this up before, and was told not to log errors if I didn't want to disrupt the application flow. This stems from the fact that we use monolog for error handling in the main application. I don't think this is a bug.

A little bit of related detail in lekoala/silverstripe-debugbar#72 during upgrade from SS3 to SS4 where we had to ditch support for showing any error logs above debug.

One workaround is to use your own monolog service rather than using the one that is configured in core. This isn't a great solution for inter-module logging compatibility, but would be fine for logging in your own module or project.

[maxime-rainville]

@robbieaverill What was the stated rational for not logging errors?

The doc for LoggerInterface::error() states:

Runtime errors that do not require immediate action but should typically be logged and monitored.

To me that sounds like calling this method should not be a big deal.

[robbieaverill]

I agree with you =) we probably need a weigh in from @tractorcow at some point when he's available

[maxime-rainville]

Did @tractorcow say logging errors was bad?! I'll have a stern word with him once he's back from holiday.

[robbieaverill]

I only remember that he was involved with this conversation.

Another possible solution is that we could move the core error logging into its own implementation and allow devs to do what they wish with the default LoggerInterface service.

[Sil3ntStorm]

Kinda offtopic, but in a default installation of SS4.1 with no configuration changes, where would I find such error (or any other level) logs? I checked the standard suspects (PHP logs, Webserver logs, syslog) and couldn't find any trace of these log messages.
error() logs are evidently sent to the browser, but other levels I couldn't find without modifying the configuration, adding a file logger.

[robbieaverill]

@Sil3ntStorm by default all logs go to the browser. You'll need to push a file logging handler if you want file logs - see https://docs.silverstripe.org/en/4/developer_guides/debugging/error_handling/#logging-to-a-file

I think the issue here is that logging an error to a file will also log it to the browser, which is a behavioural change with the introduction of monolog in SS4 from what SS_Log did in SS3

[Sil3ntStorm]

Yeah I know of that page and the file logging configuration change.
If logging going to the browser is a desired default behavior, then that in itself is not necessarily the issue (though debatable) , as that could then be disabled through removing the default handler according to the documentation if desired.
However, it doesn't appear as though all logging goes to the browser, as changing the level from error to warning/info/debug will not actually show up in the browser. The only thing that will show up is the message supplied to $this->httpError. If the httpError call is not done, then a blank page is served (ie. no data is sent except headers).
When doing the httpError call, logging error will break something elsewhere causing templates to be processed and HTML generated, then the error message supplied to the httpError is appended to the HTML and all of that sent to the browser.
When logging error without calling httpError, it serves the error 500 template twice, without ever including either message anywhere.

• Log::error + httpError = Error 500 Template HTML + httpError message (served with status 400 as specified in httpError)
• Log::error = Error 500 Template twice (served with status 500)
• Log::info + httpError = Error Message from httpError
• Log::info = Blank page

(If I didn't mess up somewhere, it's late)

With the above in mind, it appears as though my initial statement that logging is apparently (supposed to be?) a no-op by default is correct (except for these bugs / inconsistencies).
I actually prefer logging not to be sent to the browser, as it's more of a debugging / monitoring aid than a user facing thing.

[sminnee]

It may be that our current behaviour for "error" should be reserved for "critical", "emergency", or "alert"?

Coupled with this would be to adjust our exception & error handlers to log higher-severity messages as well

[dhensby]

I think he's right that the logger shouldn't be affecting the behavior of the application beyond writing a log message to the error logs.

I agree wit @maxime-rainville (and @robbieaverill); logging errors should not cause a halt in execution itself. If error logging happens to log an exception, it shouldn't swallow the exception and continue execution, but it shouldn't take a non-halting error and halt. That's madness

[robbieaverill]

The best and most non-breaking solution I have here is to shift the default framework logging (CLI and HTTP) to a sub-service of LoggerInterface rather than the default implementation of it. That way clients can continue to use LoggerInterface as normal but raising errors and higher won't kill their websites.

[dhensby]

non-breaking

what would be breaking about not halting execution when logging errors?

[robbieaverill]

Sorry, I meant non-breaking in terms of what's in core already and how it could be adjusted to behave differently without breaking existing SS installs that may be relying on the existing LoggerInterface

[sminnee]

I'm a little nervous about making an incremental change without thinking through all the different use-cases. There's a risk that we make it more intuitive in this situation and less intuitive in another.

To that end, in our default configuration in live mode, what should the following situations do?

System errors:

• An exception is thrown
• A fatal user_error or system error is triggered
• A warning user_error or system error is triggered
• A notice user_error or system error is triggered

Log messages:

• An emergency message is logged by core or project code (indicating that the System is unusable.)
• An alert message is logged (Action must be taken immediately. Example: Entire website down, database unavailable, etc. This should trigger the SMS alerts and wake you up.)
• A critical message is logged (Critical conditions. Example: Application component unavailable, unexpected exception.)
• An error message is logged (Runtime errors that do not require immediate action but should typically be logged and monitored.)

The real question is: is there any level of log message that should voluntarily halt execution?

• If the answer is no, then it would seem like the best is to decouple error display from other logging. However, the first 4 items should still probably be logged to the standard LoggerInterface
• If the answer is yes, then we should probably increase the log-level of the uncaughts exception and user_errors

If we do want to decouple I would probably suggest that the system errors/exceptions are both sent to the LoggerInterface and to the system for error display. The error display system could still use LoggerInterface as its backbone, e.g. LoggerInterface.errorhandler. That way we don't need to refactor the code supporting it and break its APIs.

[Sil3ntStorm]

Logging is just logs for future reference to discover and aid in fixing issues. This is a website not some sort of client application where the developer needs to grab the logs from the client. So clients (users of the website) don't need to ever see these logs.
The one maintaining the website has access to the logs anyway (if they're actually logged to some file, be that web logs, php logs or custom file), so he can fix the issues or forward them along if need be.

Not sure what your definition of a system error is and how it relates to the Logging Levels.

In general in my view it all comes down to this:

• In cases where you absolutely cannot continue log the error and send the browser the configured Internal Server Error (ISE) static page and abort.
• If the system is so broken that it cannot even do the configured ISE page anymore, send a blank ISE and abort.
• Anything else, log the message and continue.

None of that has anything to do with logging really though, and should not be handled by a logging class. If a function called "log" does anything except the actual logging of the message to the configured means of logging then that is an unexpected, unintended side effect of said function.

If the developer thinks it's important enough to abort then it should have to be done explicitly, after the logging.

PS: There are SMS alerts in SS? 😮

[sminnee]

The system is currently architected so that errors and uncaught exceptions are handled by the error logger. It's built as a bunch of monolog handlers. On production sites, all it shows the users is a "sorry, something went wrong" page. On development sites, it often does make more sense to expose the error details to the user, and potentially the log messages too (I've sometimes used a plugin that puts it into my chrome dev tools, for example).

A system error is a user_error call, uncaught exception, or other fatal error. These should create log messages, but that doesn't necessarily mean that the log handler should behave the same way for these.

The core question is If you have sent an emergency or alert log message (as defined by PSR-3), should the system halt or not? If yes, then the error handler makes sense.

PS: No, there aren't SMS alerts but those are the PSR-3 log definitions. In principle you could probably use this to make them if you wanted https://github.com/tylercd100/monolog-sms

[dhensby]

If you have sent an emergency or alert log message (as defined by PSR-3), should the system halt or not?

My opinion is that it should not. The logger is there precisely to log the event in some way. The error handler then gets to decide how to deal with the error itself.

I should be able to do $logger->emergency('lol, this is just a joke'); and my application shouldn't halt (but I should have an emergency level entry in my logs).

One thing that might be a bit confusing is if you have a logger that logs to the browser; if you're using an "HTML output logger" for example, this is much more difficult for the application to continue as expected because HTML output may have started before headers have gone out and that handler may halt on errors (I think ours, or at least our SS3 html output for errors, does this). That's more a quirk of the specific logger but shouldn't be a feature of our abstract logging interface.

[sminnee]

Alright, that being the case, we should handle error display separately from logging. In the interests of not breaking APIs I think we should keep using Monolog handlers as the mechanism by which error display works. However, it can use a different LoggerInterface service so that regular log messages bypass it.

Here's a suggested implementation architecture; does it make sense?

• MonologErrorHandler is refactored to accept an array of loggers as as well as a single logger.
  • In cases where an array is provided, it constructs a LoggerList decorator that dispatches log messages to each child LoggerInterface (maybe someone on packagist already has implemented this?)
• The default handler send messages to 2 services: %$Psr\Log\LoggerInterface and %$Psr\Log\LoggerInterface.errorhandler (in that order)
• %$Psr\Log\LoggerInterface.errorhandler is given the display error logic
• %$Psr\Log\LoggerInterface by default is just a Monolog\Logger with no handlers attached.

We should test that instructions for setting up, say, logging to a file remain working without modification, to ensure that we haven't broken any APIs in doing this.

[ScopeyNZ]

I'm also encountering this issue with silverstripe-fulltextsearch. Having errors/warnings outputted as response body by default destroys Content-Type: application/json. Any future implementation needs to consider that.

[robbieaverill]

I really want to fix this. This is totally a bug in my opinion. I'll try and find some time to get a PR up for consideration if @ScopeyNZ doesn't beat me to it.

I'm getting really tired of having to reduce error log levels down to notice or something non-indicative of the problem when a module I work on has logging in it.

[ScopeyNZ]

Had to do some log level downgrading in the RealMe module today too!

[sminnee]

@robbieaverill do you want to do a PR of the approach I suggested above (I've put in the ticket description too)

[robbieaverill]

Yes, reading through it now

The real question is: is there any level of log message that should voluntarily halt execution?

No, in my opinion. This is a logger. If I wanted to halt execution I'd throw an exception rather than rely on a logger to handle it.

This mirrors @dhensby's opinion too so that seems good enough for a RFC pull request =)

[sminnee]

Yeah that's the approach that I incorporated into my recommended fix approach. We still use MonoLog to provide our error handling, but it's a separate extension point.

Using Monolog as an error handler is a bit overengineered, but it's already implemented and doing anything else would end up as an API breakage.

[robbieaverill]

PR at #8241 for consideration