Post-response task running (destructable services) are actually blocking; add test coverage and warn for common misconfiguration

The docs for flush() seem to indicate that you must both flush any output buffers and call this function to achieve the kind of behavior Drupal seeks to do in termination/DestructableInterface:

Flushes the system write buffers of PHP and whatever backend PHP is using (CGI, a web server, etc). This attempts to push current output all the way to the browser with a few caveats.

flush() may not be able to override the buffering scheme of your web server and it has no effect on any client-side buffering in the browser. It also doesn't affect PHP's userspace output buffering mechanism. This means ob_flush() should be called before flush() to flush the output buffers if they are in use.

Adding a historical related issue even though this code has since been Symfony-ized.

Re: #4, could very well be. My track record/experience in raising upstream issues on Symfony doesn't make me too optimistic, but their team always provides good feedback as to why something might not fit. Opened this issue.

I suspect if it's not "fixed" upstream, it would be because they expect "you" (in that case, Drupal) to do the "final flush." But let's see.

A little nugget that arose from a conversation in Slack:

So yes this is basically the discussion from comments 38-40 on #1599622-38: Run poormanscron via a non-blocking HTTP request. I'll try to avoid a religious war over runtime configuration, but I do agree with the conclusion from comment 40 that whatever your thoughts about Apache + mod_php, it is common and even is the default mode of operation for the php:apache Docker image, and there are plenty of situations in which FPM isn't practical or what you want or... whatever.

[This issue] is basically the more general question of, do we want to be compatible with non-FPM runtimes for post-response flush processing, and I honestly can't see a reason why we wouldn't, other than to spite people who prefer something other than FPM.

For my $0.02, I find the perennial arguments over Apache+mod_php vs. FPM to be unproductive and unnecessarily divisive. Combined with the fact the vast majority of sites will not realize much real performance enhancement in this regard vs. poor caching or performance elsewhere in the stack where developers do have more control. Plus there are lots, lots of other runtimes, e.g. Nginx Unit or Swoole.

I think our goal should be that Drupal's shutdown process handling should work regardless of your runtime, because it should be easy to do.

The test failure is on the vary header now containing accept-encoding. I imagine this is automatically set somehow? Curious if the test suite is overly strict on this.

Thanks for the archaeology in #10.

It seemed initially this is a bit of a quirk, since my perhaps naive expectation would be that the header would be added always or never.

However, this issue actually reveals a gap in existing test coverage. In my experimentation, Apache's mod_deflate will not act on responses with a content-length of less than ~69 bytes. If the content is longer, then Apache will add a vary: accept-encoding header and gzip the response if the client expressed its compatibility.

The failing test had a content-length of 5, so it appeared as though flush() was adding this header per se. I think it's more that this function call forces mod_deflate to act regardless of this limit (minimum compression ratio?)

Anyway, I added a longer fixture text snippet and require the vary header either contain only accept-encoding or be absent entirely.

Does this issue also need to add coverage for DestructableInterface, since there is none, currently?

Tests are back green... curious a maintainer's take on whether we need to more broadly add coverage on the termination processes.

Also, been thinking on the question of whether this gets "fixed" upstream or here, I think at the very least we add this flush() in Drupal, until such time as Symfony does. I will stand by the rating of this being major, because it breaks expectations of current functionality in a pretty significant way.

@fabpot considers this a bug in Symfony, so looks like we can just get it fixed there.

Yeah, I was surprised by that one.

I think the test changes/improvements should still go in, though?

What about thoughts on:

curious a maintainer's take on whether we need to more broadly add coverage on the termination processes.

PP on upstream.

Well that was fast. https://github.com/symfony/symfony/pull/46931#event-7006033935

NW for updates to testing.

OK so I'm bumping this back to major for reasons as explained below.

Drupal's ability to perform post-response processing is blocked by #2579775: Missing Content-Length header blocks response until all registered shutdown functions execute and the Kernel terminate events run (which I have marked as a duplicate of this issue, since this has more work/tests) as well as the server's having output buffering enabled.

The last part is a "new" consideration as Symfony quickly added a flush() to its code, but it only gets called if there are output buffers to be closed. Adding an ob_start() call to Drupal was considered way back in #80029: ob_start at beginning of index.php might speed up Drupal but since this only affects users of CGI-based (mod_php) installs, I don't think that's a viable option now.

The updated MR now includes a few things I think are important:

• Test coverage for DestructableInterface, which was missing (and affects/covers all server environments)
• A status page warning for users who would be affected by the lack of output buffering (e.g., it's turned off in your PHP ini settings)
• The code from the linked issue that blocks post-response processing to work at all, anywhere. (This is the justification for the priority upgrade.)

Does the recommendation for output buffering in non-FPM environments need to be added elsewhere, e.g. in docs?

Credit should be given to to contributors to the duplicate/replaced issue.

Note this MR will act as a failing test until Drupal includes at least Symfony 4.5, which includes the upstream bugfix. I'm going to leave this as NR since that's a pretty soft postponement and this can be reviewed now, with a minor manual patch. This could then test against updated dependencies and ship out in short order for both Drupal 9 and 10.

Most of the failures are relating to:

transfer closed with x bytes remaining to read

... which I suspect is relating to the content-length header pulled in from the other issue... in local testing it doesn't appear to actually be a truncated response, but clearly there's a mismatch...

Related Big Pipe issue.

Test failures def. look related to calls to Response::setContent(). Seems to be the reasonable answer is to assess the various weights of subscribers which set the content so we can consolidate the related setting of the content-header header, appropriately (and in a central place.)

Perhaps the "best" way to do this would be to do so inside of ::setContent() or as some type of side effect, however we're using the Symfony core response object so that would require the kind of overloading we're unlikely to want to do.

Will investigate these various classes of failures and analyze the various calls to ::setContent() to see if I can't arrive at a least-invasive solution.

This actually seems to be an issue with Guzzle expecting a body on HEAD requests...which obviously are not forthcoming.

Well it gets stranger... when testing this locally at the command line, I noted that curl gave me this helpful note when I was specifying -X HEAD:

$ curl -X HEAD -v -o /dev/null http://localhost:8082
Warning: Setting custom HTTP method to HEAD with -X/--request may not work the 
Warning: way you want. Consider using -I/--head instead.

I thought... huh. There's not much in the curl docs, but I did find this nugget in a blog post from the maintainer:

What -X does

When doing HTTP with curl, the -X option changes the actual method string in the HTTP request. That’s all it does. It does not change behavior accordingly...

Warmer! Turns out that if you specify -I at the command line, this tells curl you want to do a HEAD request and omit looking for a body of content-length length. Otherwise internally libcurl treats the response as if it were made with GET. But what about setting $method to HEAD when calling libcurl via Guzzle?

So I thought, OK, this is a bug in Guzzle... but Drupal certainly couldn't be the first implementation of a HEAD request with a content-length header. Sure enough, Guzzle sets the appropriate CURLOPT_NOBODY option... but only if the body is unspecified.

Turns out JSON:API module re-uses a $request_options variable between various requests, including HEAD. So internally, the HTTP driver was telling curl to handle these as GET.

This only occurs now because we're setting a content-length header, but this regression should be limited to the test suite.

See note at #19 re: reviewing this in light of the upstream fix.

@catch thanks for the review and the compliment. Looks like we were editing this at the same time so the version change back to 9.4.x wasn't purposeful. I'm going to let CI run and if we get down to one expected failure, I'll rebase on 9.5.x and then we can PP this on Symfony releases. But getting this to an "RTBC pending upstream release" would be good? Then, this should be able to go in to 10.0.x and get backported... or however you'd want to handle that.

Out of curiosity, I tried to look at how Laravel tests their similar feature... and I don't think they have test coverage. This definitely uncovered some edge cases/test fixes/etc. in Drupal. I think this should also make any refactors to Big Pipe marginally easier, too.

Added two draft change records.

Thanks for the review... I can't speak to whether it's "for sure" broken in all the places all the time, but I think this issue is necessary for a few reasons, even if this currently works in FPM:

• There are a lot of people running with mod_php or some other CGI, and this is definitely broken there, now.
• There is no test coverage for this feature in any case. At least on DrupalCI/local environments, this is broken b/c the server environment is simpler than FPM.
• Setting content-length makes it easier for us to detect WTF conditions in our various middlewares that do manipulation of the response contents, as evidenced by the various test "fixes" that were involved once the primary test coverage expanded.

So even if it's just to improve test coverage and ensure we don't regress from Symfony (which committed the related fix rather quickly) I think this is the minimum viable fix to address the above points. Happy to address anything specific, though.

Additionally,

It works for BigPipe, so I am confused why that would be a problem.

I think this is because BigPipe is a streamed response, vs. whatever the opposite/default case is called.

Right, OK. Lots of interesting intersections to keep track of here. To Fabian's point, I think BigPipe does work here in the sense that it does currently call flush(), which is what we needed Symfony to add (and this is PP'd on new Symfony versions being tagged.) Which is kinda the point. If there are no BigPipe replacements (e.g., json:api responses) then you don't ever get a flush() and we need the Symfony fix, plus test coverage and better detection of broken content-length headers, anyway.

Opened #3300773: Fix failed test on `symfony/http-foundation` 4.4.44/6.1.3 and later

#3300773: Fix failed test on `symfony/http-foundation` 4.4.44/6.1.3 and later is in!

@catch mentioned there that this "should probably only go into 9.5.x" but I'm a bit confused, would this then get into Drupal 10 during a rebase?

NW for rebase since the linked issue contained one of the test updates from this issue.

Added an MR against 10.1.x; there was a merge conflict in `system.install` unique to 10.x.

The 9.5.x MR will need to wait for #3300773-32: Fix failed test on `symfony/http-foundation` 4.4.44/6.1.3 and later.

Well... I don't really know what to make of these test failures. They aren't consistent across runs (there is some overlap, but not 100%) and I can't reproduce locally.

I would suspect the update to symfony/http-foundation but that was just committed with passing tests on a different issue. The failing tests all appear to be Functional (likely browser) so there's gotta be some side effect here, but why it's happening now is a mystery to me.

May need to add some debugging to the failing tests, since they are only failing on DrupalCI. When I've had similar issues in the past, it's been down to timing (DrupalCI runs faster than my local) but I don't think most of these are timing related.

Seems a common thread is the failing tests intersect with cache bins, which could in theory have to do with some timing/race conditions and would explain some of the inconsistency in which tests fail. Maybe?

A few more thoughts before I have to change tack today:

Pretty sure the failure in ShutdownFunctionsTest is sensitive to the test-running environment? There is a conditional in that test which I think is now hit by Apache+mod_php as well, so that is likely to need a refactor. That seems logical enough.

The other test failures either intersect with the render cache or locale/language negotiation or both. I have a sneaking suspicion this is somehow sensitive to the test running environment's HTTP requests, because I can't reproduce locally. Very sticky. But not particularly surprised given the test fixes we've had to make already on this issue? Wouldn't be surprised if there were a few more, though these are more insidious because I can't reproduce.

Yeah, I have just about whack-a-mole'd all these; most all of this is race conditions with caches that are set after the response is sent. The LocaleLookup is the most insidious.

Well this was another adventure in frustration, but I'm glad we are able to improve so much test coverage.

My two earlier hunches were kinda-sorta correct - this had to do with cache write operations done in services that either implement DestructableInterface or subscribe to the kernel termination event. The string translation tests definitely threw me for a loop since I don't do a ton of i18n.

Of note, the Path Alias test only failed once; I'm glad I was able to catch it to avoid some WTF type conditions in the future. I definitely think this is worth getting in to core and I think with the number of test runs this has gone through now, it's likely we've caught most/all of these cases. But if there are some "random" failures in the future, we should definitely suspect these types of race conditions.

Marking this back to NR. I only updated the 10.1.x MR but if it passes, it's a very straightforward backport.

I'm curious to hear how you two are using CloudFront in front of Drupal... I use CloudFront (about the only AWS service I can stomach using) a ton for controlling access to media with signed URLs/signed cookies, but I haven't yet found much of a use case for content responses/whole sites.

Could be something interesting to put in the content-length header change record if this unlocks functionality that wasn't even on my radar.

Thanks for testing.

Re: #53:

This is just for the part that's running our Functional tests that are backed by a running site using DTT

I'm not sure what DTT is?

When trying to implement the header via a contrib module [...] we also saw significant speed impacts

Are you talking about negative performance impacts in your test suite, or you're saying that the change to set the content-length header significantly slows down the site, overall?

I'm certainly open to learning new things (I learned a lot working on this issue) but I find it hard to believe that doing a strlen() on the contents of the response would slow down responses in a meaningful way.

I just checked and core tests seem to be taking about exactly an hour now, and I compared test durations for this issue with the issue that bumped symfony/http-foundation and there's no difference - actually this one runs a minute faster.

Could you elaborate on whether you think there is an outstanding issue to be addressed here before it can be RTBC?

Alex, thanks for the review.

Changes in tests like... [sleep(1)] ... really concern me.

Trust me I didn't feel good doing this, either.

Yes you'll have issues like this if you are testing using nginx today but not if you are using apache.

It's actually the other way around, if I understand you correctly. Drupal's own test infra (at least DrupalCI, I dunno about the GitLab environment) now "properly" runs Drupal with the shutdown functions. (Also reference my comments about runtime bikeshedding at #7, not that we're doing so here.)

I suppose one could say that the CI environment should disable output buffering, however we are making the recommendation to run with it turned on so I don't think it makes much sense to change the default to off in CI.

Or to look at it another way, waiting for Drupal to finish post-request processing and documenting it in the tests seems safer to me than basically saying Drupal won't test post-response processing. I could even go further and contend these tests are currently broken in the sense that they do not actually test the subject's designed operation but rather rely on the CI environment not supporting it, to pass. (Yes, the work gets done regardless but then what's the point of going to all the trouble to defer?)

My worry is that this will suddenly cause test suites for projects to fail and people will have a really hard time tracking this down.

This is the catch-22. For core, enabling post-request processing causes the test fragility, which is why this touches on such a disparate number of modules. In effect we're fixing the test fragility by acknowledging that there is a timing component to certain integration tests.

And as a last theory-to-the-alternative push for getting this done, I'd note that there are a not-insignificant number of other sleep() calls in tests which could in theory be better performed by say, mocking the time service. I don't like that kind of whataboutism but in the spirit of Dries' recent talk about core contribution friction I wonder if that's the kind of perfect-enemy-of-the-good thing we can ticket as a follow-up (or just accept it.)

I did spend a good amount of time trying to research how other frameworks test this kind of thing (e.g., Laravel, Symfony) and the answer is, they don't. Which is why this already prompted a fix in Symfony (but no new test coverage, even!) and I believe why it was latent for so long in Drupal.

I agree in principle.

That said, I think that ransoms this issue to what amounts to a major change in core test-running infra/structure/classes. Personally, I think that's a huge ask for a bugfix. It's also a gigantic PITA to get any changes like a PHP ini change (especially a conditional one) into the existing test infra... which is all being rebuilt for GitLab anyway.

Regardless of that point, I think the "random fails" concern is a bit overblown. End users generally do not run their own tests against Drupal core; they rely on the upstream software pipeline (that is, DrupalCI and the like). In the case of contrib, I think this should break pipelines if it reveals an over-reliance on synchronous execution when they are actually testing asynchronous code. (Which this is, not in a fibers sense, but a "we'll do it later" execution sense.)

I'd venture to say that the affected contrib projects affected by this are small in number, and customer installs with affected tests are smaller still.

Size of impact isn't a strong case in and of itself, but I don't think the risk here is significant and I'd gladly pitch in on a follow-up task... but given this is a Major and contains enough "big" changes already, I'm just concerned this will become another multi-year core fix if we venture into "let's change how we run tests."

Thoughts?

Now needs a rebase for 10.1.x.

So an interesting observation here re: BigPipe; when you are using mod_php BigPipe will flush its response to the client as expected, however because it sends no content-length header at the outset (because it doesn't know the content-length) the client doesn't close the connection after everything is sent. So the client appears to continue to "spin" during post-request processing. If you close the client connection, the server side continues to do its post-request tasks because:

PHP will not detect that the user has aborted the connection until an attempt is made to send information to the client. (source)

This is kinda annoying UX in that the client doesn't immediately close and give the perceived performance of the page being "done" loading. However if the client disconnects, PHP keeps going on its merry way because no further output is attempted to be sent. I had thought perhaps we needed to implement ignore_user_abort(true) but I think this means, no we don't. This is one annoying feature of big_pipe when you can't call fastcgi_finish_request() but, whatever.

Re: #63:

Instead of using sleep() this could just be something like setting a state flag in the test and then resetting it in the last destructable service, and polling for that change in the test, no?

I thought we could do that, and that was my initial implementation of the test... however because this is a browser/functional test, the service is not accessible from the test runner; it's running in the context of the tested site. Really tough.

I think it would be helpful if those who are making commits (and opening new MRs?) could explain their work? Also it would be helpful for the work to stay on the main MR that has been worked on (2568) since its target has been changed to 11.x... no excuse not to stay there.

MR 2568 is now rebased to 11.x, hoping to maintain the MR review history in one place. Tests should still be passing as evidenced by the other 11.x MR that was created so I think this should be ready for another pass by @catch.

Per #3379199-7: [random test failure] DisplayFeedTranslationTest::testFeedFieldOutput the follow-up just committed in #3375959: Add a way to delay executions in test runner until terminate event completed in the child site fixes #92, so I think any regression talk should get followed-up there. FWIW I don't think any of us were particularly in love with the sleep() calls on this issue so it's awesome to see a creative fix to harden this (still new) test coverage.