Ensure register_shutdown_function() works with php-fpm (blocks testbot php-fpm)

Yikes, I hope this doesn't mean that shutdown functions don't run at all, because that would be larger problem on php-fpm.

Since this blocks PHP 5.4 testing, and I don't really want to release without 8.x automatically tested on 5.4, bumping to critical.

Copied from the other issue. As rfay wrote, this is the same bug, just different problems.

In general this seems to be a problem with fpm/fastcgi_finish_request() and code running after that call.
This has been introduced in https://github.com/symfony/symfony/pull/1262 and reported as problem on http://stackoverflow.com/questions/14191947/php-fpm-fastcgi-finish-reque... and more important on https://github.com/symfony/symfony/issues/6417

Since this is critical maybe the related D7 issue needs a higher priority than normal as well.

Quoting @stof:

well, not seeing the output is expected, as you are explicitly telling that the request is finished.

The goal of fastcgi_finish_request is to finish the request (so that the client does not wait longer) but to continue the PHP process (to send mails, process images...)

In other words:

The shutdown functions are fully executed. But they simply cannot output anything anymore, because the response buffer was released to the client and terminated already.

Ideal solution

Skip this test if it runs on a CGI SAPI.

Problem: Simpletest does not have a proper way for skipping environment-dependent tests.

Next best solution

Check for a CGI SAPI within the test method and return early.

Problem: The test runner executes the test, so the SAPI is CLI, not cgi*. It is only cgi* in code running in response to requests to the child site.

Solution

See patch.

@rfay: Alrighty, this patch passed against HEAD, so now it's time to check whether it also works on a php-fpm SAPI. :)

Can't we change the test to write something to state or something else ... the test should not ensure that you can output stuff but that code is called in the shutdown function.

Here is a patch for 8.x which don't tests using print statments.

I think you included #2177041: Remove all implementations of hook_menu in that patch.

This time with way less changes.

Rerolled, at least the patch also applies on my local system now

Yes, that's much better!

Can we get a confirmation from someone with php-fpm that this now passes, looks RTBC from my side but I can't actually tests it. But I can't imagine why it wouldn't work?

We could always commit it and see what happens. :D

Let's do this.

Umm... I just tested it and, no, it doesn't work at all.

I manually tested on 5.3.28.

From what I can tell, shutdown functions are not called at all after fastcgi_finish_request() is called.
I was only able to get part of the test to pass by manually calling _drupal_shutdown_function() in drupal_handle_request() after send().

The check for the thrown exception is still checking for printed output as well.

Here's the workaround I have so far. Still not sure what to do with the exception checking.

Just kidding, the shutdown function has to come before the terminate() call to work.

In fact we need to remove all usages of register_shutdown_function() since this just will not work with php-fpm. Fortunately we already have an alternative. The kernel terminate event!

Let's not have two ways of doing this.

@alexpott, I agree 100%, but that is a much larger change, and this issue is muy importante.

Here's what I could come up with as a glorious stop-gap hack. I'm going to stop posting patches now, so I can review whatever gets proposed.

@alexpott: I don't think that the change in scope helps us in any way here, because we need to make this work for D7 and D6, too. Due to that, I'd recommend the D8 Kernel refactoring to happen in a separate issue.

@twistor: Your observations seem to be different than #9 — so either #9 is not correct (although the behavior is explained like this everywhere else on the net), or we actually need to manually trigger shutdown functions for FastCGI as in your proposed patch (which would look acceptable + backportable to me).

I was surprised by this as well, I haven't been able to find any explicit documentation on the matter, but I have found a few references that state fastcgi_finish_request() can be used, rather than register_shutdown_function().
http://stackoverflow.com/questions/14902917/can-i-use-fastcgi-finish-req...

My thought is that since fastcgi_finish_request() closes the connection, the behavior of shutdown functions would be changed, so they aren't called?

I'm going to get a 5.4 version fpm running and test this again to make sure that this isn't a version oddity.

Some research findings:

http://www.php.net/manual/en/function.register-shutdown-function.php#108212 essentially says that fastcgi_finish_request() can be used as a replacement for register_shutdown_function() (and exit()), but you need to manually control their invocation.

http://www.php.net/manual/en/function.register-shutdown-function.php#112746 says that shutdown functions are not invoked under FastCGI, unless you use ignore_user_abort(TRUE).

https://github.com/symfony/symfony/issues/6417 and https://bugs.php.net/bug.php?id=63963 are marginally related, interesting details about writing/closing the session in a FastCGI environment (and before possibly calling fastcgi_finish_request()).

After reading some further resources, I wonder what happens if you add an explicit exit() call at the end of index.php?

That solves the mystery. Adding exit() to the end of index.php calls the shutdown functions. It doesn't help us though, since they have to get called before terminate() to be able to do anything useful.

That could work for a fix for 7.x and 6.x.

The real fix for 8.x is as @alexpott mentions.

So, should we add a hack here for 8.x so that we can move on to 6.x and 7.x? Then really fix 8.x in a separate issue.

Or, we could decide that shutdown functions aren't guaranteed to have any Drupal apis available and change the test to write to a file or something.

TBH, I'd go with the approach and patch in #24 for all core versions.

The expectation is that (1) shutdown functions are executed and (2) shutdown functions are able to perform final cleanup tasks.

If necessary, we can definitely remove the test expectation which asserts that a shutdown function is able to produce output on-screen (as well as the expectation that an exception thrown in a shutdown function is printed on screen).

We can append an additional exit() call to the end of index.php, similarly wrapped in a function_exists() condition, so as to ensure that non-Drupal shutdown functions are executed, too (although I'm not sure whether that is Drupal's responsibility).

I don't get why we are not solving this for Drupal 8 in the correct way first. We've got a kernel with an event for this specific situation.

Here is a patch that does the absolute minimum to make Drupal 8 work correctly with php-fpm and actually makes no api changes.

#32 works fine for me. It's the best we can do and be backwards compatible. It is cleaner, I guess I wasn't focusing on where to put the hack. It seems to do it "properly" we'd need a service, or make calling code actually implement their own terminate event subscribers.

We still have 2 issues:

1. Do we support native shutdown functions? If so, then we need to call exit().
2. Can we simply remove the assumption that shutdown functions can print exceptions? (This seems non-negotiable, but we need a patch that does it.)

@sun, you mentioned that we should conditionally call exit(), is there a reason we can't always call it?

Just to clarify, #32 has only one failure left. The exception printing.

1. +++ b/core/core.services.yml
   @@ -102,6 +102,10 @@ services:
   +  drupal.shutdown:
   +    class: Drupal\Core\EventSubscriber\DrupalShutdown
   

   Not sure why we're prefixing this the service and class name with Drupal?

   All services are Drupal services and the namespace already dictates Drupal\Core...?

2. +++ b/core/lib/Drupal/Core/EventSubscriber/DrupalShutdown.php
   @@ -0,0 +1,58 @@
   +    // Set the CWD to DRUPAL_ROOT as it is not guaranteed to be the same as it
   +    // was in the normal context of execution.
   +    chdir(DRUPAL_ROOT);
   

   Since no longer called as a shutdown function, this chdir() and comment no longer applies.

3. +++ b/core/lib/Drupal/Core/EventSubscriber/DrupalShutdown.php
   @@ -0,0 +1,58 @@
   +    catch (Exception $exception) {
   

   This patch (hopefully) blows up all tests, because Exception is not rooted to the top-level namespace here.

   In case it does not, then this (additional) conversion attempt will have to resolve much larger error/exception handler issues in D8.

4. +++ b/core/lib/Drupal/Core/EventSubscriber/DrupalShutdown.php
   @@ -0,0 +1,58 @@
   +        print '<h1>Uncaught exception thrown in shutdown function.</h1>';
   +        print '<p>' . Error::renderExceptionSafe($exception) . '</p><hr />';
   ...
   +      error_log($exception);
   

   Likewise, since no longer called from a shutdown function, Drupal's regular exception handler should kick in...

   (I'm fairly sure it does not, or if it does, it blows up.)

   These detailed conversion aspects are essentially why I think we should not try to convert D8 in this issue. Especially because none of these workarounds are available in previous Drupal versions.

   The changes do not actually fix php-fpm support in Drupal core; they work around the problem in a different way (that is only available in D8). Due to that, the conversion attempt rather feels like a distraction here?

5. +++ b/core/lib/Drupal/Core/EventSubscriber/DrupalShutdown.php
   @@ -0,0 +1,58 @@
   +    $events[KernelEvents::TERMINATE][] = array('onKernelTerminate', 150);
   

   Since this is about shutdown function, I think the priority should use the lowest possible number; e.g., -1000.

I don't see how the terminate event is equivalent - register_shutdown_function() ensures that your code runs even in the case of a fatal error, that's required for DatabaseLockBackend at a minimum - the whole point of that is to ensure that locks don't persist beyond an individual request, which could otherwise mean the lock needs to expire before it can be broken again.

There might well be cases where we're using register_shutdown_function() and don't need to be, but that's a separate issue I think.

Ho hum. Changing our shutdown functions to terminate events is just not pretty. There are too many times we call exit; in our code. The last patch breaks the interactive installers session handling. Changing some of our shutdown functions to terminate events is going to require an awful lot of work.

So yep @sun and @catch you're right :)

Let's do the minimum to make this work on PHP-FPM.

Minor code style fix.

Where's the actual fix?

+++ b/core/modules/system/lib/Drupal/system/Tests/System/ShutdownFunctionsTest.php
@@ -36,11 +36,15 @@ function testShutdownFunctions() {
+    if (!function_exists('fastcgi_finish_request')) {
+      // If using PHP-FPM then fastcgi_finish_request() will have been fired
+      // preventing further output to the browser. Make sure exceptions
+      // displayed through \Drupal\Core\Utility\Error::renderExceptionSafe() are
+      // correctly escaped.
+      $this->assertRaw('Drupal is <blink>awesome</blink>.');

This won't work from the command line.

OK, seems like my comment somehow disappeared, writing it again.

So, shutdown functions are running in php-fpm ; they just do so after the end of the request as they were supposed too.

The only reason the patch in #17 isn't running successfully for the two state test is that there's a race condition: we're checking the state when the drupalGet returns, but at that point the shutdown functions are still running in the FPM thread. Adding a sleep(1) between the drupalGet and the assertEqual get thoses two assertions to pass reliably on fpm.

That still leaves us with the fact that there's no way to reliably show an exception thrown in a shutdown function in the browser, because at that point the connection to the client is closed. Not sure what to do here, shutdown functions were not really meant for conveying informations to the end user.

The only reason that the exception handling happens in there is to avoid the "Exception thrown without stacktrace" errors that are printed at the bottom of the page if that happens (for non-fpm).

And the only reason we have that test coverage there is that all such places were updated for the encoding stuff and then tests were written for them.

I think it's perfectly fine to drop those assertions and use error_log() or something like that.

How about this? The assert will only be made if fastcgi_finish_request() does not exist on the server under test.

DeFr++
twistor--

Dang, I thought I tested for exactly this, but I guess I failed. #41 is confirmed. It is a race condition.

We just need to handle the exception printing.

It does make me feel a little better about PHP.

The only thing missing is the proposed sleep() from #41.

Good point @DeFr!

Let's only sleep when necessary.

This looks golden.

Tested manually with 5.3.28 and 5.4.24.

Thanks again DeFr!

Edit: Assuming this comes back green of course.

Hi,
I think this may be related with my problem.
We run Apache2.4+php-fpm+PHP 5.4.19 and it seems register shutdown function from drupal is never called, at leat no data are written to database sessions.
Even installation failed on this:

Fatal error: Call to a member function isAuthenticated() on a non-object in /home/e/emil00/www/drupal8/core/includes/session.inc on line 253

It is failed becouse it presumes $user is object already from last access over SESSION, but it does not exists here.

Is it possible connection here? This seems as blocker issue for PHP5.4 and FPM.
I did try some search thru code, but it I am not familiar with drupal design.
I played with this, check for existence of $user and then play with login etc ( user is have changed last login timestamp), but nothing is written into session, I also put debugging file writes into _drupal_session_write from core/includes/session.inc, but PHP never hit this.

Do you think it may be related? Thanks

46: 2157053.46.patch queued for re-testing.

+++ b/core/includes/bootstrap.inc
@@ -2623,12 +2623,16 @@ function _drupal_shutdown_function() {
+    // If using PHP-FPM then fastcgi_finish_request() will have been fired
+    // preventing further output to the browser.
+    if (!function_exists('fastcgi_finish_request')) {

I don't really see why we need this special handling/condition? With FastCGI, the output will simply not be printed?

In other words, we can leave a comment, but the extra logic condition appears to be unnecessary?

Aside from that minor issue, this patch looks good to me.

46: 2157053.46.patch queued for re-testing.

re #51 but why bother printing anything when you know it's no going to appear anywhere?

As mentioned, the remark was minor, I just don't think the condition is necessary, since FastCGI will not output anything in the first place, so why bother? ;)

Let's move forward here :)

Hopefully, the backports will work mostly as-is. Speaking of, tagging accordingly.

I would assign to alexpott, but he rolled the last patch. Darn. :)

Given the direction this patch has taken has had many twists and turns, I'd like to leave it for at least a day, but then I'm happy to commit it, if catch/Dries don't get to it first.

This is fine with me, and has been about a day now. Committed/pushed to 8.x, thanks!

I think there's nothing to backport to either D7 or D6 here.

The only reason FPM is acting differently here is because D8 now explicitely (through Symfony) calls fastcgi_finish_request if it's defined to close the connection slightly earlier to get a client side performance boost. Neither D7 nor D6 do that, so the connection is closed with FPM at the same time as for the other PHP SAPIs and shutdown functions can thus output text to the client without problem there.

(I confirmed this locally by running the D7 Shutdown functions tests in FPM, and it's passing just fine)

TBH, I wasn't aware that we're actually working around a problem that is caused by Symfony. That feels a bit weird/nuts ;)

But in any case, thanks a ton to both of you, @DeFr and @twistor, for massively helping out here by actually testing + debugging on php-fpm. That was super-helpful!

Given that, let's move on to the other remaining php-fpm issues, I guess?

@DeFr, I'm trying to use shutdown function on D7 on php-fpm setup, and it's not being called. Thought that could be related to this issue... Could you please look at this question: http://drupal.stackexchange.com/q/102603/10667 -- and help me figure out what I'm doing wrong?

@Shevchuk: Answered on stackexchange. Long story short: you can't call drupal_set_message in a shutdown function because the session was already written to the database. That's what dpm is using internally, so it's a bad check.

@sun: I guess it can be seen either as a feature or a bug ; there's a bunch of parts in D7 that actually somehow hopes that the connection to the client was in fact closed, which just doesn't happen as is. See for the example the documentation of hook_exit, which specifies that all hook_exit implementation are not supposed to print anything, which is even more true for shutdown functions that runs even later. Another example is that for some users in D7, for all those sites that are not configured to run cron cleanly and falls back to the system built in cron, the request between the server and the client is only closed after all the cron tasks actually got executed.

I don't want to re-open this issue, but I just want to add something here.

I was testing Devel 8.x and I wasn't able to display the query log.
Why ? Because it uses a PHP shutdown function to display the log. But since Symfony triggers a fastcgi_finish_request in Response::Send() this is not working anymore.

I think Devel might not be the only only that was trying to send outputs during the shutdown. We need to know that this is not working anymore now (with PHP-FPM).