Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Exceptions thrown after kernel.terminate event are silently swallowed (i.e. not logged anywhere). #19078

Closed
d-ph opened this issue Jun 16, 2016 · 10 comments

Comments

Projects
None yet
5 participants
@d-ph
Copy link

commented Jun 16, 2016

Hello,

This problem spans over these projects:

  1. Symfony\Component\Debug
  2. Symfony\Component\HttpKernel\HttpKernel
  3. https://github.com/symfony/symfony-standard

Since all of them live under the Symfony umbrella, I decided to report the problem here.

You might want to get a cup of tea/coffee before continuing reading.


Steps to reproduce:

  1. Get a hold of an nginx + php-fpm7.0 stack.
  2. Make sure the fpm pool has catch_workers_output enabled (on puphpet's Ubuntu, uncomment that option in this file: /etc/php/7.0/fpm/pool.d/www.conf and restart the php-fpm service)
  3. Create an index.php file with this content:
<?php
echo 'Hi';
fastcgi_finish_request();
throw new \Exception('lorem ipsum');

4.Run this file from your favourite browser.

Result:
Your browser renders the word Hi and the response was 200. The exception message has been logged to fpm's log file (on puphpet's Ubuntu, the fpm's log file sits in: /var/log/upstart/php7.0-fpm.log).

5.Install symfony standard edition.
6.Replace DefaultController::indexAction's body with this:

        $eventDispatcher = $this->get('event_dispatcher');
        $eventDispatcher->addListener('kernel.terminate', function (PostResponseEvent $event) {
            throw new \Exception('exception from kernel.terminate listener');
        });

        return new Response('foo');

Don't forget to import Response and PostResponseEvent classes.

7.Access app_dev.php from your favourite browser.

Result:
Your browser renders the word foo and the response was 200. The exception message is not logged anywhere. It's not logged to fpm's log file or symfony's log file. Obviously it's also not logged to nginx' log file, because as far as nginx is concerned, the request was successful.

Expected result:
Great question. I'd say that the exception should at least be logged (both it's message and the stack) to fpm's log file, similar to what happened after step 4.


More details of the problem:

  1. If you comment this line: Debug::enable(); in app_dev.php, then the expected result happens.
  2. The problem is related with the fact, that HttpKernel::terminateWithException() is called after the kernel has already started to terminate. This method is registered as an exception handler by Symfony\Component\HttpKernel\EventListener\DebugHandlersListener::configure():
if ($event instanceof KernelEvent) {
    if (method_exists($event->getKernel(), 'terminateWithException')) {
        $this->exceptionHandler = array($event->getKernel(), 'terminateWithException');
    }
}

In that case, HttpKernel::terminateWithException() throws:

throw new \LogicException('Request stack is empty', 0, $exception);

3.The problem is related with the fact, that Symfony\Component\Debug\ExceptionHandler::handle() tries to compose and send a response with a pretty error page, but after the kernel.terminate event, the response has already been sent.


The solution I was thinking about:

Unregister the Symfony\Component\Debug\ExceptionHandler before the $kernel->terminate($request, $response); is called in app_dev.php, because there is no point in sending a pretty error page, when the response is already sent to the client. There is no way to do that currently. To simulate that just to see whether it works, please put these lines at the beginning of the Symfony\Component\Debug\ExceptionHandler::handle()'s body:

if ($this->handler) {
    call_user_func($this->handler, $exception);
}

return;

If you rerun the app_dev.php now, you will see it works. This still leaves us with HttpKernel::terminateWithException() being called after the kernel.terminate event to fix. I thought of a private HttpKernel::$terminating = false; field, that is set to true in the HttpKernel::terminate() method. That way, I could do:

public function terminateWithException(\Exception $exception)
{
    if ($this->terminating) {
        return;
    }

If you do this and run the app_dev.php again, you will see that it's broken again.

I decided to leave the HttpKernel intact and xdebug carefully, what's going on. I discovered, that the change in Symfony\Component\Debug\ExceptionHandler::handle() is enough, because of some sort of a side effect caused by HttpKernel::terminateWithException()'s throwing an exception. This was the moment, when I decided to give up and ask for an advice.

So yes, could I get some help in resolving this issue, please?

Thanks

@nicolas-grekas

This comment has been minimized.

Copy link
Member

commented Jun 16, 2016

Good idea, PR welcomed :)

@d-ph

This comment has been minimized.

Copy link
Author

commented Jun 16, 2016

I don't know how to fix this properly. As I said, applying the fix in Symfony\Component\Debug\ExceptionHandler::handle() method fixes the problem, but the fix relies on some sort of side effect. This can be clearly seen with xdebug, when you step instruction by instruction starting in the Symfony\Component\Debug\ExceptionHandler::handle() method.

@nicolas-grekas

This comment has been minimized.

Copy link
Member

commented Jun 17, 2016

Could you please try #19084?

@d-ph

This comment has been minimized.

Copy link
Author

commented Jun 17, 2016

Hi,

Yes, I'll try it in a minute. Just a couple of thoughts before I do anything:

  1. Bear in mind, that it won't fix this ticket, as you mentioned in #19084. It will fix the fact, that symfony tries to terminate an already terminating kernel which is a related issue, not the core issue
  2. Your fix assumes, that the "top" php's error handler is the one appended by DebugHandlersListener::configure(). There is no guarantee, that it's going to be true. This is my gripe with php's set_exception_handler() -- you cannot reliably iterate over currently registered handlers and deregister the one you're interested in. In my opinion it would be more reliable, if... ok, let me fork your branch and let me show you what I'd do instead. But again, please keep in mind the point 1. -- #19084 won't fix this ticket.

Thanks and stay tuned for my push.

@nicolas-grekas

This comment has been minimized.

Copy link
Member

commented Jun 17, 2016

It will fix the fact, that symfony tries to terminate an already terminating kernel which is a related issue, not the core issue

Not sure why you say this. What the PR fixes is generating an HTML page after the request has been sent, which makes no sense and is the root issue that prevents the native exception handler to be caller by mean of throwing after tentatively logging the exception (which is not possible when the logger is closed).

Your fix assumes, that the "top" php's error handler is the one appended

Yes, and it's perfectly fine: each stacking level is responsible for it's own level. We don't have to deal with others codes bugs, especially in such critical areas as error handling (and btw, nobody writes such code at the app level, error handling is a framework-only thing).

@d-ph

This comment has been minimized.

Copy link
Author

commented Jun 17, 2016

image

Your fix doesn't work when Debug::enable() is called in app_dev.php. That's because the reason I mentioned in point 2.

When Debug::enable() is not called (i.e. no other code tries to set_exception_handler()), then your fix works, because your assumption is correct then (the "top" excepiton_handler is the one we're setting in the configure()).

Let me show you my idea, please.

@d-ph

This comment has been minimized.

Copy link
Author

commented Jun 17, 2016

Fyi, I will get back to this later today. I've got some dependencies conflicts while pulling my github branch with symfony into my project via composer and I don't want to spend more time on this right now. Soz

@d-ph

This comment has been minimized.

Copy link
Author

commented Jun 18, 2016

Hi again.

nicolas-grekas@68aa421

This change fixes the fact, that Kernel::terminateWithException is called by the DebugHandlersListener after Kernel is already terminating.

Again: it fixes a related problem to this ticket. I doesn't fix the problem itself -- the exception thrown after the kernel.terminate is still not logged in fpm logs (or anywhere else, for that matter)

@nicolas-grekas

This comment has been minimized.

Copy link
Member

commented Jun 20, 2016

See #19114

fabpot added a commit that referenced this issue Jun 20, 2016

bug #19114 [HttpKernel] Dont close the reponse stream in debug (nicol…
…as-grekas)

This PR was merged into the 2.7 branch.

Discussion
----------

[HttpKernel] Dont close the reponse stream in debug

| Q             | A
| ------------- | ---
| Branch?       | 2.7
| Bug fix?      | yes
| New feature?  | no
| BC breaks?    | no
| Deprecations? | no
| Tests pass?   | yes
| Fixed tickets | #19078
| License       | MIT
| Doc PR        | -

Because it's `terminate`'s job to clean the state, not the `Response`'s,
and because the current behavior prevents getting any output on trailing errors on FPM especially.

Commits
-------

2fbc200 [HttpKernel] Dont close the output stream in debug

@fabpot fabpot closed this Jun 20, 2016

@d-ph

This comment has been minimized.

Copy link
Author

commented Jun 29, 2016

Sorry for a late reply.

Yeah, this change allows the post-kernel-terminate errors to come to developer's attention. But also, that change essentially disables the ability to schedule stuff to be done after the response is sent, when kernel.debug is true (because the new code never finishes the fastcgi request when the kernel.debug = true). It feels like a regression to me. Regardless, I'm ok to leave this ticket closed.

@nicolas-grekas nicolas-grekas self-assigned this Nov 27, 2017

fabpot added a commit that referenced this issue Dec 11, 2017

bug #25410 [HttpKernel] Fix logging of post-terminate errors/exceptio…
…ns (nicolas-grekas)

This PR was merged into the 2.7 branch.

Discussion
----------

[HttpKernel] Fix logging of post-terminate errors/exceptions

| Q             | A
| ------------- | ---
| Branch?       | 2.7
| Bug fix?      | yes
| New feature?  | no
| BC breaks?    | no
| Deprecations? | no
| Tests pass?   | yes
| Fixed tickets | #19078
| License       | MIT
| Doc PR        | -

After terminate, the request stack is empty, thus `terminateWithException` currently fails, preventing listeners to know about the failure.

Commits
-------

e85b371 [HttpKernel] Fix logging of post-terminate errors/exceptions

@fabpot fabpot closed this Dec 11, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.