ParseError Causes Unresponsive Worker

freshleafmedia commented 1 year ago

Describe the bug

When the code contains a syntax error the RR worker locks up and never responds.

Expected behaviour

An Ignition debug page

Actual behaviour

RR worker goes to 100% CPU and the browser times out

Steps to reproduce

Install completely vanilla Laravel
Install RR integration
Write code with syntax error. Eg:

routes/web.php

<?php

use Illuminate\Support\Facades\Route;

Route::get('/', function () {
    return view('welcome');
});

syntaxerror

System information

Key	Value
PHP version	`8.2.9`
Current package version	`v5.12.0`
RoadRunner version	`2023.2.0`
Environment	`docker`
Laravel version	`10.20.0`

RoadRunner configuration file content

version: "3"

http:
  address: 0.0.0.0:8000
  pool:
    debug: true

server:
  command: "php ./vendor/bin/rr-worker start --relay-dsn unix:///var/run/rr-relay.sock"
  relay: "unix:///var/run/rr-relay.sock"

rpc:
  listen: tcp://127.0.0.1:6001

Package configuration file content

Using the default

https://github.com/roadrunner-php/laravel-bridge/blob/v5.12.0/config/roadrunner.php

Additional context

If I add logging to the .rr.yaml:

logs:
  mode: production
  level: debug
  output: stdout
  encoding: json

I can see the following, and it just keeps repeating:

(lines truncated for brevity)

{"level":"debug","ts":1693066706217844325,"logger":"rpc","msg":"plugin was started","address":"tcp://127.0.0.1:6001","list of the plugins with RPC methods:":["lock","informer","app","resetter"]}
{"level":"debug","ts":1693066706218196887,"logger":"http","msg":"http server was started","address":"0.0.0.0:8000"}
[INFO] RoadRunner server started; version: 2023.2.2, buildtime: 2023-08-10T16:38:53+0000
{"level":"debug","ts":1693066724545294964,"logger":"server","msg":"worker is allocated","pid":15,"internal_event_name":"EventWorkerConstruct"}
{"level":"debug","ts":1693066724592002773,"logger":"server","msg":"sending stop request to the worker","pid":15}
{"level":"info","ts":1693066724608827321,"logger":"http","msg":"http log","status":200,"method":"GET","URI":"/","remote_address":"172.17.0.1:59198","read_bytes":0,"write_bytes":27514,"start":169306672
{"level":"debug","ts":1693066725075147149,"logger":"server","msg":"worker is allocated","pid":18,"internal_event_name":"EventWorkerConstruct"}
{"level":"debug","ts":1693066725111879408,"logger":"server","msg":"sending stop request to the worker","pid":18}
{"level":"debug","ts":1693066725132054119,"logger":"server","msg":"stderr","error":"read |0: file already closed"}
{"level":"info","ts":1693066725132635926,"logger":"http","msg":"http log","status":404,"method":"GET","URI":"/favicon.ico","remote_address":"172.17.0.1:59198","read_bytes":0,"write_bytes":6603,"start"
{"level":"info","ts":1693066736498534539,"logger":"server","msg":"<!DOCTYPE html>\n<html lang=\"en\" class=\"auto\">\n<!--\nParseError: syntax error, unexpected end of file in file /var/www/vhosts/tmp
{"level":"info","ts":1693066736499277807,"logger":"server","msg":".\",\"42\":\"     *\",\"43\":\"     * @param  \\\\Illuminate\\\\Container\\\\Container  $container\",\"44\":\"     * @param  string  $
{"level":"info","ts":1693066736499838389,"logger":"server","msg":"/\\/ for any listeners that need to do work after this initial booting gets\",\"987\":\"        \\/\\/ finished. This is useful when o
{"level":"info","ts":1693066736500500296,"logger":"server","msg":"}}var U=a;t.unstable_IdlePriority=5,t.unstable_ImmediatePriority=1,t.unstable_LowPriority=4,t.unstable_NormalPriority=3,t.unstable_Pro
{"level":"info","ts":1693066736501057659,"logger":"server","msg":"To solve this, you can either unmount the component at the end of your test (and ensure that any asynchronous operations get canceled 
{"level":"info","ts":1693066736501616268,"logger":"server","msg":"with componentDidUpdate(). This component defines getSnapshotBeforeUpdate() only.\",We(t))),\"function\"==typeof r.getDerivedStateFrom
{"level":"info","ts":1693066736502188894,"logger":"server","msg":"ate;if(0!=(t.flags&ar))return t.lanes=n,0!=(8&t.mode)&&xd(t),t;var k=null!==x,A=!1;return null===e?void 0!==t.memoizedProps.fallback&&
{"level":"info","ts":1693066736502850481,"logger":"server","msg":",(e.documentElement.firstElementChild||e.documentElement.children[0]).appendChild(t),t=e.createElement(\"style\"),(e.documentElement.f
{"level":"info","ts":1693066736509620006,"logger":"server","msg":"ments[1]:{},n=t.transform,r=void 0===n?hn:n,a=t.symbol,o=void 0!==a&&a,i=t.mask,l=void 0===i?null:i,s=t.maskId,c=void 0===s?null:s,u=t
{"level":"info","ts":1693066736510763307,"logger":"server","msg":"tains `self` is not supported at the top-level of a language.  See documentation.\");return e.classNameAliases=hi(e.classNameAliases||
{"level":"info","ts":1693066736514137959,"logger":"server","msg":"kenizer().tokenize(e),this.getFormattedQueryFromTokens().trim()}},{key:\"getFormattedQueryFromTokens\",value:function(){var e=this,t=\
{"level":"info","ts":1693066736514707529,"logger":"server","msg":"ect.create(t&&t.prototype,{constructor:{value:e,writable:!0,configurable:!0}}),t&&l(e,t)}(m,e);var t,n,r,o=(n=m,r=function(){if(\"unde
{"level":"info","ts":1693066736517692668,"logger":"server","msg":"A(t){return 45===t?(e.consume(t),P):O(t)}function I(t){return 47===t?(e.consume(t),o=\"\",L):O(t)}function L(t){return 62===t&&st.incl
{"level":"info","ts":1693066736518221296,"logger":"server","msg":"dren}\\`)`);let r=t.runSync(t.parse(n),n);if(\"root\"!==r.type)throw new TypeError(\"Expected a `root` node\");let a=L.default.createE
{"level":"info","ts":1693066736518726015,"logger":"server","msg":",6,7,8,9,10],Fd=jd.concat([11,12,13,14,15,16,17,18,19,20]),zd=[\"class\",\"data-prefix\",\"data-icon\",\"data-fa-transform\",\"data-fa
{"level":"info","ts":1693066736519790953,"logger":"server","msg":"egExp)return\"regexp\"}return t}function m(e){var t=p(e);switch(t){case\"array\":case\"object\":return\"an \"+t;case\"boolean\":case\"
{"level":"info","ts":1693066739569492959,"logger":"server","msg":"<!DOCTYPE html>\n<html lang=\"en\" class=\"auto\">\n<!--\nParseError: syntax error, unexpected end of file in file /var/www/vhosts/tmp
{"level":"info","ts":1693066739577456049,"logger":"server","msg":".\",\"42\":\"     *\",\"43\":\"     * @param  \\\\Illuminate\\\\Container\\\\Container  $container\",\"44\":\"     * @param  string  $
{"level":"info","ts":1693066739578128542,"logger":"server","msg":"/\\/ for any listeners that need to do work after this initial booting gets\",\"987\":\"        \\/\\/ finished. This is useful when o
{"level":"info","ts":1693066739578718109,"logger":"server","msg":"}}var U=a;t.unstable_IdlePriority=5,t.unstable_ImmediatePriority=1,t.unstable_LowPriority=4,t.unstable_NormalPriority=3,t.unstable_Pro
{"level":"info","ts":1693066739579579866,"logger":"server","msg":"To solve this, you can either unmount the component at the end of your test (and ensure that any asynchronous operations get canceled 
{"level":"info","ts":1693066739581177994,"logger":"server","msg":"with componentDidUpdate(). This component defines getSnapshotBeforeUpdate() only.\",We(t))),\"function\"==typeof r.getDerivedStateFrom
{"level":"info","ts":1693066739582446748,"logger":"server","msg":"ate;if(0!=(t.flags&ar))return t.lanes=n,0!=(8&t.mode)&&xd(t),t;var k=null!==x,A=!1;return null===e?void 0!==t.memoizedProps.fallback&&
{"level":"info","ts":1693066739587109985,"logger":"server","msg":",(e.documentElement.firstElementChild||e.documentElement.children[0]).appendChild(t),t=e.createElement(\"style\"),(e.documentElement.f
{"level":"info","ts":1693066739590088668,"logger":"server","msg":"ments[1]:{},n=t.transform,r=void 0===n?hn:n,a=t.symbol,o=void 0!==a&&a,i=t.mask,l=void 0===i?null:i,s=t.maskId,c=void 0===s?null:s,u=t
{"level":"info","ts":1693066739592750257,"logger":"server","msg":"tains `self` is not supported at the top-level of a language.  See documentation.\");return e.classNameAliases=hi(e.classNameAliases||
{"level":"info","ts":1693066739594854725,"logger":"server","msg":"kenizer().tokenize(e),this.getFormattedQueryFromTokens().trim()}},{key:\"getFormattedQueryFromTokens\",value:function(){var e=this,t=\
{"level":"info","ts":1693066739598049216,"logger":"server","msg":"ect.create(t&&t.prototype,{constructor:{value:e,writable:!0,configurable:!0}}),t&&l(e,t)}(m,e);var t,n,r,o=(n=m,r=function(){if(\"unde
{"level":"info","ts":1693066739600113675,"logger":"server","msg":"A(t){return 45===t?(e.consume(t),P):O(t)}function I(t){return 47===t?(e.consume(t),o=\"\",L):O(t)}function L(t){return 62===t&&st.incl
{"level":"info","ts":1693066739602450061,"logger":"server","msg":"dren}\\`)`);let r=t.runSync(t.parse(n),n);if(\"root\"!==r.type)throw new TypeError(\"Expected a `root` node\");let a=L.default.createE
{"level":"info","ts":1693066739615816064,"logger":"server","msg":",6,7,8,9,10],Fd=jd.concat([11,12,13,14,15,16,17,18,19,20]),zd=[\"class\",\"data-prefix\",\"data-icon\",\"data-fa-transform\",\"data-fa
{"level":"info","ts":1693066739617971521,"logger":"server","msg":"egExp)return\"regexp\"}return t}function m(e){var t=p(e);switch(t){case\"array\":case\"object\":return\"an \"+t;case\"boolean\":case\"

I believe it is the Ignition HTML page being output.

Even after the syntax error is corrected the rr worker will keep going until it has finished writing the error report which can take a little while.

tarampampam commented 1 year ago

@rustatian could you comment - is this expected behavior for the rr, or not?

rustatian commented 1 year ago

As far as I can tell from the logs, there is no suspicious activity or syntax errors inside the worker. If there is an error, RR won't start such a worker. I see that 2 workers were started and then stopped:

"sending stop request to the worker","pid":18}

The last error in the logs is probably related to the HTML of smt. Because this is the http log. So I'm guessing that the error is somewhere in the @freshleafmedia worker, leading to the hang and 100CPU spin (keep in mind that you're using debug mode, where workers are allocated per-request). This isssue is not related to the RR.

P.S.: RR does not officially support Laravel 😃

freshleafmedia commented 1 year ago

@rustatian Thanks for the input.

You mention the error is possibly somewhere in our worker but the worker we are using is the one provided in this repo

What is the expected behaviour when encountering a FatalError? I expected that the response from PHP's error handling to be returned to the browser, instead it is returned to the console?

rustatian commented 1 year ago

@freshleafmedia This is not a good practice to return an error to the browser, moreover, this is insecure. RR logs the error and returns the status code with the general information, like bad request, internal error, etc. By worker, I mean the code you wrote inside that worker 😃

freshleafmedia commented 1 year ago

@rustatian

By worker, I mean the code you wrote inside that worker 😃

Understood :smile:

In a production environment I completely agree, you would never want to show error messages. However while in a development environment it is common to show details of an exception.

By default Laravel comes with a package called ignition which renders details about an exception to the browser:

Laravel ignition error page

Given that this is 'just' a HTTP response I'm not sure why RR can not return this content to the browser. I suspect it is something to do with it being a FatalError and the registering of error handlers.

https://github.com/laravel/framework/blob/10.x/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php#L37-L54

RR does correctly return the error view for other types of error message.

rustatian commented 1 year ago

Feel free to use our awesome tool, instead of paid, basic Laravel piece of 😃 : https://buggregator.dev/

roadrunner-php / laravel-bridge