ResourceObjectNormalizer::getNormalization can result in max-age drift when different sets of fields are requested

larowlan → credited enyug → .

larowlan → credited mstrelan → .

larowlan → credited nick_schuch → .

📌 Add #cache['downstream-ttl'] to force expiration after a certain time and fix #cache['max-age'] logic by adding #cache['age'] Active reports this exact issue in #11

I've confirmed that the drifted max age bubbles up to DPC resulting in the entire page being cached for too long as well.

Hmm, interesting bug. Was just talking about something similar with a colleague earlier this week.

Not sure is this is truly jsonapi or more caching. I'll come back to this issue soon.

Not sure is this is truly jsonapi or more caching

True it could exist in other areas, I'm not sure if other parts of the caching system cache things like this though. The issue really stems from that fact that we get a cached item (the normalized fields) which already contain max ages, add stuff on to that same cache entry, and then re cache it with a mix of new and existing data.

Ok interesting, fair enough. I'll put in on my list and will probably start to see if i can create some failing tests.

We have ran into this issue, and my colleague @casey has found this problem happening in other parts of the caching system also. We ran into this because we use max-age in combination with a time for anonimous visitors to have access to a private file and we noticed that cache was not invalidated a tthe right time. This was also a combination of different caches that stack their max-age and therefor ending up with caches that don't invalidate at the right time. This gets even worse, when certain caches invalidate or get purged because of cache size this can actually result in issues around an invalid state which results in WSOD's. We've seen this in cron and certain very big sites.

As we talked about this this morning, we think we might need a META issue around this, where max-age should consider expires and be recalculated if a later cache uses earlier caches. This would probably fix a lot of issues.

I hope i can make a good writeup soon so we can work on this. We can probably fix this in steps though and start calculating max-age based on bubbled max-age and expires.

Caching is hard lol

adding some related issues also

Add parent issue, since me and casey think we can solve this globally.

Since solving the main issue is a web of tasks and unsolved questions (it seems), i've extracted the jsonapi part in a mr. Would love to get some feedback on this approach, so gonna post it here, might even be able to do a local fix here, without touching the others.

The code should apply max-age properly this way based on the time of the request. We use this pattern from the parent issue, which we succesfully use in production (see this comment → in #2352009: [pp-3] Bubbling of elements' max-age to the page's headers and the page cache → ).

Code looks good, is there a way we can add a test for this behaviour?

I will test this with our previous use case

bbrala → credited casey → .

I'll think up a test Friday with casey. Didn't get there tonight.

Adding casey since we worked on this together.

Note:

Probably use ResourceObjectNormalizerCacherTest and use a dataprovider to create different set's of fields and check variationcache for the proper max age.

We can use the request stack getCurrectRequest to set the time in the request and see if invalidation is ok. That test should then fail without the code.

Think that should work.

Added a test that tests the max age result in a normalization. It tests default max-age, then little later since last request, and lastly after it expires. I also added the code suggestion from casey earlier.

Test only run fails: https://git.drupalcode.org/issue/drupal-3444257/-/jobs/1675965 yay.

Think this is covering it quite well. And only like 0,7 seconds of testing.

Al ready for review again

Warning was missing 'account' from the context for field serialization. Fixed right now by passing 'account' => NULL, but also added a followup to fix the warning at its root: 📌 Calling normalize without account context generates a warning. Active .

The created timestamp can be a float, so we need to floor the expires value so that we can calculate a proper max_age. We use floor because if it
expires on timestamp 1720000.5 we need to make sure it expires on timestamp 1720001.

Locally this fixed the tests, think all is ok now for real ;)

We talked this over some more during lunch lol ;p

Expires is a bad idea. This is create time of the cache, this could mean the cache was requested, but created seconds later if the request is slow. Since everything everywhere uses request time for caches, this is wrong and will result in silly bugs if we are not carefull.

When looking through core i did notice this code in Drupal\views\Plugin\views\cache\CachePluginBase

  public function cacheGet($type) {
    $cutoff = $this->cacheExpire($type);
    switch ($type) {
      case 'query':
        // Not supported currently, but this is certainly where we'd put it.
        return FALSE;

      case 'results':
        // Values to set: $view->result, $view->total_rows, $view->execute_time,
        // $view->current_page.
        if ($cache = \Drupal::cache($this->resultsBin)->get($this->generateResultsKey())) {
          if (!$cutoff || $cache->created > $cutoff) {

That is kinda scary, unrelated, but why would that use created, and not when it expires...

Anyways, unrelated ;)

Added test for specifically 0 seconds.
Ended up being convinved to change the loop to caseys suggestion.

Do wonder if the fact that REQUEST_TIME+1600 gived a max-age of 0 is correct. Shouldn't that be a fresh record with 800?

I did not have a project where I would suffer from the described problem, but based on the issue description and the attached test I think the described problem is addressed.
I had some nitpicks and also spin up a test-only branch just to confirm that the test fails.

The Needs Review Queue Bot → tested this issue. It fails the Drupal core commit checks. Therefore, this issue status is now "Needs work".

This does not mean that the patch necessarily needs to be re-rolled or the MR rebased. Read the Issue Summary, the issue tags and the latest discussion here to determine what needs to be done.

Consult the Drupal Contributor Guide → to find step-by-step guides for working with issues.

mxr576 → changed the visibility of the branch 3444257-test.only to hidden.

Fixed the things that I have spotted, RTBC from my part.

<3

I read the IS, comments and the MR (not a code review). All questions are answered. The only thing I spotted was that the proposed resolution is a question.

Leaving at RTBC

Updates a few small things in IS, thanks

Great job guys, this is a good one to get in!

Left a question on the MR

Also keen to see this go in, but the test makes me think we're left with a performance regression in place of the bug.

Hmm, digging into my memory i think the following reasoning was important here. I've gone through this with @casey to see if what you say is true. We've updated the comments in the tests and adjusted the test with 1600 to 801 to hopefully be more clear on the intention of the tests.

To awnser your comment: Cache entries track expire time, the cache record is valid in the second it invalidates. See cache backends:

$cache->valid = $cache->expire == Cache::PERMANENT || $cache->expire >= $this->time->getRequestTime();

The cache should be renewed the next second after expiring. A max-age of 0 means the cache is still valid but will not be next second. Invaliding the cache is still just done in the cache backend through the expire data. We are not changing anything on that layer. The only thing the max-age does is tell the layers in front of drupal (nginx, a CDN or whatever) it is about to expire.

Should we disable the cache on max-age 0 by returning FALSE in the ResourceObjectNormalizationCacher::get method we should pretty much get the same data because the cache has not expired yet.

Whats important to note is that the test only tests the ResourceObjectNormalizationCacher and its logic around max-age. We are not testing the cache backend and handling of expire data. We assume that is correct. (although i didn't find any tests around the expire=0 and handling of that case).

Also rebased. :x

Left some comments in the MR and their is a failing test :-(.

Added comments to the two parts you gave feedback on quietone.

Also fixed the test, i updated the the comment to the test based on a deepdive, and accidentally updated the tested value. Sorry about that.

See https://git.drupalcode.org/project/drupal/-/merge_requests/8154/diffs?co...

Believe feedback has been addressed on this one.

@bbrala, thanks for the comments.

I rebased the MR and there were no conflicts. Then I removed an @see to the issue because we don't link to the core issues in the code base, And I also changed the format of the comments to follow the recommendations in the coding standards. See https://www.drupal.org/docs/develop/standards/php/api-documentation-and-... → .

Since the changes did not change the code and only reformatted comments, I am leaving the RTBC.

Bit embarrassing I'm wrongly formatting a comment.

Thanks :)

I found the comment a bit hard to read and suggested on possible change, although not solid enough to use gitlab suggestions for it.

Tried to make the comment a bit more understandable. It is still hard imo, but more clean in many ways :)

RTBC since its only a small comment change.

That looks better, definitely can't improve on it at least!

Committed/pushed to 11.x and cherry-picked back through to 10.3.x, thanks!

catch → closed merge request !8154

Wow! 😳

Seems like this was wrong ever since 2019, where I worked on this in #2819335: Resource (entity) normalization should use partial caching → ? AFAICT the big refactor in 📌 Refactor ResourceObjectNormalizationCacher to use VariationCache Fixed didn't change this.

Looks like the entire "D8 cacheability" effort back in 2013–2015 overlooked the general problem: 🐛 Stacked caches result in max-age drift in caches Active 😬

Automatically closed - issue fixed for 2 weeks with no activity.