An exception was thrown by the bridge (from user's code)

[stepanselyuk]

Hello,
I got:

HTTP/1.1 502 Bad Gateway
Server: nginx/1.16.1
Date: Mon, 07 Oct 2019 19:17:32 GMT
Content-Type: text/plain
Content-Length: 88
Connection: close

Slave returned an invalid HTTP response. Maybe the script has called exit() prematurely?

Instead of normal Symfony's error-500, that's caused by my error in the application. But just I don't know why php-pm died on that, cause that error was on the application/payload level. Here the log:

cdp-web-web           | --- Worker 5501 stderr ---
cdp-web-web           | An exception was thrown by the bridge. Forcing restart of the worker. The exception was: Error: Call to undefined method App\Entity\AccessToken::getUser() in /var/www/src/Security/AccessTokenAuthenticator.php:55
cdp-web-web           | Stack trace:
cdp-web-web           | #0 /var/www/vendor/symfony/security-guard/Provider/GuardAuthenticationProvider.php(101): App\Security\AccessTokenAuthenticator->getUser('ae7862e86dc110e...', Object(Symfony\Bridge\Doctrine\Security\User\EntityUserProvider))
cdp-web-web           | #1 /var/www/vendor/symfony/security-guard/Provider/GuardAuthenticationProvider.php(95): Symfony\Component\Security\Guard\Provider\GuardAuthenticationProvider->authenticateViaGuard(Object(App\Security\AccessTokenAuthenticator), Object(Symfony\Component\Security\Guard\Token\PreAuthenticationGuardToken))
cdp-web-web           | #2 /var/www/vendor/symfony/security-core/Authentication/AuthenticationProviderManager.php(80): Symfony\Component\Security\Guard\Provider\GuardAuthenticationProvider->authenticate(Object(Symfony\Component\Security\Guard\Token\PreAuthenticationGuardToken))
cdp-web-web           | #3 /var/www/vendor/symfony/security-guard/Firewall/GuardAuthenticationListener.php(135): Symfony\Component\Security\Core\Authentication\AuthenticationProviderManager->authenticate(Object(Symfony\Component\Security\Guard\Token\PreAuthenticationGuardToken))
cdp-web-web           | #4 /var/www/vendor/symfony/security-guard/Firewall/GuardAuthenticationListener.php(87): Symfony\Component\Security\Guard\Firewall\GuardAuthenticationListener->executeGuardAuthenticator('main_1', Object(App\Security\AccessTokenAuthenticator), Object(Symfony\Component\HttpKernel\Event\RequestEvent))
cdp-web-web           | #5 /var/www/vendor/symfony/security-http/Firewall.php(139): Symfony\Component\Security\Guard\Firewall\GuardAuthenticationListener->__invoke(Object(Symfony\Component\HttpKernel\Event\RequestEvent))
cdp-web-web           | #6 /var/www/vendor/symfony/security-http/Firewall.php(129): Symfony\Component\Security\Http\Firewall->handleRequest(Object(Symfony\Component\HttpKernel\Event\RequestEvent), Object(Generator))
cdp-web-web           | #7 /var/www/vendor/symfony/security-http/Firewall.php(97): Symfony\Component\Security\Http\Firewall->callListeners(Object(Symfony\Component\HttpKernel\Event\RequestEvent), Object(Generator))
cdp-web-web           | #8 /var/www/vendor/symfony/event-dispatcher/EventDispatcher.php(298): Symfony\Component\Security\Http\Firewall->onKernelRequest(Object(Symfony\Component\HttpKernel\Event\RequestEvent), 'kernel.request', Object(Symfony\Component\EventDispatcher\EventDispatcher))
cdp-web-web           | #9 /var/www/vendor/symfony/event-dispatcher/EventDispatcher.php(260): Symfony\Component\EventDispatcher\EventDispatcher::Symfony\Component\EventDispatcher\{closure}(Object(Symfony\Component\HttpKernel\Event\RequestEvent), 'kernel.request', Object(Symfony\Component\EventDispatcher\EventDispatcher))
cdp-web-web           | #10 /var/www/vendor/symfony/event-dispatcher/EventDispatcher.php(235): Symfony\Component\EventDispatcher\EventDispatcher->doDispatch(Array, 'kernel.request', Object(Symfony\Component\HttpKernel\Event\RequestEvent))
cdp-web-web           | #11 /var/www/vendor/symfony/event-dispatcher/EventDispatcher.php(73): Symfony\Component\EventDispatcher\EventDispatcher->callListeners(Array, 'kernel.request', Object(Symfony\Component\HttpKernel\Event\RequestEvent))
cdp-web-web           | #12 /var/www/vendor/symfony/http-kernel/HttpKernel.php(127): Symfony\Component\EventDispatcher\EventDispatcher->dispatch(Object(Symfony\Component\HttpKernel\Event\RequestEvent), 'kernel.request')
cdp-web-web           | #13 /var/www/vendor/symfony/http-kernel/HttpKernel.php(68): Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object(Symfony\Component\HttpFoundation\Request), 1)
cdp-web-web           | #14 /var/www/vendor/symfony/http-kernel/Kernel.php(198): Symfony\Component\HttpKernel\HttpKernel->handle(Object(Symfony\Component\HttpFoundation\Request), 1, true)
cdp-web-web           | #15 /ppm/vendor/php-pm/httpkernel-adapter/Bridges/HttpKernel.php(87): Symfony\Component\HttpKernel\Kernel->handle(Object(Symfony\Component\HttpFoundation\Request))
cdp-web-web           | #16 /ppm/vendor/php-pm/php-pm/src/ProcessSlave.php(433): PHPPM\Bridges\HttpKernel->handle(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #17 /ppm/vendor/php-pm/php-pm/src/ProcessSlave.php(397): PHPPM\ProcessSlave->handleRequest(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #18 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(49): PHPPM\ProcessSlave->onRequest(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #19 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(54): React\Http\Io\MiddlewareRunner->call(Object(React\Http\Io\ServerRequest), 3)
cdp-web-web           | #20 /ppm/vendor/react/http/src/Middleware/RequestBodyParserMiddleware.php(34): React\Http\Io\MiddlewareRunner->React\Http\Io\{closure}(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #21 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(59): React\Http\Middleware\RequestBodyParserMiddleware->__invoke(Object(React\Http\Io\ServerRequest), Object(Closure))
cdp-web-web           | #22 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(54): React\Http\Io\MiddlewareRunner->call(Object(React\Http\Io\ServerRequest), 2)
cdp-web-web           | #23 /ppm/vendor/react/http/src/Middleware/RequestBodyBufferMiddleware.php(44): React\Http\Io\MiddlewareRunner->React\Http\Io\{closure}(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #24 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(59): React\Http\Middleware\RequestBodyBufferMiddleware->__invoke(Object(React\Http\Io\ServerRequest), Object(Closure))
cdp-web-web           | #25 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(54): React\Http\Io\MiddlewareRunner->call(Object(React\Http\Io\ServerRequest), 1)
cdp-web-web           | #26 /ppm/vendor/react/http/src/Middleware/LimitConcurrentRequestsMiddleware.php(91): React\Http\Io\MiddlewareRunner->React\Http\Io\{closure}(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #27 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(59): React\Http\Middleware\LimitConcurrentRequestsMiddleware->__invoke(Object(React\Http\Io\ServerRequest), Object(Closure))
cdp-web-web           | #28 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(40): React\Http\Io\MiddlewareRunner->call(Object(React\Http\Io\ServerRequest), 0)
cdp-web-web           | #29 /ppm/vendor/react/http/src/StreamingServer.php(239): React\Http\Io\MiddlewareRunner->__invoke(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #30 /ppm/vendor/react/http/src/StreamingServer.php(176): React\Http\StreamingServer->handleRequest(Object(React\Socket\Connection), Object(React\Http\Io\ServerRequest))
cdp-web-web           | #31 /ppm/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Http\StreamingServer->React\Http\{closure}(Object(React\Http\Io\ServerRequest), '')
cdp-web-web           | #32 /ppm/vendor/react/http/src/Io/RequestHeaderParser.php(59): Evenement\EventEmitter->emit('headers', Array)
cdp-web-web           | #33 /ppm/vendor/react/http/src/Io/RequestHeaderParser.php(47): React\Http\Io\RequestHeaderParser->parseAndEmitRequest(463)
cdp-web-web           | #34 /ppm/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Http\Io\RequestHeaderParser->feed('GET /api/accoun...')
cdp-web-web           | #35 /ppm/vendor/react/stream/src/Util.php(71): Evenement\EventEmitter->emit('data', Array)
cdp-web-web           | #36 /ppm/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Stream\Util::React\Stream\{closure}('GET /api/accoun...')
cdp-web-web           | #37 /ppm/vendor/react/stream/src/DuplexResourceStream.php(193): Evenement\EventEmitter->emit('data', Array)
cdp-web-web           | #38 /ppm/vendor/react/event-loop/src/StreamSelectLoop.php(244): React\Stream\DuplexResourceStream->handleData(Resource id #393)
cdp-web-web           | #39 /ppm/vendor/react/event-loop/src/StreamSelectLoop.php(211): React\EventLoop\StreamSelectLoop->waitForStreamActivity(NULL)
cdp-web-web           | #40 /ppm/vendor/php-pm/php-pm/src/ProcessSlave.php(356): React\EventLoop\StreamSelectLoop->run()
cdp-web-web           | #41 /tmp/dbgJddOkp(36): PHPPM\ProcessSlave->run()
cdp-web-web           | #42 {main}
cdp-web-web           | Worker #5501 closed after 0 handled requests
cdp-web-web           | Start new worker #5501
cdp-web-web           | Script did not return a valid HTTP response. Maybe it has called exit() prematurely?
cdp-web-web           | Worker #5501 registered. Waiting for application bootstrap ... 
cdp-web-web           | Worker #5501 ready.

Environment:

php-pm/php-pm:2.0.1
php-pm/httpkernel-adapter:2.0.2
PHP 7.3.9
Symfony 4.3.4
Debug: 0

[andig]

Could you provide an example to repro this?

[andig]

Actually, I feel this is the desired behavior. If client throws without catching we close the slave as we don't know whats wrong. What is the actual problem you're having with this?

[stepanselyuk]

Well, I believe the client (the end-user, browser) should receive what Symfony sent to it, Error 500 with headers, but not just 502 error from Nginx over php-pm. In the case of development mode and with debug=0, I need every time to reach php-pm logs instead of just getting what's wrong from the answer. Maybe php-pm can just retranslate any exception to the user?

Another example I got suddenly (updated configuration) and it persisted before I removed the cache completely. It's Symfony (level) error. I cannot catch this. Maybe in production mode, this behavior is okay cause some external logger usually used and deployment scaled to many pods.

cdp-web-web           | --- Worker 5501 stderr ---
cdp-web-web           | An exception was thrown by the bridge. Forcing restart of the worker. The exception was: LogicException: Resetting a non-lazy manager service is not supported. Declare the "doctrine.orm.default_entity_manager" service as lazy. in /var/www/vendor/symfony/doctrine-bridge/ManagerRegistry.php:49
cdp-web-web           | Stack trace:
cdp-web-web           | #0 /var/www/vendor/doctrine/persistence/lib/Doctrine/Common/Persistence/AbstractManagerRegistry.php(233): Symfony\Bridge\Doctrine\ManagerRegistry->resetService('doctrine.orm.de...')
cdp-web-web           | #1 /ppm/vendor/php-pm/httpkernel-adapter/Bootstraps/Symfony.php(172): Doctrine\Common\Persistence\AbstractManagerRegistry->resetManager('default')
cdp-web-web           | #2 /ppm/vendor/php-pm/httpkernel-adapter/Bridges/HttpKernel.php(101): PHPPM\Bootstraps\Symfony->postHandle(Object(App\Kernel))
cdp-web-web           | #3 /ppm/vendor/php-pm/php-pm/src/ProcessSlave.php(433): PHPPM\Bridges\HttpKernel->handle(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #4 /ppm/vendor/php-pm/php-pm/src/ProcessSlave.php(397): PHPPM\ProcessSlave->handleRequest(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #5 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(49): PHPPM\ProcessSlave->onRequest(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #6 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(54): React\Http\Io\MiddlewareRunner->call(Object(React\Http\Io\ServerRequest), 3)
cdp-web-web           | #7 /ppm/vendor/react/http/src/Middleware/RequestBodyParserMiddleware.php(27): React\Http\Io\MiddlewareRunner->React\Http\Io\{closure}(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #8 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(59): React\Http\Middleware\RequestBodyParserMiddleware->__invoke(Object(React\Http\Io\ServerRequest), Object(Closure))
cdp-web-web           | #9 /ppm/vendor/react/http/src/Io/MiddlewareRunner.php(54): React\Http\Io\MiddlewareRunner->call(Object(React\Http\Io\ServerRequest), 2)
cdp-web-web           | #10 /ppm/vendor/react/http/src/Middleware/RequestBodyBufferMiddleware.php(58): React\Http\Io\MiddlewareRunner->React\Http\Io\{closure}(Object(React\Http\Io\ServerRequest))
cdp-web-web           | #11 /ppm/vendor/react/promise/src/FulfilledPromise.php(25): React\Http\Middleware\RequestBodyBufferMiddleware->React\Http\Middleware\{closure}('login=user1%40r...')
cdp-web-web           | #12 /ppm/vendor/react/promise/src/Promise.php(134): React\Promise\FulfilledPromise->then(Object(Closure), Object(Closure))
cdp-web-web           | #13 /ppm/vendor/react/promise/src/Promise.php(168): React\Promise\Promise::React\Promise\{closure}(Object(React\Promise\FulfilledPromise))
cdp-web-web           | #14 /ppm/vendor/react/promise/src/Promise.php(231): React\Promise\Promise->settle(Object(React\Promise\FulfilledPromise))
cdp-web-web           | #15 /ppm/vendor/react/promise/src/FulfilledPromise.php(39): React\Promise\Promise::React\Promise\{closure}('login=user1%40r...')
cdp-web-web           | #16 /ppm/vendor/react/promise/src/Promise.php(135): React\Promise\FulfilledPromise->done(Object(Closure), Object(Closure), Object(Closure))
cdp-web-web           | #17 /ppm/vendor/react/promise/src/Promise.php(168): React\Promise\Promise::React\Promise\{closure}(Object(React\Promise\FulfilledPromise))
cdp-web-web           | #18 /ppm/vendor/react/promise/src/Promise.php(231): React\Promise\Promise->settle(Object(React\Promise\FulfilledPromise))
cdp-web-web           | #19 /ppm/vendor/react/promise-stream/src/functions.php(75): React\Promise\Promise::React\Promise\{closure}('login=user1%40r...')
cdp-web-web           | #20 /ppm/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Promise\Stream\{closure}()
cdp-web-web           | #21 /ppm/vendor/react/http/src/Io/HttpBodyStream.php(80): Evenement\EventEmitter->emit('close')
cdp-web-web           | #22 /ppm/vendor/react/http/src/Io/HttpBodyStream.php(179): React\Http\Io\HttpBodyStream->close()
cdp-web-web           | #23 /ppm/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Http\Io\HttpBodyStream->handleEnd()
cdp-web-web           | #24 /ppm/vendor/react/http/src/Io/LengthLimitedStream.php(87): Evenement\EventEmitter->emit('end')
cdp-web-web           | #25 /ppm/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Http\Io\LengthLimitedStream->handleData('login=user1%40r...')
cdp-web-web           | #26 /ppm/vendor/react/http/src/Io/CloseProtectionStream.php(96): Evenement\EventEmitter->emit('data', Array)
cdp-web-web           | #27 /ppm/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Http\Io\CloseProtectionStream->handleData('login=user1%40r...')
cdp-web-web           | #28 /ppm/vendor/react/http/src/StreamingServer.php(179): Evenement\EventEmitter->emit('data', Array)
cdp-web-web           | #29 /ppm/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Http\StreamingServer->React\Http\{closure}(Object(React\Http\Io\ServerRequest), 'login=user1%40r...')
cdp-web-web           | #30 /ppm/vendor/react/http/src/Io/RequestHeaderParser.php(59): Evenement\EventEmitter->emit('headers', Array)
cdp-web-web           | #31 /ppm/vendor/react/http/src/Io/RequestHeaderParser.php(47): React\Http\Io\RequestHeaderParser->parseAndEmitRequest(357)
cdp-web-web           | #32 /ppm/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Http\Io\RequestHeaderParser->feed('POST /get-acces...')
cdp-web-web           | #33 /ppm/vendor/react/stream/src/Util.php(71): Evenement\EventEmitter->emit('data', Array)
cdp-web-web           | #34 /ppm/vendor/evenement/evenement/src/Evenement/EventEmitterTrait.php(123): React\Stream\Util::React\Stream\{closure}('POST /get-acces...')
cdp-web-web           | #35 /ppm/vendor/react/stream/src/DuplexResourceStream.php(193): Evenement\EventEmitter->emit('data', Array)
cdp-web-web           | #36 /ppm/vendor/react/event-loop/src/StreamSelectLoop.php(244): React\Stream\DuplexResourceStream->handleData(Resource id #394)
cdp-web-web           | #37 /ppm/vendor/react/event-loop/src/StreamSelectLoop.php(211): React\EventLoop\StreamSelectLoop->waitForStreamActivity(NULL)
cdp-web-web           | #38 /ppm/vendor/php-pm/php-pm/src/ProcessSlave.php(356): React\EventLoop\StreamSelectLoop->run()
cdp-web-web           | #39 /tmp/dbglnoMNP(36): PHPPM\ProcessSlave->run()
cdp-web-web           | #40 {main}
cdp-web-web           | Worker #5501 closed after 0 handled requests
cdp-web-web           | Start new worker #5501
cdp-web-web           | Script did not return a valid HTTP response. Maybe it has called exit() prematurely?

[dnna]

I remember this issue and its a tricky one, because, on the one hand, the behavior is correct (the slave should definitely not handle any more requests after the exception) but on the other hand, this behavior prevents us from sending a proper response to the browser (as the slave closes abruptly).

I'm not sure if there is a way to have the slave return a response and then close without serving any more requests? I don't think this can be implemented on the bridge level alone, because afaik if the bridge returns a response it cannot control whether the slave will close or not. @andig any ideas?

[andig]

To summarize the discussion sofar: currently- when client throws- PPM returns:

HTTP/1.1 502 Bad Gateway
Slave returned an invalid HTTP response. Maybe the script has called exit() prematurely?

Instead, it should return (an exception response as Symfony does?) with HTTP 500.

[dnna]

If you ask me, ideally the behavior should be that if debug is true it would return the exception message and the stack trace to the browser, while if its false it would show a generic message like "An error occurred" and just log the actual exception as usual.