New Process facade / ProcessResult hides exceptions

[ManuelLeiner]

Laravel Version

10.12.0

PHP Version

8.2.6

Database Driver & Version

No response

Description

tl;dr;
When working with the new Process facade, errors that happen in underlying scripts, e.g. executing a python script from a Laravel queue worker, will not appear in the logs. We are not able to quickly identify the actual problem.

Description
We are working with docker containers. One kind of container starts a Laravel queue worker that listens on a Redis queue. One of our jobs uses the Laravel Illuminate\Support\Facades\Process facade to trigger a python script. In case the process/python script throws an error, the job now uses Illuminate\Process\ProcessResult->throw() to finish execution and log the error (Illuminate\Process\Exceptions\ProcessFailedException). The actual python error message is nowhere to be found. For the log examples below I extracted the necessary logic to an invokable controller, instead of actually working with jobs. The behaviour is the same.

Here is the log output today:

compose-fpm-1          | [2023-05-30 10:00:37] local.ERROR: The process "'/usr/bin/python3' '-u' '/var/www/project/scripty.py'" failed. {"userId":1,"exception":"[object] (Illuminate\\Process\\Exceptions\\ProcessFailedException(code: 1): The process \"'/usr/bin/python3' '-u' '/var/www/project/scripty.py'\" failed. at /var/www/html/vendor/laravel/framework/src/Illuminate/Process/ProcessResult.php:123)
compose-fpm-1          | [stacktrace]
compose-fpm-1          | #0 /var/www/html/app/Http/Controllers/ProcessController.php(13): Illuminate\\Process\\ProcessResult->throw()
compose-websockets-1   | Connection id 517174791.95337871 sending message {"event":"pusher:pong"}
compose-fpm-1          | #1 /var/www/html/vendor/laravel/framework/src/Illuminate/Routing/Controller.php(54): App\\Http\\Controllers\\ProcessController->__invoke()
compose-websockets-1   | naix-custom-websockets: connection id 517174791.95337871 received message: {"event":"pusher:ping","data":{}}.
compose-fpm-1          | #2 /var/www/html/vendor/laravel/framework/src/Illuminate/Routing/ControllerDispatcher.php(43): Illuminate\\Routing\\Controller->callAction()
compose-fpm-1          | #3 /var/www/html/vendor/laravel/framework/src/Illuminate/Routing/Route.php(259): Illuminate\\Routing\\ControllerDispatcher->dispatch()

Before we refactored to the Process facade, we used to work with the Symfony classes directly, i.e. the job used to run a Symfony\Component\Process\Process and in case the process ended unsuccessful, it would throw a Symfony\Component\Process\Exception\ProcessFailedException passing in the Symfony process. In the past we would see the actual python error, e.g. the line that crashed, we would actually know what happened.

compose-fpm-1          | [2023-05-30 10:09:24] local.ERROR: The command "'/usr/bin/python3' '-u' '/var/www/project/scripty.py'" failed.
compose-fpm-1          | Exit Code: 1(General error)
compose-fpm-1          | Working directory: /var/www/html/public
compose-fpm-1          | Output:
compose-fpm-1          | ================
compose-fpm-1          | Error Output:
compose-fpm-1          | ================
compose-fpm-1          | Traceback (most recent call last):
compose-fpm-1          |   File "/var/www/project/scripty.py", line 3, in <module>
compose-fpm-1          |     raise ValueError('ERROR')
compose-fpm-1          | ValueError: ERROR
compose-fpm-1          |  {"userId":1,"exception":"[object] (Symfony\\Component\\Process\\Exception\\ProcessFailedException(code: 0): The command \"'/usr/bin/python3' '-u' '/var/www/project/scripty.py'\" failed.
compose-fpm-1          | Exit Code: 1(General error)
compose-fpm-1          | Working directory: /var/www/html/public
compose-fpm-1          | Output:
compose-fpm-1          | ================
compose-fpm-1          | Error Output:
compose-fpm-1          | ================
compose-fpm-1          | Traceback (most recent call last):
compose-fpm-1          |   File \"/var/www/project/scripty.py\", line 3, in <module>
compose-fpm-1          |     raise ValueError('ERROR')
compose-fpm-1          | ValueError: ERROR
compose-fpm-1          |  at /var/www/html/app/Http/Controllers/ProcessController.php:17)
compose-fpm-1          | [stacktrace]
compose-fpm-1          | #0 /var/www/html/vendor/laravel/framework/src/Illuminate/Routing/Controller.php(54): App\\Http\\Controllers\\ProcessController->__invoke()
compose-fpm-1          | #1 /var/www/html/vendor/laravel/framework/src/Illuminate/Routing/ControllerDispatcher.php(43): Illuminate\\Routing\\Controller->callAction()
compose-fpm-1          | #2 /var/www/html/vendor/laravel/framework/src/Illuminate/Routing/Route.php(259): Illuminate\\Routing\\ControllerDispatcher->dispatch()

What do you think? Is the new Illuminate\Process\Exceptions\ProcessFailedException hiding information? Or is it just a bad pattern we use, calling a python script and expecting the error to be logged?

I am happy to provide a fork showcasing the problem or even provide a fix if we come up with a good solution.

Steps To Reproduce

Create a python script that raises an error

if __name__ == '__main__':
    raise ValueError('ERROR')

In an invokable controller execute the script using the Process facade:

<?php

namespace App\Http\Controllers;

use Illuminate\Support\Facades\Process;

class ProcessController extends Controller
{
    public function __invoke()
    {
        Process::timeout(600)
            ->run(['/usr/bin/python3', '-u', '/var/www/project/scripty.py'])
            ->throw();
    }
}

Then execute the script again using the Symfony class directly:

<?php

namespace App\Http\Controllers;

use Symfony\Component\Process\Exception\ProcessFailedException;
use Symfony\Component\Process\Process;

class ProcessController extends Controller
{
    public function __invoke()
    {
        $process = new Process(['/usr/bin/python3', '-u', '/var/www/project/scripty.py']);
        $process->setTimeout(600);
        $process->run();

        if (!$process->isSuccessful()) {
            throw new ProcessFailedException($process);
        }
    }
}

[nunomaduro]

Fixed here: #47285. Let's continue the discussion on the pull request. Also, can you try the pull request locally, to see if is working as expected for you?

[ManuelLeiner]

Works like a charm!