Logging to LoggerInterface::class . '.errorhandler' halts execution and shows blue screen

[xini]

Module version(s) affected

5.3

Description

This was brought to light in silverstripe/silverstripe-assets#656, logging an error to LoggerInterface::class . '.errorhandler' halts execution and shows a blue screen error message instead of a 'nice' error page.

LoggerInterface::class . '.errorhandler' is currently used in three places:

• ImageManipulation::Convert() (https://github.com/silverstripe/silverstripe-assets/blob/2/src/ImageManipulation.php#L728)
• Member::onBeforeWrite() when the password changed email can't be sent (https://github.com/silverstripe/silverstripe-framework/blob/5/src/Security/Member.php#L811)
• LostPasswordHandler::sendEmail() when the email couldn't be sent (https://github.com/silverstripe/silverstripe-framework/blob/5/src/Security/MemberAuthenticator/LostPasswordHandler.php#L259)

There needs to be an investigation into whether there is a wider bug in the error logging setup / hard error blue screen setup, as suggested by @GuySartorelli in silverstripe/silverstripe-assets#656.

How to reproduce

see silverstripe/silverstripe-assets#656

Possible Solution

No response

Additional Context

No response

Validations

• Check that there isn't already an issue that reports the same bug
• Double check that your reproduction steps work in a fresh installation of silverstripe/installer (with any code examples you've provided)

[kinglozzer]

I’ve added some thoughts to silverstripe/silverstripe-assets#656, but just to summarise quickly here: I think the logging is working as it should be, we just shouldn’t be using the .errorhandler logger unless we definitely want to halt execution. And even then, we should probably throw an exception or something instead.

[xini]

Thanks @kinglozzer for you investigation.

I think the setup is conceptionally wrong. The logger should not halt execution, it should just log data.

Looking at https://docs.silverstripe.org/en/5/developer_guides/debugging/error_handling/#error-levels, when I throw a warning I want the code to continue. When I throw an exception or error, it should halt execution (if the exception is not caught and dealt with).

IMHO halting excecution is not the logger's job. Whether or not I log anything anywhere should not make a difference to the application flow.
Or am I wrong here?

Also, I don't see why Silverstripe shows the ugly blue screen instead of retuning the normal 500 error page to the user in live mode?

[kinglozzer]

Sorry, my comment above is possibly misleading - when I said “halt execution” I meant “display an error screen”. I don’t think the logger is supposed to halt execution at all (I’m not sure if actually does or not), though I think it might appear like it’s halting execution because HTTPOutputHandler will output an error screen.

[xini]

I hear you. And I agree. But why is the output handler reacting differently if you log to a different logger? The logger should just log to whatever target, not influence the application flow. No?

[GuySartorelli]

While I agree that a logging service shouldn't influence application flow, that's the architecture we have to work with for CMS 5. It is what it is.

[xini]

Agreed. Hence my PR for silverstripe/silverstripe-assets#656

[kinglozzer]

Picking this up from silverstripe/silverstripe-assets#656.

---

@sminnee

From memory, the idea with .errorhandler was that it is not a log, rather, it let us use PSR-3 interfaces to build our error handling system. That is, use LoggerInterface for something that isn't strictly logging. It sounds like this is poorly documented. I don't think using it outside the core implementation was really given much consideration.

This is correct, it looks like we essentially used Monolog to register everything that controls how we display errors to the user as well as how they’re logged. I don’t know if using Monolog to achieve this is a poor choice (it doesn’t seem to be a documented feature/approach) or if it’s actually okay, but on the whole I think it’s actually been working fine since it was introduced.

I agree that any non-fatal information going to errorhandler is probably a mistake and/or should be ignored — it's pretty common for log handlers to have a minimum error level below which they drop messages, and errorhandler's shoulld be error.
So either:

• errorhandler drops any <error messages.
• if errorhandler receives a message <error, it posts a warning to the main error log ("errorhandler received non-error message. Send these to the main LoggerInterface instead: xxxxx")

This is essentially how it works already: in dev mode, HTTPOutputHandler should show anything that’s a notice or higher. In live mode, it should only show errors.

---

@xini

This logging doesn't influence application flow. The return value of a function determines the flow of the application, not the logger or log target. If I want to log an error and show the user an error page, fine. But I can also log an error/warning/info and just continue and do whatever.

Agreed, we do this kind of thing all the time, especially in things like queued jobs where “errors” need to be logged as errors, but don’t affect whether the code can continue to run. I think we’re all in agreement there.

How does .errorhandler fit into this?

It doesn’t, it’s an API that shouldn’t ever be called manually (in core or user code). It should only ever be triggered by PHP’s native error/exception handling.

Why does it halt execution?

It doesn’t actually halt execution, even though it looks like it does. I checked this quickly by doing this in Page::init():

$logger = Injector::inst()->get(LoggerInterface::class . '.errorhandler');
$logger->error('Test error');
echo "<h1>HELLO</h1>";

I see the HELLO, so execution definitely isn’t halted.

HTTPOutputHandler will output an error screen and replace any content (via HTTPResponse::setBody()) with the error screen HTML. Even if the rest of the request executes successfully, you still won’t see the result if the output is routed via Controller::handleRequest() (most pages/actions are). That’s because this check will fail, so the error response body won’t be overwritten with the “successful” response body.

Why does it not show the normal 500 error page but that error blue screen, even in production?

It definitely shouldn’t show a blue screen in live mode, and in my testing it doesn’t - in live mode, I see the nicely formatted server error page that I’d expect website visitors to see. I don’t know if you’re using DDEV like I am, but I did notice when I was testing that changing from dev -> live in .env has no effect unless I restart the container. Weirdly, I can switch from live -> dev without a restart...

[xini]

Thanks, @kinglozzer that makes a lot of sense.

It definitely shouldn’t show a blue screen in live mode, and in my testing it doesn’t - in live mode, I see the nicely formatted server error page that I’d expect website visitors to see. I don’t know if you’re using DDEV like I am, but I did notice when I was testing that changing from dev -> live in .env has no effect unless I restart the container. Weirdly, I can switch from live -> dev without a restart...

I also noticed lately that I have to flush when changing the environment. Maybe something changed, caching the environment mode?

[GuySartorelli]

I also noticed lately that I have to flush when changing the environment. Maybe something changed, caching the environment mode?

The environment mode itself is not cached, but some configuration may be dependent on the environment mode, and that configuration is cached. That's not relevant to the issue though so if you have more questions about that it might be worth discussing in slack.

[xini]

That's not relevant to the issue though

You're funny.