Half-closed without a request #8866
Comments
|
Strange. "Half-closed without a request" should mean that the client didn't send (all of) a request. But those logs show the request DATA frame and the Am I right in assuming that Do you have any interceptors that could be causing this problem? If an interceptor is wrapping the |
Correct both client and server is using
I added a logging interceptors just for debugging purposes: private ServerInterceptor logging() {
var seq = new AtomicInteger(0);
return new ServerInterceptor() {
@Override
public <ReqT, RespT> Listener<ReqT> interceptCall(
ServerCall<ReqT, RespT> call, Metadata headers, ServerCallHandler<ReqT, RespT> next) {
var remoteSeq = headers.get(TRACE_SEQ_KEY);
var seqNr = seq.incrementAndGet();
return new ForwardingServerCallListener.SimpleForwardingServerCallListener<ReqT>(
next.startCall(
new ForwardingServerCall.SimpleForwardingServerCall<ReqT, RespT>(call) {
@Override
public void sendMessage(final RespT message) {
super.sendMessage(message);
logger.info("{} - sendMessage", seq);
}
@Override
public void close(final Status status, final Metadata trailers) {
super.close(status, trailers);
logger.info(
"{} trace-seq: {} - closed with status code: {}, desc: {}",
seqNr,
remoteSeq,
status.getCode(),
status.getDescription());
}
@Override
public void sendHeaders(final Metadata headers) {
super.sendHeaders(headers);
logger.info("{} - sendHeader", seqNr);
}
},
headers)) {
@Override
public void onHalfClose() {
super.onHalfClose();
logger.info("{} - onHalfClose", seqNr);
}
@Override
public void onMessage(final ReqT message) {
super.onMessage(message);
logger.info("{} - onMessage", seqNr);
}
@Override
public void onCancel() {
super.onCancel();
logger.info("{} - onCancel", seqNr);
}
@Override
public void onComplete() {
super.onComplete();
logger.info("{} - onComplete", seqNr);
}
};
}
};
}could this cause the observed behaviour? |
|
I expect this issue will be present in newer versions too, but confirming is still worthwhile. That interceptor doesn't look to be a problem. I will note that the logs may be in a misleading order because within Is that the only interceptor in use? |
Here is a minimal reproducible(at least on my machine) example: https://github.com/tommyulfsparre/grpc-half-close |
I can reproduce the "Half-closed without a request" error with the given reproducible. |
Seems when RST_STREAM is received,
can race with |
|
Tangential question to whether this is a race condition or not: Is As far as I understand, it is possible for this condition to occur under normal circumstances if the client closes a stream prematurely. Is this a server error or a client error? The current implementation is categorizing it as a server error. Do we want to change this? |
@irock, INTERNAL is not a "server error." It's a "things are fundamentally broken." The INTERNAL usage on that line is appropriate, because the client believes the RPC is client-streaming instead of unary, so the client and server appear not to agree on the schema. It is a bug though that line is executed. But the "wrong status" part of it doesn't matter too much because the client already cancelled and so won't see it. |
|
There's no compression in the reproduction. So I think this might be it:
Could the fix be as easy as avoiding the entire @tommyulfsparre, the reproduction looks to have been very helpful here. |
|
Maybe we need something more; I'd have to look at |
|
Hi @ejona86! Do you have any news on a potential fix for this issue? |
|
At the server side, transport first notifies stream created, then server call is started, and |
|
never mind, that situation was in successful case. When deadline is small enough( in my local test, request delay =100ms, deadline=400ms), we do see 100% of time that, due to deadline and slow |
|
Cancellation drains the MessageDeframer, but our code handling the deframer closure is noticing we've received halfClose on-the-wire and reporting that accidentally. The problem here isn't the ordering between onMessage() and halfClose(). The problem is that halfClose() shouldn't be reported at all. The cancellation code threw away the request message, so it won't ever be delivered. The call is already cancelled when this INTERNAL error occurs, so the server doesn't send the status to the client. The client processes the deadline locally to see the DEADLINE_EXCEEDED. |
|
oh i looked at the original issue again, so even in the undesired situation the client never receives INTERNAL error, only server sees that. The client always see DEADLINE_EXCEEDED. The it looks the reproduction is ok.
The received halfClose from the client was caused by client cancellation, right? Then it makes sense, the deadline was long enough for the server to receive the request but not processed it, and be small enough to cancel before it all completes to cause the INTERNAL error. |
No, I expect that was part of the original request. Something like: Commonly that delay is large enough that the server would have But the rest of what you said sounds fine. |
gRPC version
1.40.0Environment
A client and server communicating over localhost.
I have a simple client and server that does nothing beside responding to an incoming RPC:
The client sends 100 RPCs with a
100msdeadline in parallel over a single channel that is in aREADYstate and shutdowns after all RPCs has been sent.(
trace-seq: 97is metadata that gets sent along with each RPC)After the JVM has started we get a bunch of RPC with status:
INTERNAL, desc: Half-closed without a requestserver side, client report the expectedDEADLINE_EXCEEDED. So before any JIT or lazy class loading.Re-running the client (keeping the server running) doesn't not produce those error and we can see that only onCancel gets called when the client cancel an RPC. Instead of close(Status.INTERNAL) -> onHalfClose -> onCancel that we saw before.
I guess that gRPC can't do much about the slow JVM startup but is the
INTERNAL, desc: Half-closed without a requestexpected in those cases?The text was updated successfully, but these errors were encountered: