Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[10.x] Do not bubble exceptions thrown rendering error view when debug is false (prevent infinite loops) #48732

Merged
merged 9 commits into from
Oct 18, 2023

Conversation

simensen
Copy link
Contributor

@simensen simensen commented Oct 15, 2023

I recently upgraded an application and forgot to update the layouts for the custom error pages. This resulted in the custom error pages throwing exceptions. In production, with app.debug set to false, this had horrible consequences.

If a 404 was requested, this triggered the rendering of the custom 404 error view. Rendering the custom 404 error view resulted in an exception. The same running application instance – still in the same request – would catch this and trigger rendering the custom 500 error view. Rendering that custom 500 error view resulted in an exception...

In my real-life situation, a single 404 error went from reporting one exception (the initial "missing file" exception) to an additional 19 exceptions for failing to render the custom error pages. All within one request.

The resulting error log went from 51 lines to 7,751 lines for the same situation.

This massive spike in log traffic caused a spike in my Papertrail usage. Had I not caught this as quickly as I did, it could have cost me a lot of money. As it is, I'm out about $30 from when I realized there was a problem until I solved it in my error views (~1 day).


My proposed fix wraps the error view rendering in try/catch.

If app.debug is true, it throws the new exception assuming the debug handler will render an appropriate message.

If app.debug is false, it ignores the exception and the fallback convertExceptionToResponse on the original exception is called exactly like it would if no custom error views were defined.

My initial implementation didn't distinguish whether the app was in debug. It treated all error view rendering errors the same and returned the Symfony response. However, the debug handling would actually be helpful in this case (it would tell you why the view threw an exception!) I added the config('app.debug') || throw $t to cover that case.

If it turns out my assumption about the debug handler catching the exception is incorrect, I'm happy to simplify this PR and not worry about that edge case.


This could be added to my own App\Exceptions\Handler, but this does not feel like a preference sort of thing. This is something the framework should be protecting people from, even if it is not something that may happen very often.

@driesvints driesvints changed the title Do not bubble exceptions thrown rendering error view when debug is false (prevent infinite loops) [10.x] Do not bubble exceptions thrown rendering error view when debug is false (prevent infinite loops) Oct 16, 2023
@timacdonald
Copy link
Member

Pretty sure the logic here is backwards.

If debug is true, we don't throw (which is when we probably do want to throw).

So if debug is false, like it is in prod, we will throw - which is the current behaviour and causes 9 exception reports.

Will verify with a test and push up.

@timacdonald
Copy link
Member

timacdonald commented Oct 17, 2023

Hey, @simensen, I'm made some small tweaks here that I would love you to verify make sense.

I found with your initial fix that in production (debug=false) I was still seeing the exception be reported serveral times.

Also, in development (debug=true) the exception was not reported at all.

Script to verify a prod environment with your original changes:

composer create-project laravel/laravel reporting-issue
cd reporting-issue
curl https://raw.githubusercontent.com/simensen/laravel-framework/0b5eece0b87d7d3466b1c645c943e9034daba925/src/Illuminate/Foundation/Exceptions/Handler.php > ./vendor/laravel/framework/src/Illuminate/Foundation/Exceptions/Handler.php
mkdir -p resources/views/errors
echo "<?php \$foo();" > resources/views/errors/404.blade.php > resources/views/errors/500.blade.php
sed -i "s#//#info('Reporting exception.', ['message' => \$e->getMessage()]);#" app/Exceptions/Handler.php
sed -i "s#APP_DEBUG=true#APP_DEBUG=false#" .env
tail -F storage/logs/laravel.log | grep "Reporting exception"

Then run php artisan serve in a different terminal tab and visit a page that does not exist. I am still seeing the following for a single request:

[2023-10-17 01:03:51] local.INFO: Reporting exception. {"message":"Undefined variable $foo"} 
[2023-10-17 01:03:51] local.INFO: Reporting exception. {"message":"Undefined variable $foo"} 
[2023-10-17 01:03:51] local.INFO: Reporting exception. {"message":"Undefined variable $foo"} 
[2023-10-17 01:03:51] local.INFO: Reporting exception. {"message":"Undefined variable $foo"} 
[2023-10-17 01:03:51] local.INFO: Reporting exception. {"message":"Undefined variable $foo"} 
[2023-10-17 01:03:51] local.INFO: Reporting exception. {"message":"Undefined variable $foo"} 
[2023-10-17 01:03:51] local.INFO: Reporting exception. {"message":"Undefined variable $foo"} 
[2023-10-17 01:03:51] local.INFO: Reporting exception. {"message":"Undefined variable $foo"} 
[2023-10-17 01:03:51] local.INFO: Reporting exception. {"message":"Uncaught ErrorException: Undefined variable $foo in /private/tmp/reporting-issue/storage/framework/views/8564abbef7e7ff1321ab6f849a4eb7b5.php:1

I pushed up some integration tests in a single commit so you can check them out and also tweaked the implementation in a different commit.

If a user hits a 404 (or other status code exception: 403, etc.) and there is an error rendering the error page they will see the following...

Screenshot 2023-10-17 at 11 32 08 am

@timacdonald timacdonald self-assigned this Oct 17, 2023
@simensen
Copy link
Contributor Author

@timacdonald Thanks for looking into this! You fully get what I'm going for here. You are correct that I had the boolean logic reversed, too. If you can move the expected exception code from the testItDoesNotCrashIfErrorViewThrowsWhileRenderingAndDebugFalse to the testItDoesNotCrashIfErrorViewThrowsWhileRenderingAndDebugTrue method, that should fix the original tests. You can either update the comments OR you can remove the comments altogether.

My original hunch that I might not have understood how this would interact with the error handling was correct. I'm glad you caught it. :)


Actually, I see you removed the unit tests. I don't think they were wrong or invalid; they just assumed erroneously when the exception should be thrown. I'm fine if you want to leave them out, but if you put them back in, the instructions for getting them to pass again are in the first paragraph above. :)

@timacdonald
Copy link
Member

timacdonald commented Oct 17, 2023

@simensen I've made that change. Thanks for raising this.

On a related note, to try and help save you in the future from a similar issue, framework related or not, you might also like to check out some features we recently added to help stop exception spikes:

@taylorotwell taylorotwell merged commit dda4e0f into laravel:10.x Oct 18, 2023
19 of 20 checks passed
timacdonald added a commit to timacdonald/framework that referenced this pull request Oct 24, 2023
…g is false (prevent infinite loops) (laravel#48732)

* Do not bubble exceptions thrown rendering error view when debug is false

* Add failing tests

* Only re-throw when debug mode it `true`

* Manually report exception if debug mode is `false`

* Remove unit tests

* lint

* Revert "Remove unit tests"

This reverts commit f4222ef.

* Fix original unit tests

* Fix paths for windows

---------

Co-authored-by: Tim MacDonald <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants