[🐛 BUG]: Grpc worker crashes instead of returning error response

[rauanmayemir]

No duplicates 🥲.

• I have searched for a similar issue in our bug tracker and didn't find any solutions.

What happened?

Throwing a Spiral\RoadRunner\GRPC\Exception\InvokeException in a grpc service used to return an error grpc response, but now it will crash the worker and the response will look like:

Unknown (2)
sync_worker_exec: SoftJobError: sync_worker_exec_payload: 7|:|Unauthorized access `index`|:| (type.googleapis.com/google.rpc.ErrorInfo�_ �PermissionDenied�#app.ServiceName�& �message��Unauthorized access `index`

The relevant code is here: https://github.com/spiral/roadrunner-grpc/blob/master/src/Server.php#L151

Version

2.7.6

Relevant log output

worker stopped, and will be restarted	{"reason": "worker error", "pid": 7625, "internal_event_name": "EventWorkerError", "error": "sync_worker_exec: SoftJobError:\n\tsync_worker_exec_payload: 7|:|Unauthorized access `index`|:|\n(type.googleapis.com/google.rpc.ErrorInfo\u0012_\n\u0010PermissionDenied\u0012#app.ServiceName\u001a&\n\u0007message\u0012\u001bUnauthorized access `index`"}
2022-02-09T13:19:56.387+0300	ERROR	grpc        	method call was finished with error	{"error": "sync_worker_exec: SoftJobError:\n\tsync_worker_exec_payload: 7|:|Unauthorized access `index`|:|\n(type.googleapis.com/google.rpc.ErrorInfo\u0012_\n\u0010PermissionDenied\u0012#app.ServiceName\u001a&\n\u0007message\u0012\u001bUnauthorized access `index`", "method": "/app.ServiceName/MethodName", "start": "2022-02-09T13:19:56.365+0300", "elapsed": "22.497083ms"}

[rauanmayemir]

Here's an example service that reproduces the crash: https://github.com/buhta/spiral-roadrunner-grpc/tree/invoke-error

2022-02-09T13:54:49.165+0300	WARN	server      	worker stopped, and will be restarted	{"reason": "worker error", "pid": 9162, "internal_event_name": "EventWorkerError", "error": "sync_worker_exec: SoftJobError:\n\tsync_worker_exec_payload: 13|:|Internal"}
2022-02-09T13:54:49.165+0300	ERROR	grpc        	method call was finished with error	{"error": "sync_worker_exec: SoftJobError:\n\tsync_worker_exec_payload: 13|:|Internal", "method": "/service.Echo/Ping", "start": "2022-02-09T13:54:49.163+0300", "elapsed": "2.031416ms"}
2022-02-09T13:54:49.166+0300	DEBUG	server      	worker stopped	{"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed; process_wait: signal: killed", "errorCauses": [{"error": "signal: killed"}, {"error": "process_wait: signal: killed"}]}
2022-02-09T13:54:49.201+0300	DEBUG	server      	worker is allocated	{"pid": 9166, "internal_event_name": "EventWorkerConstruct"}

[butschster]

<?php

use Spiral\Goridge;
use Spiral\RoadRunner;

$rr = new RoadRunner\Worker($relay);


$rr->error('7|:|Unauthorized access `index`|:|\n(type.googleapis.com/google.rpc.ErrorInfo\u0012_\n\u0010PermissionDenied\u0012#app.ServiceName\u001a&\n\u0007message\u0012\u001bUnauthorized access `index`');

[rauanmayemir]

More like:

$rr->error('7|:|Unauthorized access `index`|:|\n(type.googleapis.com/google.rpc.ErrorInfo\u0012_\n\u0010PermissionDenied\u0012#app.ServiceName\u001a&\n\u0007message\u0012\u001bUnauthorized access `index`');

[rustatian]

@rauanmayemir @butschster It's not possible to reproduce the issue by immediately returning an error. Because the worker can't be initialized if you do that.

[rustatian]

I'll try to create a unit test for that, let's see.

[rustatian]

Thanks, @rauanmayemir @butschster, the issue is now resolved.

[route33]

@rustatian I get the same error on 2.11.4 with

public function Ping(ContextInterface $ctx, Message $in): Message
    {
        throw \Spiral\RoadRunner\GRPC\Exception\InvokeException::create(
            'Internal',
            \Spiral\RoadRunner\GRPC\StatusCode::INTERNAL
        );
        $out = new Message();

        return $out->setMsg(date('Y-m-d H:i:s').': PONG');
    }

with output:

2022-11-08T19:11:04.896Z    DEBUG   server          worker is allocated {"pid": 65, "internal_event_name": "EventWorkerConstruct"}
2022-11-08T19:11:04.910Z    INFO    grpc            grpc server was started {"address": "tcp://0.0.0.0:9012"}
[INFO] RoadRunner server started; version: 2.11.4, buildtime: 2022-10-06T14:43:01+0000
2022-11-08T19:11:07.719Z    INFO    server          {"message":"Internal in /home/rr/vendor/spiral/roadrunner-grpc/src/Exception/GRPCException.php:74","context":{"exception":"Spiral\\RoadRunner\\GRPC\\Exception\\InvokeException: Internal in /home/rr/vendor/spiral/roadrunner-grpc/src/Exception/GRPCException.php:74\nStack trace:[...]: Worker->startEventLoop()\n#8 {main}"},"level":250,"level_name":"NOTICE","channel":"service","datetime":"2022-11-08T19:11:07.718691+00:00","extra":{}}


2022-11-08T19:11:07.761Z    WARN    server          worker stopped, and will be restarted   {"reason": "worker error", "pid": 65, "internal_event_name": "EventWorkerError", "error": "sync_worker_exec_worker_with_timeout: SoftJobError:\n\tsync_worker_exec_payload: 13|:|Internal"}
2022-11-08T19:11:07.762Z    ERROR   grpc            method call was finished with error {"error": "rpc error: code = Internal desc = Internal", "method": "/my.service.MyService/Ping", "start": "2022-11-08T19:11:07.571Z", "elapsed": "190.82562ms"}
2022-11-08T19:11:07.768Z    DEBUG   server          worker stopped  {"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed; process_wait: signal: killed", "errorCauses": [{"error": "signal: killed"}, {"error": "process_wait: signal: killed"}]}
2022-11-08T19:11:08.410Z    DEBUG   server          worker is allocated {"pid": 73, "internal_event_name": "EventWorkerConstruct"}

[rustatian]

Hey @route33 👋🏻

That is the correct message. Code number 13 is Internal error: https://developers.google.com/maps-booking/reference/grpc-api/status_codes.
And this message is correct:

2022-11-08T19:11:07.762Z    ERROR   grpc            method call was finished with error {"error": "rpc error: code = Internal desc = Internal", "method": "/my.service.MyService/Ping", "start": "2022-11-08T19:11:07.571Z", "elapsed": "190.82562ms"}

This message is just a full internal log. Logger is not parsing the error message: 13|:|Internal:

2022-11-08T19:11:07.761Z    WARN    server          worker stopped, and will be restarted   {"reason": "worker error", "pid": 65, "internal_event_name": "EventWorkerError", "error": "sync_worker_exec_worker_with_timeout: SoftJobError:\n\tsync_worker_exec_payload: 13|:|Internal"}

[route33]

But the issue is that the worker keeps restarting on every exception. Is that the normal flow?

[rustatian]

Yes. I have implemented a non-restarting flow but waiting for the PHP part: https://github.com/spiral/roadrunner-grpc/issues/10

I guess our PHP team will resolve it in a few days.