Glide \ guzzle causing timeouts & server crashes.

[stuartcusackie]

My staging server has a recent Statamic / Blade Directives build and it keeps crashing and producing 502 bad gateways. The server is still running with plenty of available resources but nginx stops responding. A simple nginx restart fixes it. UPDATE: It has been stable for 10 days now.

A few points:

• I am not using antlers I am using edalzell/statamic-blade directives. I have opened an issue there with a code sample: https://github.com/edalzell/statamic-blade/issues/49.
• The error seems to eminate from usage of the @glide directive, which calls Statamic\Tags\Glide::generate()
• The site is very fast in general and I cannot see any bottlenecks or bad loops.
• I can't replicate the error manually - It just happens over night. All images seem to be loading fine when browsing.
• The staging site gets quite a few spam requests from bots but nothing that shouldn't simply return a 404 error.
• It's possible that a @glide call was made to a file that doesn't exist, or maybe an local cache item made it's way to the server and caused confusion, but even so, shouldn't Glide just return an error quickly, rather than producing long running requests? I've only a basic unstanding of how all of that works.

Things I've tried:

• I've flushed the entire cache, but that did not solve it.
• I have enabled asset caching but that did not solve it.
• I have reinforced all calls to glide by checking that the files exist first, but that did not solve it.
• I have enabled PHP slow logs on requests that take over 30 seconds (example below).

PHP7.4-fpm.log Some requests are taking really long. This one took 36 seconds but there are others that are taking 100s+. Maybe the server was overloaded at this point. I enabled PHP slow logs on requests that take over 30 seconds to see if I could get any more detail (below).

[22-May-2021 08:32:55] WARNING: [pool www] child 71226, script '/home/forge/staging.mysite.com/public/index.php' (request: "GET /index.php") executing too slow (36.444137 sec), logging
[22-May-2021 08:32:55] NOTICE: child 71226 stopped for tracing
[22-May-2021 08:32:55] NOTICE: about to trace 71226
[22-May-2021 08:32:55] NOTICE: finished trace of 71226

PHP slow.log Below is matching slow log entry for the above (same process id). A problem with Guzzle's CurlHandler??

[22-May-2021 08:32:55]  [pool www] pid 71226
script_filename = /home/forge/staging.mysite.com/public/index.php
[0x00007ff406a17720] curl_exec() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/Handler/CurlHandler.php:44
[0x00007ff406a17680] __invoke() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/Handler/Proxy.php:28
[0x00007ff406a175d0] GuzzleHttp\Handler\{closure}() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/Handler/Proxy.php:48
[0x00007ff406a17520] GuzzleHttp\Handler\{closure}() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/PrepareBodyMiddleware.php:35
[0x00007ff406a17440] __invoke() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/Middleware.php:31
[0x00007ff406a17390] GuzzleHttp\{closure}() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/RedirectMiddleware.php:71
[0x00007ff406a172f0] __invoke() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/Middleware.php:63
[0x00007ff406a17250] GuzzleHttp\{closure}() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/HandlerStack.php:75
[0x00007ff406a171c0] __invoke() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/Client.php:331
[0x00007ff406a17070] transfer() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/Client.php:168
[0x00007ff406a16f90] requestAsync() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/Client.php:187
[0x00007ff406a16f00] request() /home/forge/staging.mysite.com/vendor/guzzlehttp/guzzle/src/ClientTrait.php:61
[0x00007ff406a16e80] head() /home/forge/staging.mysite.com/vendor/statamic/cms/src/Imaging/GuzzleAdapter.php:344
[0x00007ff406a16de0] head() /home/forge/staging.mysite.com/vendor/statamic/cms/src/Imaging/GuzzleAdapter.php:163
[0x00007ff406a16d60] has() /home/forge/staging.mysite.com/vendor/league/flysystem/src/Filesystem.php:57
[0x00007ff406a16ce0] has() /home/forge/staging.mysite.com/vendor/league/glide/src/Server.php:164
[0x00007ff406a16c70] sourceFileExists() /home/forge/staging.mysite.com/vendor/league/glide/src/Server.php:498
[0x00007ff406a16b60] makeImage() /home/forge/staging.mysite.com/vendor/statamic/cms/src/Imaging/ImageGenerator.php:150
[0x00007ff406a16ad0] generate() /home/forge/staging.mysite.com/vendor/statamic/cms/src/Imaging/ImageGenerator.php:94
[0x00007ff406a16a00] generateByUrl() /home/forge/staging.mysite.com/vendor/statamic/cms/src/Imaging/StaticUrlBuilder.php:74

laravel.log I can see lots of error blocks like below. I have no idea why production.ERROR appears so many times. I can't be 100% sure that these errors are directly connected to the timeouts but it's a strange coicidence at least.

I've caught these exceptions in Laravel's Exception hander and logged the request details. There was nothing unsual in there, just bot requests for pages and files that don't exist.

[2021-05-22 08:32:48] production.ERROR:   
[2021-05-22 08:32:48] production.ERROR:   
[2021-05-22 08:32:48] production.ERROR:   
[2021-05-22 08:32:49] production.ERROR:   
[2021-05-22 08:32:49] production.ERROR:   
[2021-05-22 08:32:49] production.ERROR:   
[2021-05-22 08:32:49] production.ERROR:   
[2021-05-22 08:32:49] production.ERROR:   
[2021-05-22 08:32:49] production.ERROR:   
[2021-05-22 08:32:49] production.ERROR:   
[2021-05-22 08:32:49] production.ERROR:   
[2021-05-22 08:32:50] production.ERROR:   
[2021-05-22 08:32:50] production.ERROR:   
[2021-05-22 08:32:50] production.ERROR:   
[2021-05-22 08:32:50] production.ERROR:   
[2021-05-22 08:32:50] production.ERROR:   
[2021-05-22 08:32:50] production.ERROR:   
[2021-05-22 08:32:50] production.ERROR:   
[2021-05-22 08:32:51] production.ERROR:   
[2021-05-22 08:32:51] production.ERROR:   
[2021-05-22 08:32:51] production.ERROR:   
[2021-05-22 08:32:51] production.ERROR:   
[2021-05-22 08:32:51] production.ERROR:   
[2021-05-22 08:32:51] production.ERROR:   
[2021-05-22 08:32:51] production.ERROR:   
[2021-05-22 08:32:51] production.ERROR:   
[2021-05-22 08:32:52] production.ERROR: Uncaught Statamic\Exceptions\NotFoundHttpException in /home/forge/staging.mysite.com/vendor/statamic/cms/src/Imaging/ImageGenerator.php:152
Stack trace:
#0 /home/forge/staging.mysite.com/vendor/statamic/cms/src/Imaging/ImageGenerator.php(94): Statamic\Imaging\ImageGenerator->generate()
#1 /home/forge/staging.mysite.com/vendor/statamic/cms/src/Tags/Glide.php(132): Statamic\Imaging\ImageGenerator->generateByUrl()
#2 /home/forge/staging.mysite.com/vendor/statamic/cms/src/Tags/Glide.php(103): Statamic\Tags\Glide->generateImage()
#3 [internal function]: Statamic\Tags\Glide->Statamic\Tags\{closure}()
#4 /home/forge/staging.mysite.com/vendor/laravel/framework/src/Illuminate/Collections/Collection.php(642): array_map()
#5 /home/forge/staging.mysite.com/vendor/statamic/cms/src/Tags/Glide.php(116): Illuminate\Support\Collection->map()
#6 /home/forge/staging.mysite.com/vendor/edalzell/blade-directives/src/Directives/Glide.php(26): Statamic\Tags\Glide->generate()
#7 /home/forge/staging.mysite.com/vendor/laravel/framework/src/Ill {"exception":"[object] (Symfony\\Component\\ErrorHandler\\Error\\FatalError(code: 0): Uncaught Statamic\\Exceptions\\NotFoundHttpException in /home/forge/staging.mysite.com/vendor/statamic/cms/src/Imaging/ImageGenerator.php:152
Stack trace:
#0 /home/forge/staging.mysite.com/vendor/statamic/cms/src/Imaging/ImageGenerator.php(94): Statamic\\Imaging\\ImageGenerator->generate()
#1 /home/forge/staging.mysite.com/vendor/statamic/cms/src/Tags/Glide.php(132): Statamic\\Imaging\\ImageGenerator->generateByUrl()
#2 /home/forge/staging.mysite.com/vendor/statamic/cms/src/Tags/Glide.php(103): Statamic\\Tags\\Glide->generateImage()
#3 [internal function]: Statamic\\Tags\\Glide->Statamic\\Tags\\{closure}()
#4 /home/forge/staging.mysite.com/vendor/laravel/framework/src/Illuminate/Collections/Collection.php(642): array_map()
#5 /home/forge/staging.mysite.com/vendor/statamic/cms/src/Tags/Glide.php(116): Illuminate\\Support\\Collection->map()
#6 /home/forge/staging.mysite.com/vendor/edalzell/blade-directives/src/Directives/Glide.php(26): Statamic\\Tags\\Glide->generate()
#7 /home/forge/staging.mysite.com/vendor/laravel/framework/src/Ill at /home/forge/staging.mysite.com/vendor/statamic/cms/src/Imaging/ImageGenerator.php:152)
[stacktrace]
#0 {main}
"} 

Statamic version: 3.1.14 PHP version: 7.4 Existing Laravel app

Will update if I learn any more. Cheers.

[jackmcdade]

I'm going to close this as it was stable for 10 days many months ago. Maybe just an issue with one of that packages that has been updated. Feel free to comment so we can reopen if this is still an ongoing thing!