rss
ComputerMinds.co.uk: Debugging Great Uncle Call Stacks - to solve a recursive router rebuild error
Our automated tests for a Drupal 11 upgrade failed with a cryptic error: Recursive router rebuild detected. A bit like when cron warns about it already running, this meant something had started a router rebuild, but without finishing successfully, before another rebuild of routing information was triggered. My solution was pretty specific to our context - but what might be interesting here is how I identified what had led to this problem.
The context
We run automated functional tests on this client project as regression tests, to show that various bespoke functionality still works, as changes are introduced. These are run in a DDEV instance inside a github action, via phpunit (and the DDEV Selenium Standalone Chrome add-on). To keep the maintenance of these tests easy and as portable as possible, we just use core's existing phpunit.xml.dist file as their configuration. The tests install a fresh Drupal site, importing our project's ordinary configuration along the way, and then perform actions in a headless browser, clicking on elements just like a site visitor would, etc. During work to upgrade from Drupal 10 to 11, tests started failing whilst just installing Drupal. Nothing to do with our custom functionality. What gives?!
The easy bit
At least we had a clear error message to go by. Enable xdebug, stick a breakpoint on the line which throws the exception, and run to the line. (Thanks DDEV for getting us that far easily enough!) So that's in the rebuild() method of core's \Drupal\Core\Routing\RouteBuilder class. Simple enough to confirm there that, yes, the $this->building property shows a previous attempt to rebuild the routes has happened. But how can we see what that was?
At this point, the call stack shows us all the 'parent' callers of this method, but it's not a truly recursive call like the error implies: there's no smoking gun suggesting something incorrectly called back into rebuild(). Traversing through the parents, the most notable thing was just to see that this call is part of the install_finished step of installing Drupal. Seems reasonable that Drupal would build up its record of routes once everything has been installed. So what earlier installation task had somehow started a router rebuild, without getting to the end of the rebuild() method where the $this->building property is reset?
I wanted to identify what had triggered the earlier incomplete router rebuild, regardless of why that hadn't completed successfully. (In post-mortem, I found some unrelated exception had been thrown, sending control flow away before the $this->building property was reset, but the exception was handled 'gracefully' and installation innoncently continued. That exception could be avoided, but the principle remains that some kinds of exception should be acceptable and allow installation to continue on successfully.)
The magic
So the parent function calls, and 'grandparent' calls, couldn't tell me much. If the function stacks were CSS, I'd be building mad :has() selectors for the previous sibling of a grandparent (or some other ancestor). Something like a Great Uncle or Great Aunt, perhaps? Anyway - let's call it that - I needed to debug the Great Uncle Stack!
The diagram above illustrate this, as a graph of control flow (to be read depth-first, left-to-right). The exception is only thrown on the second call to rebuild() (the right branch in the diagram), but the call we need to understand is at the end of the first stack (the left branch), which wouldn't be available to us during the second call. We want to know what triggered that first rebuild() call.
Here's how I solved this: use a static variable to record each previous entry into the method; i.e. the full stack traces, with PHP's internal debug_backtrace() function:
static $stacks = [];
$stacks[] = debug_backtrace();Then during the breakpoint debugging session, that static store of stack traces can be inspected.
So when my breakpoint landed, I could then see what the call stack was for when this rebuild() method had been previously called! In the screenshot above, the $stacks variable holds two stack traces: the first will contain the cause of the mysterious first failed call to rebuild(), somewhere in its stack of 42 function calls. (The second value in $stacks is just the stack trace up to this breakpoint, about to throw the exception.) So traversing through that first stack showed a specific install task and function that had triggered this.
The surprise
Bizarrely, the culprit was core's menu_link_content module! It has an entity_predelete hook implementation which, quite sensibly, wants to remove any menu links pointing to entities being deleted. But to do that, of course it needs to get information about which URLs an entity has which a menu link could point to - and that means route information is needed.
Of course, whilst installing Drupal, we didn't have any such menu links we needed to care about! But we do have entities that get deleted, so that hook is invoked. Our ordinary configuration for the project is imported as part of installing Drupal, which actually recreates some config - i.e. deleting before creating again the same config, just with a different UUID. That's because various config is created by default in installations without a specific UUID, and then gets switched to match the UUIDs in the config for our project.
Some of that config is created by Drupal core itself - for example, date formats from the system module - and others from quite reliable modules, like token. We could go round patching each individually to avoid them installing config that we will only recreate later during installation. But that wouldn't be very maintainable, and doesn't respect the quite reasonable default installation process.
Instead we crippled the specific functionality for finding menu links to delete, just during installation, with a simple hook_module_implements_alter():
/** * Implements hook_module_implements_alter(). */ function MYPROFILE_module_implements_alter(&$implementations, $hook) { if ($hook === 'entity_predelete') { // During site installation, we have no menu links to clear up. Avoid // menu_link_content triggering router rebuilds on deleting entities.try { if ( function_exists('install_verify_completed_task') && install_verify_completed_task() ) { unset($implementations['menu_link_content']); } } catch (\Drupal\Core\Installer\Exception\AlreadyInstalledException $e) { // Allow menu_link_content to react to entity deletion. } } }
Our automated tests now pass, with Drupal installing successfully. Mystery solved and new debugging technique unlocked!
