Prestashop: [1.7.6.3] HTTP ERROR 500 when clear cache without debug mode

[arafatx]

Describe the bug
I installed fresh install of the above prestashop version (1.7.6.3), then I disabled debug mode. When I click clear cache button, I got http error 500.

Things I have checked:
1) phppsinfo.php (everything is green)
2) Permission is OK.
3) I disabled cache, activate force compilation
4) Deleted the dev and prod from /var/cache folders

Error Logs from PHP specific to the error:

[Tue Jan 28 15:48:41.805769 2020] [proxy_fcgi:error] [pid 16014:tid 140671545485056] [client 42.188.32.248:0] AH01071: Got error 'PHP message: PHP Warning:  require(/home/user1/domains/example.com/public_html/www/var/cache/prod/Container1ykoff1/getPrestashop_UserProviderService.php): failed to open stream: No such file or directory in /home/user1/domains/example.com/public_html/www/var/cache/prod/Container1ykoff1/appProdProjectContainer.php on line 1635\nPHP message: PHP Fatal error:  require(): Failed opening required '/home/user1/domains/example.com/public_html/www/var/cache/prod/Container1ykoff1/getPrestashop_UserProviderService.php' (include_path='/home/user1/domains/example.com/public_html/www/vendor/pear/pear_exception:/home/user1/domains/example.com/public_html/www/vendor/pear/console_getopt:/home/user1/domains/example.com/public_html/www/vendor/pear/pear-core-minimal/src:/home/user1/domains/example.com/public_html/www/vendor/pear/archive_tar:.:/usr/local/php72/lib/php') in /home/user1/domainsexample.com/public_html/www/var/cache/prod/Container1ykoff1/appProdProjectContainer.php on line 1635\n', referer: http://www.example.com/www/ziralogin/index.php/configure/advanced/performance/?_token=0Gbw50szftJWKbLbYvsZ4Azbp7uCS52dlIr2-2v5JmE

Additional information
PrestaShop version: 1.7.6.3
PHP version: 7.2.27

Note that, if I enable debug mode, this problem doesn't occur.

TQ.

[khouloudbelguith]

Hi @arafatx,

After deleting the prod/ & dev/ folders manually, the permission of the /var/cache/ folder is NOK.
You need to give permission to this folder.

Thanks to check & feedback.

[arafatx]

Yes, I recheck the permission is ok.
I even tried 777, 755, and chmod (recursive) with the correct users on that folder. None working.

May I know, if you also notice the same behaviour with the clean installation with this version? The previous version doesn't have this problem. I tried 1.7.6.1 with clean installation doesn't have this issue.

Also, that error log generated immediately at the exact time when HTTP error 500 occurred. The first line that I have mentioned there.

[Perfecticus]

I also want to bump this.
I have experienced this since 1.7.6.1 and a few months.
Upgrading to 1.7.6.3 did not resolve it.
As I wrote on another, closed, issue.

@khouloudbelguith

I have been trying to find other people having the issues I'm having and this appears to match my case. I have had problems on 1.7.6.1 and still have issues after migrating to 1.7.6.3.

The cache appear to end up in an unrecoverable state quite often after being cleaned.
Some routines in prestashop clears cache files automatically, I havnt investigated exacly which,
but I assume saving seo/url-options does so, as I have encountered the non-recoverable 500 when saving that.

More frequently I encounter this when manually clearing the var/cache/prod when working with mail themes and templates. Apparently you need to clear the entire cache in order to generate new mail templates from mail theme, so that is what I have been doing.

Most of the time I encounter this bug and have to run 'rm -r var/cache/prod' a number of times before the shop starts working again.

Lately I have found a more reliable way and that is to 'rm -r var/cache/prod && service apache2 restart', which I have found to be working every time.

The problem/bug still is severe in a production environment.
The customers I host webshops for does not have server experience nor access and cannot perform the tasks I have had to do to restore the shops functionality in the case of a broken cache.

So I would urge the prestashop team to look into this and try harder to reproduce this issue.
Not sure if the problem only occurs when theres frequent traffic to the shop, i.e. multiple threads trying to load the shop when the cache is not initialized, but its a theory.

The exceptions I see in the log can refer to various files but usually one of these:
PHP Fatal error: require(): Failed opening required '/var/www/html/xxx/var/cache/prod/ContainerPemfwrx/getPrestashop_AccessDenied_ListenerService.php'
PHP Fatal error: require(): Failed opening required '/var/www/html/xxx/var/cache/prod/ContainerPemfwrx/getRouting_LoaderService.php'

I'm surprised not more people are facing this issue.
I have been getting it on development, staging and production servers for multiple shop installs.
Appears to only happen for production cache (dev mode off).

Best regards
Perfecticus

[khouloudbelguith]

@arafatx, @Perfecticus, it is Ok with PS1.7.6.3 fresh install
I attached a screen record
https://drive.google.com/file/d/1_-K6at5m_ZrkZjzsQGvUOYTtF4VSaQxn/view

Also, that error log generated immediately at the exact time when HTTP error 500 occurred.

The 500 Internal Server Error can be very frustrating because it is such a vague error. In addition to the error message text itself being vague, there are actually several different issues that can cause the 500 error message to appear.

Error Logs from PHP specific to the error:

[Tue Jan 28 15:48:41.805769 2020] [proxy_fcgi:error] [pid 16014:tid 140671545485056] [client 42.188.32.248:0] AH01071: Got error 'PHP message: PHP Warning:  require(/home/user1/domains/example.com/public_html/www/var/cache/prod/Container1ykoff1/getPrestashop_UserProviderService.php): failed to open stream: No such file or directory in /home/user1/domains/example.com/public_html/www/var/cache/prod/Container1ykoff1/appProdProjectContainer.php on line 1635\nPHP message: PHP Fatal error:  require(): Failed opening required '/home/user1/domains/example.com/public_html/www/var/cache/prod/Container1ykoff1/getPrestashop_UserProviderService.php' (include_path='/home/user1/domains/example.com/public_html/www/vendor/pear/pear_exception:/home/user1/domains/example.com/public_html/www/vendor/pear/console_getopt:/home/user1/domains/example.com/public_html/www/vendor/pear/pear-core-minimal/src:/home/user1/domains/example.com/public_html/www/vendor/pear/archive_tar:.:/usr/local/php72/lib/php') in /home/user1/domainsexample.com/public_html/www/var/cache/prod/Container1ykoff1/appProdProjectContainer.php on line 1635\n', referer: http://www.example.com/www/ziralogin/index.php/configure/advanced/performance/?_token=0Gbw50szftJWKbLbYvsZ4Azbp7uCS52dlIr2-2v5JmE

This error is a cache issue.

Thanks!

[Perfecticus]

Yea, you dont seem to catch the issue we're referring to.
My suspicion is that the cache fails to initialize if multiple requests are performed simultaneously when the cache is invalid.

What could be the issue here then, some conflict between caching mechanisms?
Rinsing cache directory and restarting apache makes the site work again.
Only deleting the cache directory usually leaves the shop in a non working state.

In var/log/prod.log this is printed when such an error occurs.

[2020-01-29 10:00:29] request.CRITICAL: Uncaught PHP Exception Symfony\Component\Debug\Exception\FatalErrorException: "Compile Error: require(): Failed opening required '/var/www/html/sampleshop/var/cache/prod/ContainerPemfwrx/getPrestashop_FiltersBuilder_ResolverService.php' (include_path='/var/www/html/sampleshop/vendor/pear/pear_exception:/var/www/html/sampleshop/vendor/pear/console_getopt:/var/www/html/sampleshop/vendor/pear/pear-core-minimal/src:/var/www/html/sampleshop/vendor/pear/archive_tar:.:/usr/share/php')" at /var/www/html/sampleshop/var/cache/prod/ContainerPemfwrx/appProdProjectContainer.php line 1636 {"exception":"[object] (Symfony\\Component\\Debug\\Exception\\FatalErrorException(code: 0): Compile Error: require(): Failed opening required '/var/www/html/sampleshop/var/cache/prod/ContainerPemfwrx/getPrestashop_FiltersBuilder_ResolverService.php' (include_path='/var/www/html/sampleshop/vendor/pear/pear_exception:/var/www/html/sampleshop/vendor/pear/console_getopt:/var/www/html/sampleshop/vendor/pear/pear-core-minimal/src:/var/www/html/sampleshop/vendor/pear/archive_tar:.:/usr/share/php') at /var/www/html/sampleshop/var/cache/prod/ContainerPemfwrx/appProdProjectContainer.php:1636)"} []
[2020-01-29 10:00:47] request.CRITICAL: Uncaught PHP Exception Symfony\Component\Debug\Exception\FatalErrorException: "Compile Error: require(): Failed opening required '/var/www/html/sampleshop/var/cache/prod/ContainerPemfwrx/getRouting_LoaderService.php' (include_path='/var/www/html/sampleshop/vendor/pear/pear_exception:/var/www/html/sampleshop/vendor/pear/console_getopt:/var/www/html/sampleshop/vendor/pear/pear-core-minimal/src:/var/www/html/sampleshop/vendor/pear/archive_tar:.:/usr/share/php')" at /var/www/html/sampleshop/var/cache/prod/ContainerPemfwrx/appProdProjectContainer.php line 1636 {"exception":"[object] (Symfony\\Component\\Debug\\Exception\\FatalErrorException(code: 0): Compile Error: require(): Failed opening required '/var/www/html/sampleshop/var/cache/prod/ContainerPemfwrx/getRouting_LoaderService.php' (include_path='/var/www/html/sampleshop/vendor/pear/pear_exception:/var/www/html/sampleshop/vendor/pear/console_getopt:/var/www/html/sampleshop/vendor/pear/pear-core-minimal/src:/var/www/html/sampleshop/vendor/pear/archive_tar:.:/usr/share/php') at /var/www/html/sampleshop/var/cache/prod/ContainerPemfwrx/appProdProjectContainer.php:1636)"} []

[khouloudbelguith]

@Perfecticus, did you use opcache? it could be similar to this ticket: https://github.com/PrestaShop/PrestaShop/issues/10998.

Thanks to check & feedback.

[Perfecticus]

@khouloudbelguith, indeed I do!

I think that might be the culprit here!
I did what seedsgallery suggested in ticket #10998
by adding

opcache.revalidate_freq = 0
opcache.validate_timestamps = 1
opcache.fast_shutdown = 0

To /etc/php/7.0/apache2/conf.d/10-opcache.ini

; configuration for php opcache module
; priority=10
zend_extension=opcache.so
opcache.revalidate_freq = 0
opcache.validate_timestamps = 1
opcache.fast_shutdown = 0

After doing so and restarting webserver I have not been able to reproduce the problem.
Tested clearing cache and loading site in a few other tabs simultaneously and still no issue.

I will continue to test and report back, should it occur again.
If this is the solution, perhaps these configurations could be defined in defines.inc.php as opcache is pretty standard today.

[khouloudbelguith]

@Perfecticus, this is not a PrestaShop issue but it is fixed on your server.
That's why the fixes were added to the docker image.

@arafatx, any news?

Thanks!

[arafatx]

Hello guys thanks a lot for pointing out about opcache. I indeed use opcache on my server. I'm using the suggested setting for opcache and the problem is gone. @Perfecticus @khouloudbelguith

[khouloudbelguith]

@arafatx, thanks for your feedback.
Since it is fixed, I will close the issue, feel free to open a new one when needed.

Thanks!