v3.3 — 504 errors for some collection indexes (indices? ugh)

[theutz]

Bug description

The problem

When viewing collections in v3.3, some of them don't load properly. I have ~16 collections, and two of them get stuck in a state like this:

This collection shouldn't be empty. It should contain roughly 30 entries in the default site, as well as other multi-site entries.

Additional context

DevTools

DevTools logs two identical requests to http://admix-service-corporate.test/cp/collections/pages/entries?sort=title&order=asc&page=1&perPage=50&search=&filters=eyJzaXRlIjp7InNpdGUiOiJkZWZhdWx0In19&columns=title,site,slug. The first one usually gets cancelled right away. The second one hangs for about 30 seconds before returning a 504 timeout.

Tinker

I've attempted to recreate very roughly the queries performed using Tinker with \Statamic\Facades\Entry::query()->where('collection', 'pages')->get(), and it doesn't seem to have a problem loading the data.

Telescope

Telescope seems to notice the requests for the page at GET /cp/collections/pages, but it never logs any 504 responses for the request to http://admix-service-corporate.test/cp/collections/pages/entries?sort=title&order=asc&page=1&perPage=50&search=&filters=eyJzaXRlIjp7InNpdGUiOiJkZWZhdWx0In19&columns=title,site,slug, despite what I see in the browser devtools.

PHP-FPM

When I run the request more than once (by refreshing while it's still loading), PHP-FPM logs that it's run out of it's workers (5 have been allocated).

How to reproduce

I've tried to reproduce this issue in some minimal repo setups, but with no success.

Logs

No response

Versions

Statamic 3.3.1 Pro
Laravel 9.5.1
PHP 8.1.2
aryehraber/statamic-impersonator 2.4.1
goldnead/statamic-collapse-fieldtype 1.0.4
handmadeweb/statamic-laravel-packages 1.0.2
jacksleight/statamic-bard-mutator 1.0.3
jacksleight/statamic-bard-texstyle 0.2.0
jacksleight/statamic-focal-link 0.2.3
rias/statamic-color-swatches 2.0.5
statamic/collaboration 0.4.0
statamic/seo-pro 3.1.0
theutz/statamic-ant-design-icons 1.0.0
webographen/statamic-widget-cache-controller 1.0.1
webographen/statamic-widget-continue-editing 1.0.1

Installation

Fresh statamic/statamic site via CLI

Additional details

I haven't been able to load many of these pages in the front-end, either. I'm assuming that's due to changes in the Antlers runtime, but I haven't really got a chance to debug them since I can't even see them in the CP anymore.

[theutz]

Also, looking at the devtools again, I noticed that the first cancelled request has a perPage query value of 50, and the second request (that times out) has a perPage query value of 500. Don't know if that makes a difference.

[duncanmcclean]

How many entries do you have?

[theutz]

29 in one of the failing collections, and 21 in the other. So, not very much, I'd suppose. Perhaps it's worth mentioning that these are the only two collections that have more than 9 entries in them so far. Not sure if that'd make a difference.

[theutz]

Also, when I use an API client to run the same request in 3.2 (after downgrading), everything is 200 OK.

[duncanmcclean]

Is there anything in your logs file (storage/logs)?

[theutz]

Unfortunately, no. That's why I went rummaging around in the php-fpm logs. There didn't seem to be any trace of what's causing the problem in the laravel logs. Or anywhere else for that matter. No exceptions thrown.

[theutz]

The only signal I get that something's going wrong is this message (logged via spatie/ray):

Return type of Statamic\Fields\ArrayableString::jsonSerialize() should either be compatible with JsonSerializable::jsonSerialize(): mixed, or the #[\ReturnTypeWillChange\] attribute should be used to temporarily suppress the notice in <rootDir>/vendor/statamic/cms/src/Fields/ArrayableString.php on line 39.

[theutz]

But it only shows up as a warning.

[duncanmcclean]

Are you using a Code fieldtype anywhere?

[theutz]

I am in one of the collections, but not in the other.

[duncanmcclean]

If you comment it out in your blueprint, does it work?

[theutz]

Doesn't seem to make a difference. I tried clearing all the caches after the change, too, and didn't make a difference.

[duncanmcclean]

Okay, I'm out of ideas.. ArrayableString was mentioned in the error message and is used in the Code fieldtype so thought it was worth trying.

Hopefully someone else will have some ideas.

[theutz]

This time I enabled the DebugBar, and I noticed a few of these warnings:

[11:42:12] LOG.warning: round(): Passing null to parameter #1 ($num) of type int|float is deprecated in /Users/michaelutz/Sites/admix-service-corporate/vendor/statamic/cms/src/Assets/AugmentedAsset.php on line 145

[theutz]

Okay, I'm out of ideas.. ArrayableString was mentioned in the error message and is used in the Code fieldtype so thought it was worth trying.

Hopefully someone else will have some ideas.

No worries! Thanks, Duncan!

[edalzell]

Are you able to provide a public repo that reproduces this error?

[theutz]

Unfortunately, I can't seem to get to the heart of what's actually causing the problems. The logs don't have any useful information, and I can't tease out what conditions exactly are making it happen. If you want, I can provide a private copy of the code base for your inspection.

[christophstockinger]

I have the same problem when I want to call a collection. I get a timeout every time. Neither logs nor any errors in Telescope.

What's funny it also doesn't load any resources but fail already when calling the page http://xxx.test/collections/{name} directly.

[christophstockinger]

Okay I tried around some more to find the cause, but unfortunately I can only say that there are also other pages where the error 504 Bad Gateway Timeout occurs via Laravel Valet. Also the PHP-Artisan webserver can't open the collection page.

For this reason I can't recommend to update to version 3.3.* at the moment.

[duncanmcclean]

@christophstockinger How many entries do you have - lots?

[christophstockinger]

Over 100 entries in each collection

[elijahworkz]

I've updated to 3.3 from 3.2 and immediately noticed an increase in loading time of some collections. While I don't have 504 errors, I see same notices and my loading time increased dramatically.

In 3.2 same request took 2646ms and after upgrade 12509ms

One thing I noticed is the dramatic increase to cache and redis hits.
In 3.2 - 228
in 3.3 - 1594

I was running 3.2 with Laravel 8 before and upgraded to 3.3 and L9
I'm using custom eloquent-builder that allows me to have each collection as a model. I thought may be the problem is with that but seeing this thread I think it's something else.

I tried to check how long it takes to execute the queries and it's pretty fast so I'm thinking this issue has to do with cache.

here are screenshots from another request on the same collection. Notice the number of logs, events, cache and redis.
All log messages are the same (round(): Passing null to parameter...) and the first one is the one already mentioned here - Return type of Statamic\Fields\Values::jsonSerialize() should either be compatible with...

[elijahworkz]

I think that the reason for all the notifications and slowness happens when paginated result is returned and passed through toArray() function.

I tried to imitate the call in Tinkerwell and got some notifications when using EloquentQueryBuilder , but same request directly on the model (without Statamic) - there were no notifications.

I think if items on collection have assets - toArray() on statamic query tries to augment them.
I also tried to make 'cache_meta' = false in assets.php config and it crashed the CP.

[elijahworkz]

I created a separate issue #5752

[theutz]

I'm having the same issues that @elijahworkz outlined well here, too. I tried updating to Statamic 3.3 but keeping Laravel 8, just to see if it made a difference, and unfortunately it did not.

[theutz]

Workaround is to disable Telescope, for the time being. Waiting on a long-term fix, but I'd consider this problem solved by #5752 .