Causes 500 Error Page To Render Twice

[leepowelldev]

Silverstripe Framework Version: 4.7.2 Silverstripe Sentry Version: 3.0.7

When using this package it causes my 500 error pages to render twice, in dev this is hardly noticeable, however in production, when the friendly error page is shown then it leads to some interesting results of the error-500 page displaying twice stacked above each other.

[phptek]

I have no idea how a logging system like Sentry could cause something like this. Is there any further info you can pass on about this?

Can you define exactly what "renders twice" means? Can you provide a screenshot please?

What I'd do is as follows:

• Uninstall phptek/sentry
• Clear cache + dev/build (precautionary measure, helps me setup a test harness to match your own setup)
• Re-run whatever scenario you have where your page "renders twice"

If the problem persists, it is unrelated to phptek/sentry, if it does, just update the ticket and I'll take a look.

[leepowelldev]

Hi.

It took me a fair while to track the issue down to this plugin. I went through all my plugins and systematically removed and reinstalled them. This one was definitely the culprit. Not sure why/how but somehow it triggers Silverstripe to render the error-500 page twice before returning it as a response.

I’ll get some screenshots tomorrow to show you what I mean. But essentially you can see what I mean by putting the site into live mode, and putting anything in the code that’ll trigger an error.

I think I’ve got a demo repo knocking around too so I can send you a link to that.

Thanks

[leepowelldev]

Here are two screen shots from a brand new install, just with this plugin added ... I got it to error by adding an argument to the init method from PageController.

It works as expected when the plugin is uninstalled:

[dcentrica]

Is the error that's displayed in the screenshots, one that you think is caused by this module or something you're using to test the module with, by sending an "artificial" error to Sentry? If the latter, that's an "Error" which is an instance of Throwable which TBH, I don't know much about in the context of Sentry.

To be a fair test, can you add throw new \Exception("TEST"); into PageController::init() or somewhere similar and see what happens please?

If it's happening as a result of this module, then that's something altogether weird. In that case, I'll need all of the following:

• The method you use to install Silverstripe, e.g. composer create-project silverstripe/recipe-cms ^4.7.2
• PHP version
• Composer version

Once I have those details, I can have a game stab at reproducing your setup.

[leepowelldev]

All I know is that when this plugin is installed I'm getting the error page rendering twice. I don't think this is anything to do with logging the exception to sentry ... I think it's something to do with how it's hooked in via monolog (or similar). I've not had time to dig into the code to see what it going on.

I have added the throw new \Exception("TEST"); into PageController::init() and get the following in both live and dev mode:

[leepowelldev]

I have shared my setup with you here: https://github.com/leepowelldev/silverstripe-phpteksentry

The install proceedure was via Silverstripes documentation:

composer create-project silverstripe/installer my-project

PHP version is 7.4, as per the Docker file in the project, and Composer version is 2.0.9

[phptek]

Thanks for sharing the setup - but, while working on another project I noticed that I saw two error messages for an unrelated exception, and remembered your bug. I uninstalled the module and there it was, just one error message! Re-installing it, two again.

But that's in "dev" mode. I set the project into "test" mode and there again, I saw the standard server-error page displayed twice!

[CONFIRMED]

Thank you for taking the time to provide all your details, I'll have a crack at fixing this as soon as I get some time.

[phptek]

UPDATE: This does not occur in version 1.x of the module with Silverstripe 3.7.

[phptek]

UPDATE: This occurs in the 3.x version of the module, and:

• Removing the YML config that basically enables the module's functionality: Still Occurs
• Removing the module entirely: No longer Occurs
• Removing the Monolog handler registration YML in the module: No longer occurs

I thought that this may have something to do with Monolog's bubbling behaviour, but disabling this in SentryHandler made no difference.

[phptek]

This took some serious tracking down. Fixed in 4.0.0-alpha3.

[phptek]

Seems I was a little hasty...

[phptek]

Looks like vendor/silverstripe/framework/src/Logging/DetailedErrorFormatter.php::output() is being called twice.

[phptek]

I have dug into this and I'm convinced something's up with the Sentry package itself, or more likely how this module is using it. I've refactored the module a lot in v4 to make following logic easier. But I still cannot nail down where the problem really lies.

• I also installed silverstripe/raygun which is setup very similarly againt Monolog in YML config = single error displayed.
• Debugging in vendor/silverstripe/framework/src/Logging/DetailedErrorFormatter.php::output() and vendor/silverstripe/framework/src/Dev/DebugView.php::renderSourceFragment(), renderHeader() as well as renderError() both of these are called twice.

In a Dev environment, the both errors are actually different messages, but appear to result from the same exception.

Next Steps:

Re-install silverstripe/raygun and assert that:

1. Its Monolog handler is indeed being used then
2. those two files and three methods mentioned above, are still being called twice. If they are, then silverstripe/raygun is somehow managing to work around that fact, if they're not, then somehow, this module is in some way re-triggering SIlverstripe's logging routine(s).

[phptek]

Re-opening. It was auto-closed by GH

[kinglozzer]

I encountered this issue on a project (not using this module directly, but was using it for reference!) and found that it was caused by Sentry’s default listener integrations that are automatically activated. For me, the fix was to pass in the following option when creating the client:

$options['default_integrations'] = false;

[kinglozzer]

Actually that option also removes the HTTP request info for example, so if you rely on that you might need to instead use the integrations option to enable/disable specific ones (I suspect FatalErrorListenerIntegration, ExceptionListenerIntegration and ErrorListenerIntegration are causing this)

[robertvanlienden]

Had some contact with @kinglozzer on SilverStripe Users Slack.

I've found out that the second "alert" (the one that I assume to trigger the second error-page) gets triggered when ExceptionListenerIntegration OR ErrorListenerIntegration are enabled.

Tried to only disable this integrations to get HTTP request info inside the Sentry logs. But the HTTP Request info is only added when I enable ExceptionListenerIntegration :disappointed:

[jonom]

I have noticed that the error that the module sends has user ID attached but does not have a stack trace, whereas the Sentry sent one does not have a user ID but does have a stack trace. Is that the same for others?

[lekoala]

i have the same issue and indeed i suspect that the default integration causes the error

[lekoala]

So after (quite) a bit of digging, turns out this is causing the issue

https://github.com/getsentry/sentry-php/blob/51cec5c6ee768a71cfdd4d4316528c381172c62d/src/ErrorHandler.php#L419-L423

Basically, sentry sdk is rethrowing the error after it has been logged

Then, this is caught by Monolog's own ErrorHandler

https://github.com/Seldaek/monolog/blob/a4471eb05bb32400bf408972d5162dccc49f46c5/src/Monolog/ErrorHandler.php#L233-L256

which, interestingly enough, changes its level along the way

basically, i think it's down to the fact that silverstripe doesn't catch all exceptions and that the error-handler is handling things twice (once as a regular exception, once as a fatal error)

https://github.com/silverstripe/silverstripe-framework/blob/c2199ff88be99f3944c02f59b21c8eec6adc14fb/_config/logging.yml#L16-L17

and here is a little screenshot with the two records:

• the first one is the regular exception
• the second one is the fatal error as logged by monolog fatal handler

and if you are like me and that the "Uncaught Exception Exception" is driving you crazy (because, why "Exception Exception") this is due to

https://github.com/Seldaek/monolog/blob/a4471eb05bb32400bf408972d5162dccc49f46c5/src/Monolog/ErrorHandler.php#L189

[lekoala]

One way of fixing this is to modify the HTTPOutputHandler as done here:

https://github.com/silverstripe/silverstripe-framework/commit/c26576bb1b9ce6ad18b1c52de2c941e41711740c

but since it's only causing issues when a third party module is installed, i'm not sure how willing the core team would be to merge this :) maybe @kinglozzer has an opinion on this ?

[kinglozzer]

Yeah I’m not sure it makes sense to work around this in core when it’s really only an issue with Sentry. I can’t remember this too clearly now, but it looks like we worked around this by just registering the integrations manually without the affected fatal/exception listeners:

https://github.com/bigfork/silverstripe-sentry-handler/blob/master/src/SentryHubFactory.php#L39-L50