Problem/Motivation

I encountered this on Drupal 12.0.0-beta2 sites on Pantheon, and then reproduced it on DDEV. After installing with the web installer in a browser (Standard profile by default), the site is broken until caches are cleared. When the installer finishes, it redirects to the homepage, which returns 500 with the following error

BadMethodCallException: The "\Drupal\standard\Controller\WelcomeController::access" method is not callable as a _custom_access callback in route "/admin/welcome".

And later requests to /admin/welcome (the front page set by the Standard profile, #3590882), /user/login or other pages return the same HTTP 500.

Rebuilding the cache fixes it.

Suspected cause: a request handled by the normal kernel while the installer batch is still enabling modules compiles a container from a partial module list and writes it to cache_container. The installer does not invalidate that entry, so every later request uses it.

Steps to reproduce

  1. Create a fresh Drupal 12.0.0-beta2 site.

    On Pantheon (Terminus, Drupal 12 Start State upstream):
    terminus site:create <site-name> "<label>" drupal-12-composer-managed --org=<org>

    On DDEV:

    ddev config --project-type=drupal12 --docroot=web --php-version=8.5
    ddev start
    ddev composer create-project "drupal/recommended-project:12.0.0-beta2"
  2. Open /core/install.php in a browser and complete the web installer. It installs the Standard profile by default. (Make sure the browser has no cached favicon.) On Pantheon the dev environment redirects there (https://dev-<site-name>.pantheonsite.io/core/install.php); on DDEV it is https://<project>.ddev.site/core/install.php.
  3. When the installer finishes, it redirects to the homepage, which returns an error (500 on Pantheon, 404 on DDEV).
  4. Request /admin/welcome, /user/login or other pages, now and a few minutes later. They return 500 until the cache is cleared.

On Pantheon

PHP 8.5.12, MySQL 8.4, web installer, Standard profile, on fresh sites.

  • When the installer finishes, it redirects to the homepage, which shows a 500 error. Rebuilding the cache fixed it.
  • I repeated it on a fresh site (Git mode) with Pantheon's nginx access log. Chrome requested GET /favicon.ico one second after the batch page loaded and two seconds before the first batch request, and it received a 302. A container was written to cache_container in the same second. Afterwards the homepage, /admin/welcome and /user/login returned 500 with the exception above.
  • I also ran the web installer with curl on the same site. One extra request after the first batch step (GET /favicon.ico or GET /) broke the install every time, in 3 of 3 installs. Installs without it worked.
  • I have not found anything Pantheon-specific so far. DDEV shows the same behavior with a different stack.

Reproduced on DDEV

DDEV v1.25.2, PHP 8.5, MariaDB 11.8, Chrome.

  • The batch page has no <link rel="icon">, so Chrome requests /favicon.ico while it loads. A container is written to cache_container in the same second.
  • With curl, one extra request after the first batch step (GET /favicon.ico, GET / or GET /user/login) broke the install every time. Installs without it worked.
  • Truncating only cache_container fixes the site. In the database log of one run, nothing deleted or truncated it after it was written, and install_finished() does not call drupal_flush_all_caches() or invalidateContainer() (I searched only lib, includes and modules/system/src).
  • Compared with Drupal 11.4.11: its installer batch page declares <link rel="icon" href="/core/misc/favicon.ico">, and in one browser install on DDEV Chrome did not request /favicon.ico during the batch and the site worked. The 12.0.0-beta2 batch page has no icon link. With one extra request after the first batch step, the 11.4.11 homepage also returned 500 (No check has been registered for access_check.permission), so the weakness is not specific to 12, but a browser install only triggers it on 12.
  • The icon link is added in BareHtmlPageRenderer::renderBarePage() (12.0.0-beta2; 11.4.11) when the features.favicon theme setting is on. In 12.0.0-beta2 the installer language page gets it but the batch page does not; in 11.4.11 both do. The installer theme also changed: Claro in 11.4.11, and default_admin in 12.0.0-beta2 (InstallerKernel::INSTALL_THEME). I have not found why the setting is off on the batch page.

Attached: pantheon-access-log-excerpt.txt (browser install on Pantheon) and access-log-excerpt.txt (browser install on DDEV, plus later curl requests).

Assumptions

  • The key from DrupalKernel::getContainerCacheKey() does not include the module list, so a container compiled from a partial list is found by every later request. This fits the missing Drupal\standard namespace in the cached container of one run
  • Any request that reaches Drupal while the batch is running breaks the install, on both Pantheon and DDEV. In a browser install, that request is the one Chrome sends for /favicon.ico when the batch page loads, because the page has no icon link. I tested one browser install on each, with Chrome only.

Proposed resolution

Not verified. Options to consider:

  • Invalidate the container (invalidateContainer()) or flush caches when the install finishes.
  • Prevent normal requests from writing the container cache while an install is in progress.

Restoring the icon link on the batch page, as in 11.4.11, would remove this trigger, but any other request that reaches Drupal during the batch can still break the install.

Comments

roshnykunjappan created an issue. See original summary.

roshnykunjappan’s picture

Title: BadMethodCallException on /admin/welcome after installing the Standard profile; » BadMethodCallException on /admin/welcome after installing the Standard profile
roshnykunjappan’s picture

Issue summary: View changes
cilefen’s picture

Component: other » base system
Issue tags: +Needs steps to reproduce

I am unable to reproduce this. I followed the steps as written. There must be additional steps to reproduce.

ghost of drupal past’s picture

While there have been significant efforts (thanks @catch) to decrease the number of container rebuilds during install it never went to zero. By this I mean it's real odd if a cache rebuild fixes this because most certainly install does one of those.

roshnykunjappan’s picture

Issue summary: View changes
StatusFileSize
new1.68 KB
new1.27 KB

Updated the issue description.

roshnykunjappan’s picture

Issue summary: View changes
roshnykunjappan’s picture

Issue summary: View changes
roshnykunjappan’s picture

Issue summary: View changes
roshnykunjappan’s picture

Thanks both for the quick response. I've updated the issue summary with exact steps and the evidence I have.

@ghost of drupal past
I agree it's odd if install already rebuilds the container. I'm not sure I understand all of it, but here is what I saw. A request that reaches Drupal while the installer batch is running seems to compile a container from the modules enabled at that moment and save it in `cache_container`. I didn't find anything that removes that entry when the install finishes: in the database log of one run there was no `DELETE` or `TRUNCATE` on it, and `install_finished()` doesn't seem to call `drupal_flush_all_caches()`. A full cache rebuild does remove it, which may be why that fixes the site. I may well be missing something, so please correct me if I'm wrong.

roshnykunjappan’s picture

Issue summary: View changes
roshnykunjappan’s picture

roshnykunjappan’s picture

Issue summary: View changes
roshnykunjappan’s picture

Issue summary: View changes