Image::Convert() shows error in frontend instead of returning null

[xini]

Module version(s) affected

2.3.0

Description

When the conversion of an image fails, the error logger shows the error output on the page.

I think the conversion should fail silently and just log the error, not show it on the page.

How to reproduce

add

throw new FileConverterException('test error');

to the first line of InterventionImageFileConverter::convert()

Possible Solution

use default logger instead of error logger in https://github.com/silverstripe/silverstripe-assets/blob/2/src/ImageManipulation.php#L728

$logger = Injector::inst()->get(LoggerInterface::class);

instead of

$logger = Injector::inst()->get(LoggerInterface::class . '.errorhandler');

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)

[GuySartorelli]

Couple of questions:

1. Under what real world circumstances are you getting this error? When this was implemented, IIRC the assumption was that most (if not all) failures to convert files would be because of some misconfiguration (no converter for that file type, for example).
   Those sorts of errors should result in hard failures, and developers should resolve them.
2. What would you have happen instead? Should we just pretend the conversion was never attempted and use the original file, or just return null?
   • In the former case, that could result in e.g. displaying a video instead of a thumbnail which at best is not what the developer intended - or download links could download the wrong file, or you could have a broken thumbnail because it's trying to show a pdf where an image goes, etc etc.
   • In the latter case, you'd have links with empty href attributes, images outright missing from the page or being broken because there's no src, etc.

[xini]

1. This occurs for example when the original file doesn't exist, or if the third party library doing the conversion fails, e.g. with my converter from PDF to image for thumbnails (https://github.com/innowebau/silverstripe-pdf-image-converter) using imagick.
   Also, yes, I agree that these failures should be addressed by the dev, but logging them is enough IMO.

2. Like all other image manipulations this should just return null and fail silently. For example, when you do a $Image.Pad(200,200) and something goes wrong, it returns null. At the moment, Convert() is the only file manipulation method that results in a hard failure.

(Apart from that, the comment for ImageManipulation::Convert() states

@throws FileConverterException If the conversion fails and $returnNullOnFailure is false.

, but $returnNullOnFailure does not exist anywhere in the Silverstripe code.)

[GuySartorelli]

This occurs for example when the original file doesn't exist

How do you get into that situation?

or if the third party library doing the conversion fails

What's the reason for the failure? Is it some intermittent problem, or is it a misconfiguration, or something else?

(Apart from that, the comment for ImageManipulation::Convert() states@throws FileConverterException If the conversion fails and $returnNullOnFailure is false., but $returnNullOnFailure does not exist anywhere in the Silverstripe code.)

That's actually a good argument. Looking back at the PR: #595 (comment) The $returnNullOnFailure param was removed intentionally, and the intention was indeed that this should return null.

use default logger instead of error logger

Is the error logger somehow causing an error to be thrown? Will using the default logger still log to all places that the error logger logs to?

[xini]

This occurs for example when the original file doesn't exist

How do you get into that situation?

You tell me. ;) I have some older sites that have been upgraded a few times over time. It just happens, I guess.

or if the third party library doing the conversion fails

What's the reason for the failure? Is it some intermittent problem, or is it a misconfiguration, or something else?

The reason doesn't matter. The converter throws a FileConverterException in any case, which triggers the error.

Maybe there should be two different exceptions to be thrown for intermittent and permanent errors?

(Apart from that, the comment for ImageManipulation::Convert() states@throws FileConverterException If the conversion fails and $returnNullOnFailure is false., but $returnNullOnFailure does not exist anywhere in the Silverstripe code.)

That's actually a good argument. Looking back at the PR: #595 (comment) The $returnNullOnFailure param was removed intentionally, and the intention was indeed that this should return null.

right. that would make sense and would be in line with all other manipulations.

use default logger instead of error logger

Is the error logger somehow causing an error to be thrown? Will using the default logger still log to all places that the error logger logs to?

The default logger logs to the log file. the error logger halts execution and AFAIK there is no way to redirect it to just a log file.

I don't understand why there are two loggers anyway.

[elliot-sawyer]

I don't understand what is wrong with the submitted pull request. Not throwing an exception, and returning null, sounds like a sensible solution

I get these errors when a user uploads a file with a long name within upload limits - the resampled filename, however, is too long for the filesystem

League\Flysystem\UnableToWriteFile

Unable to write file at location: <truncated> Failed to open stream: File name too long

In my opinion, that's not a developer problem. It's a content issue and front-end users bear that impact.

Silently logging and returning nothing should be the way to go. Developers can still be alerted and fix the problem when there's time and budget to do so. In this case, developers can simply tell the content author to rename their file and try again.

[GuySartorelli]

The problem with the submitted pull request is there's no explanation of why the logger that's currently being used is incorrect. It feels like there's an underlying problem with that logger which is being ignored.

If that logger should not be used directly, then documentation needs to be updated to explicitly mention that (and give the reason why), and we need to check if we're incorrectly using it anywhere else - not just this one location.

[andreaspiening]

I am experiencing this too.

I think there is another serious context, in which this error is triggered: the combination of shortcode parsing and image conversion in a custom DBFile_Image.ss as described here.

The conversion in DBFile_Image.ss works well, when we use an image in a template and do a conversion, e.g. <a href="...">$image</a>. The view makes sure the image object exists in the current scope as well as the underlying file and only enters image scope and calls convert from the custom DBFile_Image.ss if both are true.

In the shortcode parser this is not the case, e.g. you have Page::Content that contains a shortcode to an existing image record with a missing file. Without checking if the file exists and a conversion can occur, the conversion fails hard instead of just omitting the image.

Reproduction steps:

• add existing image to Page::Content in the CMS, save and publish
• create 'Improve customisability of rendered images' example
• make sure you have no pre-resampled versions of the image and template cache is flushed
• remove the image file from the assets folder
• render page

Expected result: missing image

Actual result: server error

This can be mitigated by testing if the file exists in the DBFile_Image.ss template, e.g.

<picture>
    <% if $Me %><source srcset="$Convert('webp').Link" type="image/webp"><% end_if %>
    <img $AttributesHTML >
</picture>

I find this hack ugly because it is not consistent with the way we handle resizing of corrupt Images and I'd like to avoid it if we had a better solution.

[xini]

@GuySartorelli

The problem with the submitted pull request is there's no explanation of why the logger that's currently being used is incorrect. It feels like there's an underlying problem with that logger which is being ignored.

If that logger should not be used directly, then documentation needs to be updated to explicitly mention that (and give the reason why), and we need to check if we're incorrectly using it anywhere else - not just this one location.

The problem with using that logger is that it results in a hard server error, instead of omitting the image.

The issue with the different loggers as well as any documentation issues are not part of the submitted pull request. If there are such issues, the submitted pull request is not meant to - and shouldn't - address those.

Looking back at the PR: #595 (comment) The $returnNullOnFailure param was removed intentionally, and the intention was indeed that this should return null.

Do you want me to submit a pull request to return null then and not log the error at all?

[GuySartorelli]

The problem with using that logger is that it results in a hard server error,

Right... but is it supposed to? If it isn't supposed to, that's an underlying bug which should be addressed directly rather than worked around.. If it is supposed to, then as I mentioned any fix should include checking if this logger is used incorrectly anywhere in the codebase and updating all such misuse, as well as documenting that.

[GuySartorelli]

Do you want me to submit a pull request to return null then and not log the error at all?

The error must be logged, so no.

[xini]

The problem with using that logger is that it results in a hard server error,

Right... but is it supposed to? If it isn't supposed to, that's an underlying bug which should be addressed directly rather than worked around.. If it is supposed to, then as I mentioned any fix should include checking if this logger is used incorrectly anywhere in the codebase and updating all such misuse, as well as documenting that.

I don't know and that's not part of this issue/PR.

[xini]

Do you want me to submit a pull request to return null then and not log the error at all?

The error must be logged, so no.

I agree. And to make the convert() method behave in line with all other image/file processing methods, the error should be logged using the 'normal' error logger and null returned, as per the submitted PR.

Whether you want to create a new issue to check if the blocking error logger should be removed/documented etc, is up to you.

[GuySartorelli]

I don't know and that's not part of this issue/PR.

I disagree. This issue points out a symptom. The bug may be wider than this one symptom. If that's the case, the wider bug should be identified and fixed, rather than treating a single symptom.
I won't accept a PR that doesn't either

1. show that this is not symptomatic of a wider bug, or
2. resolve the wider bug

If I'm able to find some time to investigate this further personally, I will do so. In the meantime, if someone else wants to submit a PR that fixes it they'll first need to do some investigation to identify whether this is a symptom of a wider bug or not.

[xini]

The issue at hand is that the convert() method behaves differently to other image manipulation methods. This is resolved by logging the error using the normal error logger and returning null.

The only other locations in core where LoggerInterface::class . '.errorhandler' is used are Member and the LostPasswordHandler, when the reset email couldn't be sent. That kind of deserves a hard error (even though I would prefer a 'nice' looking error page to the SS blue screen).

Whether or not there is a wider bug/issue in the setup of the logging system, and whether or not a hard error should show a nice error page or a blue screen, really isn't part of this issue/PR!

[GuySartorelli]

The issue at hand is that the convert() method behaves differently to other image manipulation methods.

Yes. That is a symptom of what looks like a wider bug. I understand you want this specific symptom fixed. The correct way to do that is to fix the wider bug (or show there isn't one but I think there is).

I'm going to step away from this issue for now, since we're retreading the same points over and over again.

[GuySartorelli]

I've been able to wrest some time to look into this. It seems like the current situation is:

• The LoggerInterface::class . '.errorhandler' logging service was originally intended to only handle uncaught exceptions and PHP errors - it was not intended to be logged to directly. Because of this, errors logged to this service show an error message in the browser and in CLI because they indicate something unexpected went wrong.
• The "default logger" (i.e. the LoggerInterface::class logging service) was intended to be used for logging directly
• The logging and error handling documentation does say you can use LoggerInterface::class to log directly, and the "Configuring error logging" does show examples for that logger. But there's no warning against logging directly with LoggerInterface::class . '.errorhandler' or detailing what the specific purpose of that logger is - nor does the advice say to set up handlers for both services. This means developers likely have set up handlers for one or the other, and not both. In my case I've set a handler for the .errorhandler service but not the default logger.
• SS_ERROR_LOG is mentioned, but seems to only get registered on the default logger and not the .errorhandler service.

tl;dr it's not made clear in the documentation what the difference and purposes are for the two logger services, or when to register handlers for one or the other. It is likely many developers have set up a handler for one of these services but not the other.

I think an appropriate course of action is:

1. No action for CMS 5.3 - changing where things are logged in a patch release seems like it would result in errors not being logged for people who haven't set up handlers for both logging services.
2. For CMS 5.4, stop logging directly with the .errorhandler service. @xini has already looked into where it's used and found 2 usages beyond the one this issue was originally raised for, so thankfully the affected surface (at least in core code) isn't too wide.
3. For CMS 5.4 if the SS_ERROR_LOG environment variable is set, register the handler for both logging services.
4. For CMS 5.4 add a note about this change to the changelog, and encourage developers to:
   • Add a handler for both logging services, not just one
   • Check scenarios where they are logging things, and make sure they're using the default logging service not the error handler service
5. For CMS 5.4 improve the logging and error handling docs as well as any other docs that mentions logging (if any) to:
   • clearly indicate the purpose of the two handlers
   • promote adding a handler to BOTH loggers
   • explicitly warn against logging directly with the .error-handler logger.

It would probably be sensible to add a new phpstan rule to https://github.com/silverstripe/silverstripe-standards to avoid logging to the .error-handler service directly in the future.

@xini @silverstripe/core-team Does this seem sensible?

[GuySartorelli]

In the meantime, in CMS 5.3 to resolve many of the cases where this is causing a problem, it would be sensible if Convert() returns null without logging if there is no actual file to convert.

[xini]

@xini @silverstripe/core-team Does this seem sensible?

@GuySartorelli yes

In the meantime, in CMS 5.3 to resolve many of the cases where this is causing a problem, it would be sensible if Convert() returns null without logging if there is no actual file to convert.

@GuySartorelli exactly.

[kinglozzer]

I’ve skim read the silverstripe/silverstripe-framework#8241 (PR) and silverstripe/silverstripe-framework#8044 (issue) which introduced the separate loggers for some extra context. I had a very long comment written out which after re-reading I’ve essentially boiled down to “I agree” 😝 so I’ve deleted all that and just have the following notes.

The logging and error handling documentation does say you can use LoggerInterface::class to log directly, and the "Configuring error logging" does show examples for that logger. But there's no warning against logging directly with LoggerInterface::class . '.errorhandler' or detailing what the specific purpose of that logger is - nor does the advice say to set up handlers for both services.

There are only a few mentions of .errorhandler in the docs, mostly about disabling it, so at least it doesn’t suggest that people should log directly to it. Though we could copy the Core error handler for system use comment to all mentions of it just to discourage anyone who stumbles upon it from logging directly to it.

I suspect the docs are probably from before the .errorhandler was split out, so I wonder if most of them should actually reference .errorhandler now. I think we should also restructure that doc to not prioritise custom logging above the core stuff, maybe a structure more like:

• “Customising core error logging”
  This is the most common thing people will want to do, we can show them how to attach extra handlers to the .errorhandler logger, how to disable it if they really want etc.
• “Triggering errors”
  I see this as just a short section which encourages people to throw exceptions and use user_error() etc to take advantage of the core logger setup, rather than jump into anything bespoke unless they really need it.
• “Setting up your own logging”
  This would show how to configure a logger from scratch, how to call a logger with Injector etc. Basically all the bespoke stuff.

As an aside to this, the suffix of .errorhandler is really confusing when it’s for a logger instance, not a handler. Would Injector aliases let us rename it to .corelogger with an alias from the .errorhandler for BC?

[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.

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")

The latter would raise the misconfiguration issue, without risking the loss of error messages (they'd just show up as warnings with a prefix rather than info)

For CMS 5.4 if the SS_ERROR_LOG environment variable is set, register the handler for both logging services.
or CMS 5.4 add a note about this change to the changelog, and encourage developers to: Add a handler for both logging services, not just one

I would check whether this is actually needed. Instead, manipulating errorhandler should be done only when people want to alter what is send in the HTTP response in the event of an error - either the dev mode response with some details, or the terse "there has been an error" response in production

[xini]

I'm sorry, but I don't quite follow. The mix of errorhandler and logger is really confusing.

I can log something with different 'urgency' to the logger, like

Injector::inst()->get(LoggerInterface::class)->debug('Query executed: ' . $sql);
Injector::inst()->get(LoggerInterface::class)->error('Something went wrong, but let\'s continue on...');

The log then gets directed to a target/handler that is set to drop <warning messages:

$logger = Injector::inst()->get(LoggerInterface::class);
$logger->pushHandler(new StreamHandler($this->basePath . '/' . $errorLog, Logger::WARNING));

and I can configure a different handler for e.g. <error messages:

$handler = new NativeMailerHandler(
    $recipients,
    $subject,
    Email::config()->get('admin_email'),
    Logger::ERROR
);
$handler = $handler->setContentType('text/html');
$handler = $handler->setFormatter(new DetailedErrorFormatter());
$logger->pushHandler($handler);

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.

• How does .errorhandler fit into this?
• Why does it halt execution?
• Why does it not show the normal 500 error page but that error blue screen, even in production?

(And also - again - this discussion should be held in silverstripe/silverstripe-framework#11511, not here. The issue here is simply that the wrong logger is used and null should be returned by the convert() method.)