Early Rendering: A Lesson in Debugging Drupal 8

I came across the following error the other day on a client's Drupal 8 website:

LogicException: The controller result claims to be providing relevant cache metadata, but leaked metadata was detected. Please ensure you are not rendering content too early.

Leaked? That sounded bad. Rendering content too early? I didn't know what that meant, but it also sounded bad. Worst of all, this was causing a PHP fatal error along with a 500 response code. Fortunately, I caught the error during development, so there was time to figure out exactly what was going on. In so doing, I learned some things that can deepen our understanding of Drupal’s cache API.

Down the rabbit hole

I knew that this error was being caused by our code. We were writing a custom RestResource plugin, which is supposed to fetch some data from the entity API and return that data, ready to be serialized and complete with cacheability metadata. This custom RestResource was the only route that would trigger the error, and it only started happening part way through development as the codebase grew complex. It had been working fine, until the error noted above, which I include here in full with a stack trace:

The website encountered an unexpected error. Please try again later. LogicException: The controller result claims to be providing relevant cache metadata, but leaked metadata was detected. Please ensure you are not rendering content too early. Returned object class: Drupal\rest\ResourceResponse. in Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->wrapControllerExecutionInRenderContext() (line 154 of core/lib/Drupal/Core/EventSubscriber/EarlyRenderingControllerWrapperSubscriber.php). Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 135)
Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object, 1) (Line: 57)
Symfony\Component\HttpKernel\HttpKernel->handle(Object, 1, 1) (Line: 57)
Drupal\Core\StackMiddleware\Session->handle(Object, 1, 1) (Line: 47)
Drupal\Core\StackMiddleware\KernelPreHandle->handle(Object, 1, 1) (Line: 119)
Drupal\cdn\StackMiddleware\DuplicateContentPreventionMiddleware->handle(Object, 1, 1) (Line: 47)
Drupal\Core\StackMiddleware\ReverseProxyMiddleware->handle(Object, 1, 1) (Line: 50)
Drupal\Core\StackMiddleware\NegotiationMiddleware->handle(Object, 1, 1) (Line: 23)
Stack\StackedHttpKernel->handle(Object, 1, 1) (Line: 663)
Drupal\Core\DrupalKernel->handle(Object) (Line: 19)

I was confused that our code didn't appear in the stack trace; this is all Drupal core code. We need to go deeper.

As I do when this kind of situation arises, I took to the debugger. I set a breakpoint at the place in core where the exception was being thrown looking for clues. Here were my immediate surroundings:

// ...
elseif ($response instanceof AttachmentsInterface || $response instanceof CacheableResponseInterface || $response instanceof CacheableDependencyInterface) {
  throw new \LogicException(sprintf('The controller result claims to be providing relevant cache metadata, but leaked metadata was detected. Please ensure you are not rendering content too early. Returned object class: %s.', get_class($response)));
}
// ...

Foreign land. Knowing a smidgen about the Cache API in Drupal 8 and the context of what we were trying to do, I understood that we were ending up here in part because we were returning a response object that has cacheability metadata on it. That is, we were returning a ResourceResponse object that implements CacheableResponseInterface, including the relevant cacheability metadata with it. I could see from Xdebug that the $response variable in the snippet above corresponded to the ResourceResponse object we were returning, and it was packed with our data object and ready to be serialized. 

So as far as I knew, I was playing nice and adding cacheability metadata like a good Drupal developer should. What gives?

Seeing the forest for the trees

It was at this point I felt myself getting lost in the weeds. I needed to take a step back and reread the error message. When I did, I realized that I didn't understand what “early rendering” was.

I knew it had some connection to caching, so I started by reading through all the Cache API docs on drupal.org. I’ve read these several times in the past, but it’s just one of those topics, at least for me, that requires constant reinforcement. Another relevant doc I found was CachebleResponseInterface. These provided a good background and laid out some terminology for me, but nothing here talks about early rendering. I also reviewed the Render API docs but again, no mention of early rendering, and nothing getting me closer to a resolution.

So then I zoomed back in a little bit, to the parent class of the code which threw the error: \Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber

As is often the case in Drupal 8 core code, there was an excellent and descriptive doc block for the class. I often find this to be key to understanding Drupal 8. Core committers take great care to document the code they write which makes it worth getting comfortable with reading through core and contrib code.

When controllers call drupal_render() (RendererInterface::render()) outside of a render context, we call that "early rendering." Controllers should return only render arrays, but we cannot prevent controllers from doing early rendering. The problem with early rendering is that the bubbleable metadata (cacheability & attachments) are lost.

At last a definition for early rendering! However, our code wasn't (at least directly) inside a controller, it never called drupal_render() that I could tell, and what in the world is a render context?

Nobody to blame

Still, in need of some context for understanding what was going on here, I looked at git blame to find out where the code that was throwing the error about early rendering came from. Ever since I started to do Drupal 8 development, I’ve always found it useful to use a clone of Drupal locally for such occasions. PHPStorm makes using git blame quite easy. In the file you’re interested in—opened in the editor—just right click the line numbers column and click Annotate. Once the annotations display, click the one that corresponds to the line that you’re interested in to see the commit message. 

Most, if not all, Drupal core commits will have an issue number in the description, in this case, here is what I found:

Issue #2450993 by Wim Leers, Fabianx, Crell, dawehner, effulgentsia: Rendered Cache Metadata created during the main controller request gets lost

Loading up the issue, I’m faced with a wall of text, 159 comments. Although I did eventually wade through it out of morbid curiosity, what I immediately do when faced with a giant closed core issue, is check for a change record. The Drupal 8 dev cycle has been really excellent about documenting changes, and change records have really helped in the transition from earlier Drupal 7 concepts and explaining new concepts in Drupal 8. For any core issue, first, take a look in the right sidebar of the issue for “Change records for this issue”, and follow any that are linked to get a birds-eye view of the change. If you haven’t already, it’s also handy to bookmark the Change records for Drupal core listing as it's a great place to look when you're stuck on something Drupal 8.

The change record was very helpful, so if you’re interested, I recommend you definitely give it a read. In short, early rendering used to be rampant (in core and contrib), and this was a problem because cacheability metadata was lost. The change introduced a way to wrap all controllers, detect early rendering, catch and merge the cacheability metadata into the controllers' return (usually a render array). That’s all well and good, but wait! You might think, "If it’s handling the cacheabillity metadata from early rendering, why is it still throwing an error!?" Well, going back to the snippet where the exception is thrown from earlier:

// ...
elseif ($response instanceof AttachmentsInterface || $response instanceof CacheableResponseInterface || $response instanceof CacheableDependencyInterface) {
  throw new \LogicException(sprintf('The controller result claims to be providing relevant cache metadata, but leaked metadata was detected. Please ensure you are not rendering content too early. Returned object class: %s.', get_class($response)));
}
// ...

What this boils down to is if your controller is returning a response object of type AttachmentsInterface, CacheableResponseInterface, or CacheableDependencyInterface, Drupal does not give you a pass, nor does it handle cacheability metadata from early rendering for you. Drupal takes the position that since you are returning this type of response, you should also be responsible, be aware of and handle early rendering yourself. From the change log:

Since you're returning responses, you want to fully control what is sent, so you should also be a responsible citizen and not do any early rendering.

I solemnly swear not to early render

Ok, so no early rendering, got it. But, what if it’s out of our control? In our case, the code we were working in didn't have any direct calls to drupal_render() (RendererInterface::render()). My next tactic was to understand more about what was triggering early rendering. 

To do this, I set a breakpoint in the sole implementation of RendererInterface::render() and then hit the REST endpoint that was triggering the error. Xdebug immediately broke at that line, and inspecting the stack trace, we saw some of our code! Proof that we broke it! Progress. 

As it turns out, some code in another custom module was being called. This code is meant to wrap entity queries, massaging the return data into something more palpable and concise for the development team that wrote it. Deep in this code, in processing node entities, it was including a call to $node→url(), where $node is a \Drupal\node\Entity\Node object. Turns out, that triggers early rendering. To this, you might ask, "Why would something as innocuous as getting the URL for a node trigger early rendering?" The answer, and I’m only 80% sure after studying this for a while (do correct me if I’m wrong), is that URLs can vary by context based on language or the site URL. They can also have dependencies, such as the language configuration. Finally, URLs can have CSRF tokens embedded in them, which vary by session. All of which is important cacheability metadata that you want to be included in the response. OK, so what’s a responsible Drupal developer to do?

The complete (and verbose) solution, courtesy of ohthehugemanatee (indeed), is to replace your $node→url() call with something like:

// 1. Confusing: the method is called toString, yet passing TRUE for the first param nets you a \Drupal\Core\GeneratedUrl object.
$url = $node->toUrl()->toString(TRUE);
// 2. The generated URL string, as before.
$url_string = $url->getGeneratedUrl();
// Add the $url object as a dependency of whatever you're returning. Maybe a response?
$response = new CacheableResponse($url_string, Response::HTTP_OK);
$response->addCacheableDependency($url);
return $response;

That’s a lot, and it’ll be different depending on what you're doing. It’s broken down into 3 parts. First, you want to call $node->toUrl()->toString(TRUE);. This will essentially tell Drupal to track any cacheability metadata, which is part of generating the URL, and return an object from which you can get that cacheability metadata so you can deal with it. The second part is just getting the actual URL string, $url_string = $url->getGeneratedUrl();, to do with as you please. Finally, you need to account for any encountered cacheability metadata. In the context of a response as above, that means adding the $url object as a cacheable dependency. In the context of a render array, it might mean merging the $url cacheability metadata into the render array. (eg. CacheableMetadata::createFromObject($url)→applyTo($render_array))

Wrap it up

OK so now I understood where the exception was coming from and why. I also understand how I might change the code that is triggering an early rendering. But as I mentioned before, what if you don’t control the code that is triggering an early rendering? Is all hope lost? Not quite. What you can do is wrap the code triggering the early render in a render context. Let’s look at some code:

$context = new RenderContext();
/* @var \Drupal\Core\Cache\CacheableDependencyInterface $result */
$result = \Drupal::service('renderer')->executeInRenderContext($context, function() {
  // do_things() triggers the code that we don't don't control that in turn triggers early rendering.
  return do_things();
});
// Handle any bubbled cacheability metadata.
if (!$context->isEmpty()) {
  $bubbleable_metadata = $context->pop();
  BubbleableMetadata::createFromObject($result)
    ->merge($bubbleable_metadata);
}

Let’s break this down:

$context = new RenderContext();

Here, I instantiate a new render context. A render context is a stack containing bubbleable rendering metadata. It’s a mechanism for collecting cacheability metadata recursively, aggregating or “bubbling” it all up. By creating and passing it in the next line, the render context is able to capture what would have otherwise been lost cacheability metadata.

/* @var \Drupal\Core\Cache\CacheableDependencyInterface $result */
$result = \Drupal::service('renderer')->executeInRenderContext($context, function() {
  // do_things() triggers the code that we don't don't control that in turn triggers early rendering.
  return do_things();
});

Here I run some arbitrary code within the render context I created. The arbitrary code, somewhere along its execution path that we have no control over, triggers early rendering. When that early rendering occurs, since I’m wrapping the code in a render context, the cacheability metadata will bubble up to the render context I setup and allow me to do something with it.

// Handle any bubbled cacheability metadata.
if (!$context->isEmpty()) {
  $bubbleable_metadata = $context->pop();
  BubbleableMetadata::createFromObject($result)
    ->merge($bubbleable_metadata);
}

Now I check if the context is non-empty. In other words, did it catch some cacheability metadata from something that did early rendering? If it did, I get the captured cacheability metadata with $context→pop() and merge it with my \Drupal\Core\Cache\CacheableDependencyInterface object which will be returned. BubbleableMetadata is a helper class for dealing with cacheability metadata. This merge part may look different depending on your context, but the idea is to incorporate it into the response somehow. Take a look at the static methods in \Drupal\Core\Render\BubbleableMetadata  and its parent class for\Drupal\Core\Cache\CacheableMetadata some helpers to merge your cacheability metadata.

Really wrapping up

That was a heavy, long, complex debug session. I learned a lot digging into it and I hope you did as well. Let me know in the comments if you’ve ever run into something similar and came to a resolution in a different way. I’d love to continue furthering my understanding.

While it was great to figure this out, I was left wanting a better DX. In particular, improving the fact that Drupal auto-magically handles early rendering in some cases, but not others. There is also the odd workaround to capture cacheability metadata when cacheability metadata when calling $node→url() that could use some work. A quick search on the issue queue told me I wasn’t alone. Hopefully, with time and consideration, this can be made better. Certainly, there are good reasons for the complexity, but it would be great to balance that against the DX to avoid more epic debug sessions.

Acknowledgements

• Technical feedback by Juampy NR
• Hero image by Vladimir Kramer on Unsplash