Closed MaelitoP closed 4 weeks ago
@MaelitoP The following log shows that gRPC client closed the connection which caused the response was not able to send response and threw error.
Could you please check your gRPC client side?
@lxning I'm checking, but I see nothing at the moment. When I look to the client logs, we can see that the server respond with an error:
Apr 14 03:44:39 augmenter_app[924]:
time="2024-04-14T03:44:39Z"
level=error
msg="An error occurred during augmentation of an article using Sentiment v4"
articleId="xxxxx"
error="sentiment4c : prediction failed: rpc error: code = Internal desc = Model \"distilroberta\" has no worker to serve inference request. Please use scale workers API to add workers. If this is a sequence inference, please check if it is closed, or expired; or exceeds maxSequenceJobQueueSize\nInternalServerException.()"
As far as I know, if the connection is lost, we get an error like code = Unavailable desc = transport is closing
instead.
But why does the server crash when a client closes the connection? This behaviour looks weird to me, but that's probably common, I don't know.
Hello, To make sure I wasn't getting a timeout from the client, I forced a timeout to check the error message. I got this one:
error="sentiment4c : prediction failed: rpc error:
code = DeadlineExceeded
desc = context deadline exceeded"
When I did this timeout test, the TorchServe
instance crashed with error:
Apr 16 07:05:19 sentiment4_app[710]: 2024-04-16T07:05:19,850 [WARN ] grpc-default-executor-545 org.pytorch.serve.grpcimpl.InferenceImpl - grpc client call already cancelled
Apr 16 07:05:19 sentiment4_app[710]: 2024-04-16T07:05:19,850 [INFO ] grpc-default-executor-545 ACCESS_LOG - /0.0.0.0:62774 "gRPC org.pytorch.serve.grpc.inference.InferenceAPIsService/Predictions HTTP/2.0" 1 313
Apr 16 07:05:19 sentiment4_app[710]: 2024-04-16T07:05:19,850 [DEBUG] grpc-default-worker-ELG-3-8 io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler - [id: 0x62653f08, L:/0.0.0.0:7070 - R:/0.0.0.0:62774] OUTBOUND RST_STREAM: streamId=84103 errorCode=8
Apr 16 07:05:19 sentiment4_app[710]: 2024-04-16T07:05:19,903 [INFO ] W-9010-distilroberta_1.0-stdout org.pytorch.serve.wlm.WorkerLifeCycle - result=[METRICS]PredictionTime.Milliseconds:318.27|#ModelName:distilroberta,Level:Model|#type:GAUGE|#hostname:xxxxxx,xxxxxxxx,94a54730-e1f3-4fe1-ab30-63c26e2fb6c9, pattern=[METRICS]
Apr 16 07:05:19 sentiment4_app[710]: 2024-04-16T07:05:19,903 [WARN ] W-9010-distilroberta_1.0 org.pytorch.serve.job.GRPCJob - grpc client call already cancelled, not able to send this response for requestId: 94a54730-e1f3-4fe1-ab30-63c26e2fb6c9
Apr 16 07:05:19 sentiment4_app[710]: 2024-04-16T07:05:19,903 [ERROR] W-9010-distilroberta_1.0 org.pytorch.serve.wlm.WorkerThread - IllegalStateException error
Apr 16 07:05:19 sentiment4_app[710]: java.lang.IllegalStateException: Stream was terminated by error, no further calls are allowed
Apr 16 07:05:19 sentiment4_app[710]: #011at com.google.common.base.Preconditions.checkState(Preconditions.java:502) ~[model-server.jar:?]
Apr 16 07:05:19 sentiment4_app[710]: #011at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onNext(ServerCalls.java:374) ~[model-server.jar:?]
Apr 16 07:05:19 sentiment4_app[710]: #011at org.pytorch.serve.job.GRPCJob.response(GRPCJob.java:130) ~[model-server.jar:?]
Apr 16 07:05:19 sentiment4_app[710]: #011at org.pytorch.serve.wlm.BatchAggregator.sendResponse(BatchAggregator.java:103) ~[model-server.jar:?]
Apr 16 07:05:19 sentiment4_app[710]: #011at org.pytorch.serve.wlm.WorkerThread.run(WorkerThread.java:238) [model-server.jar:?]
Apr 16 07:05:19 sentiment4_app[710]: #011at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
Apr 16 07:05:19 sentiment4_app[710]: #011at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
Apr 16 07:05:19 sentiment4_app[710]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
Apr 16 07:05:19 sentiment4_app[710]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
Apr 16 07:05:19 sentiment4_app[710]: #011at java.lang.Thread.run(Thread.java:840) [?:?]
Apr 16 07:05:19 sentiment4_app[710]: 2024-04-16T07:05:19,903 [WARN ] W-9010-distilroberta_1.0 org.pytorch.serve.job.GRPCJob - grpc client call already cancelled, not able to send this response for requestId: 94a54730-e1f3-4fe1-ab30-63c26e2fb6c9
Apr 16 07:05:19 sentiment4_app[710]: 2024-04-16T07:05:19,903 [INFO ] W-9010-distilroberta_1.0 ACCESS_LOG - /0.0.0.0:62774 "gRPC org.pytorch.serve.grpc.inference.InferenceAPIsService/Predictions HTTP/2.0" 13 366
Apr 16 07:05:19 sentiment4_app[710]: 2024-04-16T07:05:19,904 [INFO ] W-9010-distilroberta_1.0-stdout MODEL_LOG - Frontend disconnected.
Apr 16 07:05:19 sentiment4_app[710]: 2024-04-16T07:05:19,904 [INFO ] epollEventLoopGroup-5-4 org.pytorch.serve.wlm.WorkerThread - 9010 Worker disconnected. WORKER_MODEL_LOADED
What can I do on the TorchServe
side to avoid a crashes when a client disconnect ?
Are you sure that it's not a bug on TorchServe
side ? If we take time to read logs we can see that the error happen here. (GRPCJob.java l.130
).
We try to do responseObserver.onNext(reply);
but responseObserver
is already cancelled.
You do a PR some time ago @lxning to fix this problem (https://github.com/pytorch/serve/pull/2420).
But when we check the master
we can see that the logic was moved in a function nammed cancelHandler(ServerCallStreamObserver<PredictionResponse> responseObserver)
. And we're not returning anymore.
This regression was introduce in #2513. I'm right or I just don't understand the logic ?
I'm having the same problem. Although the client closes the grpc channel if it times out, Torchserve shouldn't crash, or crash but boot a worker again, not leave it unusable....
@lxning The same problem is happening with me also
Same problem is happening to me as well similar to #3168 #3091
We have the same issue on our side.
I was wondering why our CI process was unstable and unable to handle our tests with only one worker and one instance. As soon as we have a timeout on a request, our worker is no longer available. In prod we saw only the problem on unexpected spikes of requests as we have multiple instances with multiple workers and thanks to daily deployment, we got our stale workers back.
I made an attempt to fix the issue here: https://github.com/pytorch/serve/pull/3267
Being new to this repository, it's a draft for now.
Downgrading torchserve=0.9.0 helped solve this issue.
Downgrading torchserve=0.9.0 helped solve this issue.
Indeed, this version is before the refactoring that reintroduced the bug. Unfortunately, at least in my case, we also need the gRPC configurations for client-side load-balancing (connection max age and grace time) that were introduced in version 0.11.0
.
Hello,
I have a problem with
TorchServe
in production. When I start the server there is no problem and everything works perfectly, I can use the model and make requests on it. But after around 3 days the server crashes and I don't understand why.If you look at the monitoring metrics, you can see that
ts_inference_requests_total
is ~1 req/s. And thePredictionTime
is between 40 and 600ms.My attempt to trigger the error in local was unsuccessful 😞
Server error logs (
TorchServe
)Client error logs (Go client)
Dockerfile
Configuration (
config.properties
)Thank you so much for you time