[💡 FEATURE REQUEST]: Improve clarity of worker errors when starting a server

[Kaspiman]

Plugin

Server

I have an idea!

When my newbie was getting used to the RR, some problems arose that were difficult to diagnose.

Let's say i have typical RR config for production usage for Logs plugin:

logs:
    level: warn
    mode: production

and also a broken worker with a syntax error (for example).

Then the output will only include the EOF error without any details.

handle_serve_command: Function call error:
2024-10-06T18:27:36.449763889Z 	serve error from the plugin *http.Plugin stopping execution, error: static_pool_allocate_workers: WorkerAllocate: EOF

A newbie has questions: why the server won't start and what is EOF?

The problem is that errors from the worker only come from the debug level. In production mode, it is difficult to immediately understand what happened. EOF is too unclear a reason. Also, an error in the EOF text was sent to the browser without any details.

What if RR write a more meaningful error message right away? It seems that the worker startup error should be more understandable and the error level should be.

Another small question. Do RR really use STDERR to exchange data frames?
https://docs.roadrunner.dev/docs/php-worker/worker#communication-methods

[rustatian]

Hey @Kaspiman 👋
Unfortunately, it is not possible to determine the exact error, I understand that EOF is too general error, but usually, it points to some error with the PHP file, e.g.: no such file for example or some garbage data in the process pipes which prevents RR to allocate a PHP process. The case is, RR does not know about PHP at all. From the RR perspective, it is just a child process and if the runtime can't provide additional information, RR unfortunately can't obtain such an info by itself somewhere.

Also, an error in the EOF text was sent to the browser without any details.

This is kind of strange, because EOF usually indicates a startup problem. When RR is running, this is highly unlikely to see this error. If you don't move the worker and send a ./rr reset command.

Another small question. Do RR really use STDERR to exchange data frames?

RR uses stdin/stdout to communicate with the PHP process. STDERR used to obtain logs/diagnostic information from the PHP process.

[rustatian]

It would be nice if you attach to the ticket some examples of PHP workers + actual error messages + desired error messages + .rr.yaml configurations.

[Kaspiman]

Use Case №1:

Any broken php worker, for example with syntax error.

http:
    pool:
        num_workers: 1

logs:
    level: warn

Actual error:

[INFO] RoadRunner server started; version: 2024.2.1, buildtime: 2024-09-12T16:25:02+0000
[INFO] sdnotify: not notified
handle_serve_command: Function call error:
serve error from the plugin *http.Plugin stopping execution, error: static_pool_allocate_workers: WorkerAllocate: EOF

Desired error message with error level: Failed to allocate worker, check application logs with stacktrace from PHP.

Now this trace is visible only from the info level.

Logs with info level and broken php worker:

[INFO] RoadRunner server started; version: 2024.2.1, buildtime: 2024-09-12T16:25:02+0000
[INFO] sdnotify: not notified
INFO    server          Warning: Undefined variable $worker in /var/www/html/worker.php on line 20
 Fatal error: Uncaught TypeError: Spiral\RoadRunner\Http\PSR7Worker::__construct(): Argument #1 ($worker) must be of type Spiral\RoadRunner\WorkerInterface, null given, called in /var/www/html/worker.php on line 20 and defined in /var/www/html/vendor/spiral/roadrunner-http/src/PSR7Worker.php:42
 Stack trace:
 #0 /var/www/html/worker.php(20): Spiral\RoadRunner\Http\PSR7Worker->__construct(NULL, Object(Nyholm\Psr7\Factory\Psr17Factory), Object(Nyholm\Psr7\Factory\Psr17Factory), Object(Nyholm\Psr7\Factory\Psr17Factory))
 #1 {main}
   thrown in /var/www/html/vendor/spiral/roadrunner-http/src/PSR7Worker.php on line 42
 
 handle_serve_command: Function call error:
     serve error from the plugin *http.Plugin stopping execution, error: static_pool_allocate_workers: WorkerAllocate: EOF

Basically, we need to log the worker output at the error level unless otherwise stated.

---

Use Case №2:

debug = true and any broken php worker, for example with syntax error.

logs:
    level: warn

http:
    pool:
        debug: true

Logs:

[INFO] RoadRunner server started; version: 2024.2.1, buildtime: 2024-09-12T16:25:02+0000
[INFO] sdnotify: not notified
ERROR	http        	execute	{"start": "2024-10-07T07:32:12+0000", "elapsed": 9, "error": "EOF"}
ERROR	http        	execute	{"start": "2024-10-07T07:32:12+0000", "elapsed": 9, "error": "EOF"}

The server has started, and when processing one request, two EOF errors are written to the logs.

Error 500 and EOF message in browser.

Desired error message in logs with error level:Failed to allocate worker, check application logs with stacktrace from PHP.

Desired error message in browser: Failed to allocate worker, check application logs with/without (idk) stacktrace from PHP.

[Kaspiman]

Is it possible to rework this kind of error?

Typical error:

 handle_serve_command: Function call error:
     serve error from the plugin *http.Plugin stopping execution, error: static_pool_allocate_workers: WorkerAllocate: EOF

It contains a lot of information that is more useful to the developer than to the user.

Possible rework:

Error from the <PluginName> plugin, message: Failed to allocate worker, check application logs, code: static_pool_allocate_workers, stacktrace: ...

[rustatian]

Ok, so, if I understand correctly, the problem is in log level, because under the info log level you may clearly see what is the actual error.
The error about Function call comes from the Endure, but definitely it is possible to add some link to docs or guideline of what to do next to see the error. Will add this to 2024.3 milestone.

[rustatian]

The actual problem here, is that we don't have a log level from PHP. Thus, all worker-related messages (RR can't distinguish between a just message and an error message, from the RR POV all that is text) are logged under the info log level. And when you use warn, obviously, all info messages are not displayed (and this is the problem).

A real solution I want to see here is a some configuration exchange from the PHP worker side to RR. Like in the Temporal plugin. RR on the init stage pings all workers, so it would be nice to exchange a configuration info between RR <-> PHP. Logging configuration is the first and obvious step.